1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19 package org.eclipse.jetty.monitor;
20
21 import java.lang.management.ManagementFactory;
22 import java.lang.management.ThreadMXBean;
23 import java.util.ArrayList;
24 import java.util.Collections;
25 import java.util.Comparator;
26 import java.util.HashMap;
27 import java.util.List;
28 import java.util.Map;
29
30 import org.eclipse.jetty.monitor.thread.ThreadMonitorException;
31 import org.eclipse.jetty.monitor.thread.ThreadMonitorInfo;
32 import org.eclipse.jetty.util.annotation.ManagedObject;
33 import org.eclipse.jetty.util.component.AbstractLifeCycle;
34 import org.eclipse.jetty.util.component.Dumpable;
35 import org.eclipse.jetty.util.log.Log;
36 import org.eclipse.jetty.util.log.Logger;
37
38 @ManagedObject("Busy Thread Monitor")
39 public class ThreadMonitor extends AbstractLifeCycle implements Runnable
40 {
41 private static final Logger LOG = Log.getLogger(ThreadMonitor.class);
42
43 private int _scanInterval;
44 private int _logInterval;
45 private int _busyThreshold;
46 private int _logThreshold;
47 private int _stackDepth;
48 private int _trailLength;
49
50 private ThreadMXBean _threadBean;
51
52 private Thread _runner;
53 private Logger _logger;
54 private volatile boolean _done = true;
55 private Dumpable _dumpable;
56
57 private Map<Long,ThreadMonitorInfo> _monitorInfo;
58
59
60
61
62
63
64
65 public ThreadMonitor() throws Exception
66 {
67 this(5000);
68 }
69
70
71
72
73
74
75
76
77 public ThreadMonitor(int intervalMs) throws Exception
78 {
79 this(intervalMs, 95);
80 }
81
82
83
84
85
86
87
88
89
90 public ThreadMonitor(int intervalMs, int threshold) throws Exception
91 {
92 this(intervalMs, threshold, 3);
93 }
94
95
96
97
98
99
100
101
102
103
104 public ThreadMonitor(int intervalMs, int threshold, int depth) throws Exception
105 {
106 this(intervalMs, threshold, depth, 3);
107 }
108
109
110
111
112
113
114
115
116
117
118
119 public ThreadMonitor(int intervalMs, int threshold, int depth, int trail) throws Exception
120 {
121 _scanInterval = intervalMs;
122 _busyThreshold = threshold;
123 _stackDepth = depth;
124 _trailLength = trail;
125
126 _logger = Log.getLogger(ThreadMonitor.class.getName());
127 _monitorInfo = new HashMap<Long, ThreadMonitorInfo>();
128
129 init();
130 }
131
132
133
134
135
136
137
138 public int getScanInterval()
139 {
140 return _scanInterval;
141 }
142
143
144
145
146
147
148
149 public void setScanInterval(int ms)
150 {
151 _scanInterval = ms;
152 }
153
154
155
156
157
158
159
160 public int getLogInterval()
161 {
162 return _logInterval;
163 }
164
165
166
167
168
169
170
171 public void setLogInterval(int ms)
172 {
173 _logInterval = ms;
174 }
175
176
177
178
179
180
181
182 public int getBusyThreshold()
183 {
184 return _busyThreshold;
185 }
186
187
188
189
190
191
192
193 public void setBusyThreshold(int percent)
194 {
195 _busyThreshold = percent;
196 }
197
198
199
200
201
202
203
204 public int getLogThreshold()
205 {
206 return _logThreshold;
207 }
208
209
210
211
212
213
214
215 public void setLogThreshold(int percent)
216 {
217 _logThreshold = percent;
218 }
219
220
221
222
223
224
225
226 public int getStackDepth()
227 {
228 return _stackDepth;
229 }
230
231
232
233
234
235
236
237 public void setStackDepth(int stackDepth)
238 {
239 _stackDepth = stackDepth;
240 }
241
242
243
244
245
246
247
248 public void setTrailLength(int trailLength)
249 {
250 _trailLength = trailLength;
251 }
252
253
254
255
256
257
258
259 public int getTrailLength()
260 {
261 return _trailLength;
262 }
263
264
265
266
267
268
269
270
271 public void logCpuUsage(int frequencyMs, int thresholdPercent)
272 {
273 setLogInterval(frequencyMs);
274 setLogThreshold(thresholdPercent);
275 }
276
277
278
279
280
281 public Dumpable getDumpable()
282 {
283 return _dumpable;
284 }
285
286
287
288
289
290 public void setDumpable(Dumpable dumpable)
291 {
292 _dumpable = dumpable;
293 }
294
295
296
297
298
299 public void doStart()
300 {
301 _done = false;
302
303 _runner = new Thread(this);
304 _runner.setDaemon(true);
305 _runner.start();
306
307 LOG.info("Thread Monitor started successfully");
308 }
309
310
311
312
313
314 public void doStop()
315 {
316 if (_runner != null)
317 {
318 _done = true;
319 try
320 {
321 _runner.join();
322 }
323 catch (InterruptedException ex) {}
324 }
325 }
326
327
328
329
330
331
332
333 protected long[] getAllThreadIds()
334 {
335 return _threadBean.getAllThreadIds();
336 }
337
338
339
340
341
342
343
344
345 protected long getThreadCpuTime(long id)
346 {
347 return _threadBean.getThreadCpuTime(id);
348 }
349
350
351
352
353
354 protected void init()
355 {
356 _threadBean = ManagementFactory.getThreadMXBean();
357 if (_threadBean.isThreadCpuTimeSupported())
358 {
359 _threadBean.setThreadCpuTimeEnabled(true);
360 }
361 }
362
363
364
365
366
367 public void run()
368 {
369
370 boolean repeat = false;
371 boolean scanNow, logNow;
372
373
374 long nextScanTime = System.currentTimeMillis();
375 long nextLogTime = nextScanTime + _logInterval;
376
377 while (!_done)
378 {
379 long currTime = System.currentTimeMillis();
380 scanNow = (currTime > nextScanTime);
381 logNow = (_logInterval > 0 && currTime > nextLogTime);
382 if (repeat || scanNow || logNow)
383 {
384 repeat = collectThreadInfo();
385 logThreadInfo(logNow);
386
387 if (scanNow)
388 {
389 nextScanTime = System.currentTimeMillis() + _scanInterval;
390 }
391 if (logNow)
392 {
393 nextLogTime = System.currentTimeMillis() + _logInterval;
394 }
395 }
396
397
398 if (!repeat)
399 {
400 try
401 {
402 Thread.sleep(100);
403 }
404 catch (InterruptedException ex)
405 {
406 LOG.ignore(ex);
407 }
408 }
409 }
410
411 }
412
413
414
415
416
417 private boolean collectThreadInfo()
418 {
419 boolean repeat = false;
420 try
421 {
422
423
424
425 Map<Thread,StackTraceElement[]> all = Thread.getAllStackTraces();
426
427 for (Map.Entry<Thread,StackTraceElement[]> entry : all.entrySet())
428 {
429 Thread thread = entry.getKey();
430 long threadId = thread.getId();
431
432
433 if (threadId == _runner.getId())
434 {
435 continue;
436 }
437
438 ThreadMonitorInfo currMonitorInfo = _monitorInfo.get(Long.valueOf(threadId));
439 if (currMonitorInfo == null)
440 {
441
442 currMonitorInfo = new ThreadMonitorInfo(thread);
443 currMonitorInfo.setStackTrace(entry.getValue());
444 currMonitorInfo.setCpuTime(getThreadCpuTime(threadId));
445 currMonitorInfo.setSampleTime(System.nanoTime());
446 _monitorInfo.put(Long.valueOf(threadId), currMonitorInfo);
447 }
448 else
449 {
450
451 currMonitorInfo.setStackTrace(entry.getValue());
452 currMonitorInfo.setCpuTime(getThreadCpuTime(threadId));
453 currMonitorInfo.setSampleTime(System.nanoTime());
454
455
456 int count = currMonitorInfo.getTraceCount();
457 if (count >= 0 && currMonitorInfo.isSpinning())
458 {
459
460 if (count < _trailLength)
461 {
462
463 currMonitorInfo.setTraceCount(count+1);
464 repeat = true;
465 continue;
466 }
467
468
469 currMonitorInfo.setSpinning(false);
470 currMonitorInfo.setTraceCount(-1);
471 }
472 if (currMonitorInfo.getCpuUtilization() > _busyThreshold)
473 {
474
475 StackTraceElement[] lastStackTrace = currMonitorInfo.getStackTrace();
476
477 if (lastStackTrace != null
478 && matchStackTraces(lastStackTrace, entry.getValue()))
479 {
480
481 currMonitorInfo.setSpinning(true);
482 if (count < 0)
483 {
484
485
486
487 currMonitorInfo.setTraceCount(0);
488 repeat = (_trailLength > 0);
489 }
490 }
491 }
492 }
493 }
494 }
495 catch (Exception ex)
496 {
497 LOG.debug(ex);
498 }
499 return repeat;
500 }
501
502
503 protected void logThreadInfo(boolean logAll)
504 {
505 if (_monitorInfo.size() > 0)
506 {
507
508 long[] running = getAllThreadIds();
509 List<ThreadMonitorInfo> all = new ArrayList<ThreadMonitorInfo>();
510 for (int idx=0; idx<running.length; idx++)
511 {
512 ThreadMonitorInfo info = _monitorInfo.get(running[idx]);
513 if (info != null)
514 {
515 all.add(info);
516 }
517 }
518
519
520 Collections.sort(all, new Comparator<ThreadMonitorInfo>()
521 {
522
523 public int compare(ThreadMonitorInfo info1, ThreadMonitorInfo info2)
524 {
525 return (int)Math.signum(info2.getCpuUtilization()-info1.getCpuUtilization());
526 }
527 });
528
529 String format = "Thread '%2$s'[%3$s,id:%1$d,cpu:%4$.2f%%]%5$s";
530
531
532
533 boolean spinning=false;
534 for (ThreadMonitorInfo info : all)
535 {
536 if (logAll && info.getCpuUtilization() > _logThreshold
537 || info.isSpinning() && info.getTraceCount() == 0)
538 {
539 String message = String.format(format,
540 info.getThreadId(), info.getThreadName(),
541 info.getThreadState(), info.getCpuUtilization(),
542 info.isSpinning() ? " SPINNING" : "");
543 _logger.info(message);
544 spinning=true;
545 }
546 }
547
548
549 if (spinning && _dumpable!=null)
550 {
551 System.err.println(_dumpable.dump());
552 }
553
554
555 for (ThreadMonitorInfo info : all)
556 {
557 if (info.isSpinning() && info.getTraceCount() >= 0)
558 {
559 String message = String.format(format,
560 info.getThreadId(), info.getThreadName(),
561 info.getThreadState(), info.getCpuUtilization(),
562 " STACK TRACE");
563 _logger.warn(new ThreadMonitorException(message, info.getStackTrace()));
564 }
565 }
566 }
567 }
568
569
570
571
572
573
574
575
576
577 private boolean matchStackTraces(StackTraceElement[] lastStackTrace, StackTraceElement[] stackTrace)
578 {
579 boolean match = true;
580 int count = Math.min(_stackDepth, Math.min(lastStackTrace.length, stackTrace.length));
581
582 for (int idx=0; idx < count; idx++)
583 {
584 if (!stackTrace[idx].equals(lastStackTrace[idx]))
585 {
586 match = false;
587 break;
588 }
589 }
590 return match;
591 }
592 }