View Javadoc

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