View Javadoc

1   //
2   //  ========================================================================
3   //  Copyright (c) 1995-2015 Mort Bay Consulting Pty. Ltd.
4   //  ------------------------------------------------------------------------
5   //  All rights reserved. This program and the accompanying materials
6   //  are made available under the terms of the Eclipse Public License v1.0
7   //  and Apache License v2.0 which accompanies this distribution.
8   //
9   //      The Eclipse Public License is available at
10  //      http://www.eclipse.org/legal/epl-v10.html
11  //
12  //      The Apache License v2.0 is available at
13  //      http://www.opensource.org/licenses/apache2.0.php
14  //
15  //  You may elect to redistribute this code under either of these licenses.
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       * Instantiates a new thread monitor.
62       *
63       * @throws Exception if unable to instantiate thread monitor
64       */
65      public ThreadMonitor() throws Exception
66      {
67          this(5000);
68      }
69      
70      /* ------------------------------------------------------------ */
71      /**
72       * Instantiates a new thread monitor.
73       *
74       * @param intervalMs scan interval
75       * @throws Exception if unable to instantiate thread monitor
76       */
77      public ThreadMonitor(int intervalMs) throws Exception
78      {
79          this(intervalMs, 95);
80      }
81      
82      /* ------------------------------------------------------------ */
83      /**
84       * Instantiates a new thread monitor.
85       *
86       * @param intervalMs scan interval
87       * @param threshold busy threshold
88       * @throws Exception if unable to instantiate thread monitor
89       */
90      public ThreadMonitor(int intervalMs, int threshold) throws Exception
91      {
92          this(intervalMs, threshold, 3);
93      }
94      
95      /* ------------------------------------------------------------ */
96      /**
97       * Instantiates a new thread monitor.
98       *
99       * @param intervalMs scan interval
100      * @param threshold busy threshold
101      * @param depth stack compare depth
102      * @throws Exception if unable to instantiate thread monitor
103      */
104     public ThreadMonitor(int intervalMs, int threshold, int depth) throws Exception
105     {
106         this(intervalMs, threshold, depth, 3);
107     }
108     
109     /* ------------------------------------------------------------ */
110     /**
111      * Instantiates a new thread monitor.
112      *
113      * @param intervalMs scan interval
114      * @param threshold busy threshold
115      * @param depth stack compare depth
116      * @param trail length of stack trail
117      * @throws Exception if unable to instantiate thread monitor
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      * Gets the scan interval.
135      *
136      * @return the scan interval
137      */
138     public int getScanInterval()
139     {
140         return _scanInterval;
141     }
142 
143     /* ------------------------------------------------------------ */
144     /**
145      * Sets the scan interval.
146      *
147      * @param ms the new scan interval
148      */
149     public void setScanInterval(int ms)
150     {
151         _scanInterval = ms;
152     }
153 
154     /* ------------------------------------------------------------ */
155     /**
156      * Gets the log interval.
157      *
158      * @return the log interval
159      */
160     public int getLogInterval()
161     {
162         return _logInterval;
163     }
164 
165     /* ------------------------------------------------------------ */
166     /**
167      * Sets the log interval.
168      *
169      * @param ms the new log interval
170      */
171     public void setLogInterval(int ms)
172     {
173         _logInterval = ms;
174     }
175 
176     /* ------------------------------------------------------------ */
177     /**
178      * Gets the busy threshold.
179      *
180      * @return the busy threshold
181      */
182     public int getBusyThreshold()
183     {
184         return _busyThreshold;
185     }
186 
187     /* ------------------------------------------------------------ */
188     /**
189      * Sets the busy threshold.
190      *
191      * @param percent the new busy threshold
192      */
193     public void setBusyThreshold(int percent)
194     {
195         _busyThreshold = percent;
196     }
197 
198     /* ------------------------------------------------------------ */
199     /**
200      * Gets the log threshold.
201      *
202      * @return the log threshold
203      */
204     public int getLogThreshold()
205     {
206         return _logThreshold;
207     }
208 
209     /* ------------------------------------------------------------ */
210     /**
211      * Sets the log threshold.
212      *
213      * @param percent the new log threshold
214      */
215     public void setLogThreshold(int percent)
216     {
217         _logThreshold = percent;
218     }
219 
220     /* ------------------------------------------------------------ */
221     /**
222      * Gets the stack depth.
223      *
224      * @return the stack depth
225      */
226     public int getStackDepth()
227     {
228         return _stackDepth;
229     }
230 
231     /* ------------------------------------------------------------ */
232     /**
233      * Sets the stack depth.
234      *
235      * @param stackDepth the new stack depth
236      */
237     public void setStackDepth(int stackDepth)
238     {
239         _stackDepth = stackDepth;
240     }
241     
242     /* ------------------------------------------------------------ */
243     /**
244      * Sets the stack trace trail length.
245      *
246      * @param trailLength the new trail length
247      */
248     public void setTrailLength(int trailLength)
249     {
250         _trailLength = trailLength;
251     }
252 
253     /* ------------------------------------------------------------ */
254     /**
255      * Gets the stack trace trail length.
256      *
257      * @return the trail length
258      */
259     public int getTrailLength()
260     {
261         return _trailLength;
262     }
263 
264     /* ------------------------------------------------------------ */
265     /**
266      * Enable logging of CPU usage.
267      *
268      * @param frequencyMs the logging frequency 
269      * @param thresholdPercent the logging threshold
270      */
271     public void logCpuUsage(int frequencyMs, int thresholdPercent)
272     {
273         setLogInterval(frequencyMs);
274         setLogThreshold(thresholdPercent);
275     }
276     
277     /* ------------------------------------------------------------ */
278     /**
279      * @return A {@link Dumpable} that is dumped whenever spinning threads are detected
280      */
281     public Dumpable getDumpable()
282     {
283         return _dumpable;
284     }
285 
286     /* ------------------------------------------------------------ */
287     /**
288      * @param dumpable A {@link Dumpable} that is dumped whenever spinning threads are detected
289      */
290     public void setDumpable(Dumpable dumpable)
291     {
292         _dumpable = dumpable;
293     }
294 
295     /* ------------------------------------------------------------ */
296     /**
297      * @see org.eclipse.jetty.util.component.AbstractLifeCycle#doStart()
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      * @see org.eclipse.jetty.util.component.AbstractLifeCycle#doStop()
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      * Retrieve all avaliable thread ids
330      *
331      * @return array of thread ids
332      */
333     protected long[] getAllThreadIds()
334     {
335         return _threadBean.getAllThreadIds();
336     }
337 
338     /* ------------------------------------------------------------ */
339     /**
340      * Retrieve the cpu time for specified thread.
341      *
342      * @param id thread id
343      * @return cpu time of the thread
344      */
345     protected long getThreadCpuTime(long id)
346     {
347         return _threadBean.getThreadCpuTime(id);
348     }
349     
350     /* ------------------------------------------------------------ */
351     /**
352      * Initialize JMX objects.
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      * @see java.lang.Runnable#run()
366      */
367     public void run()
368     {
369         // Initialize repeat flag
370         boolean repeat = false;
371         boolean scanNow, logNow;
372 
373         // Set next scan time and log time
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             // Sleep only if not going to repeat scanning immediately
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      * Collect thread info.
416      */
417     private boolean collectThreadInfo()
418     {
419         boolean repeat = false;
420         try
421         {
422             // Retrieve stack traces for all threads at once as it 
423             // was proven to be an order of magnitude faster when
424             // retrieving a single thread stack trace.
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                 // Skip our own runner thread
433                 if (threadId == _runner.getId())
434                 {
435                     continue;
436                 }
437 
438                 ThreadMonitorInfo currMonitorInfo = _monitorInfo.get(Long.valueOf(threadId));
439                 if (currMonitorInfo == null)
440                 {
441                     // Create thread info object for a new thread 
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                     // Update the existing thread info object
451                     currMonitorInfo.setStackTrace(entry.getValue());
452                     currMonitorInfo.setCpuTime(getThreadCpuTime(threadId));
453                     currMonitorInfo.setSampleTime(System.nanoTime());
454     
455                     // Stack trace count holds logging state
456                     int count = currMonitorInfo.getTraceCount();
457                     if (count >= 0 && currMonitorInfo.isSpinning())
458                     {
459                         // Thread was spinning and was logged before
460                         if (count < _trailLength) 
461                         {
462                             // Log another stack trace
463                             currMonitorInfo.setTraceCount(count+1);
464                             repeat = true;
465                             continue;
466                         }
467                         
468                         // Reset spin flag and trace count
469                         currMonitorInfo.setSpinning(false);
470                         currMonitorInfo.setTraceCount(-1);
471                     }
472                     if (currMonitorInfo.getCpuUtilization() > _busyThreshold)
473                     {
474                         // Thread is busy
475                         StackTraceElement[] lastStackTrace = currMonitorInfo.getStackTrace();
476     
477                         if (lastStackTrace != null 
478                         && matchStackTraces(lastStackTrace, entry.getValue()))
479                         {
480                             // Thread is spinning
481                             currMonitorInfo.setSpinning(true);
482                             if (count < 0)
483                             {
484                                 // Enable logging of spin status and stack traces 
485                                 // only if the incoming trace count is negative
486                                 // that indicates a new scan for this thread
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             // Select thread objects for all live threads
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             // Sort selected thread objects by their CPU utilization
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             // Log thread information for threads that exceed logging threshold
532             // or log spinning threads if their trace count is zero
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             // Dump info
549             if (spinning && _dumpable!=null)
550             {
551                 System.err.println(_dumpable.dump());
552             }
553 
554             // Log stack traces for spinning threads with positive trace count
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      * Match stack traces.
572      *
573      * @param lastStackTrace last stack trace
574      * @param stackTrace current stack trace
575      * @return true, if successful
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 }