From 599d7f92c9e1564a8c51ed3c2b833a9c25324731 Mon Sep 17 00:00:00 2001 From: Michael Gorovoy Date: Wed, 10 Aug 2011 01:31:16 -0400 Subject: [PATCH 1/2] 352684 Added spinning thread analyzer, improved logging to eliminate redundant info --- .../eclipse/jetty/monitor/ThreadMonitor.java | 647 +++++++----------- .../jetty/monitor/ThreadMonitorInfo.java | 223 ++++++ .../jetty/monitor/ThreadMonitorTest.java | 74 +- 3 files changed, 523 insertions(+), 421 deletions(-) create mode 100644 jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitorInfo.java diff --git a/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitor.java b/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitor.java index 7b7e8d3773e..ffe3b88a3bf 100644 --- a/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitor.java +++ b/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitor.java @@ -34,9 +34,11 @@ import org.eclipse.jetty.util.log.Logger; public class ThreadMonitor extends AbstractLifeCycle implements Runnable { private int _scanInterval; - private int _dumpInterval; + private int _logInterval; + private int _detectInterval; + private int _detectPeriod; private int _busyThreshold; - private int _dumpThreshold; + private int _logThreshold; private int _stackDepth; private ThreadMXBean _threadBean; @@ -46,7 +48,7 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable private Logger _logger; private volatile boolean _done = true; - private Map _extInfo; + private Map _monitorInfo; /* ------------------------------------------------------------ */ /** @@ -75,7 +77,7 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable _stackDepth = depth; _logger = Log.getLogger(ThreadMonitor.class.getName()); - _extInfo = new HashMap(); + _monitorInfo = new HashMap(); init(); } @@ -93,15 +95,39 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable } /* ------------------------------------------------------------ */ - public int getDumpInterval() + public int getLogInterval() { - return _dumpInterval; + return _logInterval; } /* ------------------------------------------------------------ */ - public void setDumpInterval(int ms) + public void setLogInterval(int ms) { - _dumpInterval = ms; + _logInterval = ms; + } + + /* ------------------------------------------------------------ */ + public int getDetectInterval() + { + return _detectInterval; + } + + /* ------------------------------------------------------------ */ + public void setDetectInterval(int ms) + { + _detectInterval = ms; + } + + /* ------------------------------------------------------------ */ + public int getDetectPeriod() + { + return _detectPeriod; + } + + /* ------------------------------------------------------------ */ + public void setDetectPeriod(int ms) + { + _detectPeriod = ms; } /* ------------------------------------------------------------ */ @@ -117,15 +143,15 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable } /* ------------------------------------------------------------ */ - public int getDumpThreshold() + public int getLogThreshold() { - return _dumpThreshold; + return _logThreshold; } /* ------------------------------------------------------------ */ - public void setDumpThreshold(int percent) + public void setLogThreshold(int percent) { - _dumpThreshold = percent; + _logThreshold = percent; } /* ------------------------------------------------------------ */ @@ -141,10 +167,17 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable } /* ------------------------------------------------------------ */ - public void enableDumpAll(int ms, int percent) + public void logCpuUsage(int ms, int percent) { - setDumpInterval(ms); - setDumpThreshold(percent); + setLogInterval(ms); + setLogThreshold(percent); + } + + /* ------------------------------------------------------------ */ + public void logSpinInfo(int periodMs, int intervalMs) + { + setDetectPeriod(periodMs); + setDetectInterval(intervalMs); } /* ------------------------------------------------------------ */ @@ -180,47 +213,23 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable /* ------------------------------------------------------------ */ /** - * Initialize JMX objects. + * Find deadlocked threads. + * + * @return array of the deadlocked thread ids */ - protected void init() + protected long[] findDeadlockedThreads() { - _threadBean = ManagementFactory.getThreadMXBean(); - if (_threadBean.isThreadCpuTimeSupported()) - { - _threadBean.setThreadCpuTimeEnabled(true); - } - - String versionStr = System.getProperty("java.version"); - float version = Float.valueOf(versionStr.substring(0,versionStr.lastIndexOf('.'))); try { - if (version < 1.6) - { - findDeadlockedThreadsMethod = ThreadMXBean.class.getMethod("findMonitorDeadlockedThreads"); - } - else - { - findDeadlockedThreadsMethod = ThreadMXBean.class.getMethod("findDeadlockedThreads"); - } + return (long[])findDeadlockedThreadsMethod.invoke(_threadBean,(Object[])null); } catch (Exception ex) { Log.debug(ex); + return new long[0]; } } - /* ------------------------------------------------------------ */ - /** - * Find deadlocked threads. - * - * @return array of the deadlocked thread ids - * @throws Exception the exception - */ - protected long[] findDeadlockedThreads() throws Exception - { - return (long[]) findDeadlockedThreadsMethod.invoke(_threadBean,(Object[])null); - } - /* ------------------------------------------------------------ */ /** * Retrieve all avaliable thread ids @@ -259,69 +268,35 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable /* ------------------------------------------------------------ */ /** - * Output thread info to log. - * - * @param threads thread info list + * Initialize JMX objects. */ - protected void dump(final List threads) + protected void init() { - if (threads != null && threads.size() > 0) + _threadBean = ManagementFactory.getThreadMXBean(); + if (_threadBean.isThreadCpuTimeSupported()) { - for (ThreadInfo info : threads) - { - StringBuffer msg = new StringBuffer(); - if (info.getLockOwnerId() < 0) - { - String state = info.isInNative() ? "IN_NATIVE" : - info.getThreadState().toString(); - msg.append(String.format("Thread %s[id:%d,%s] is spinning", - info.getThreadName(), info.getThreadId(), state)); - } - else - { - msg.append(String.format("Thread %s[id:%d,%s]", - info.getThreadName(), info.getThreadId(), info.getThreadState())); - msg.append(String.format(" on %s owned by %s[id:%d]", - info.getLockName(), info.getLockOwnerName(), info.getLockOwnerId())); - } - - _logger.warn(new ThreadMonitorException(msg.toString(), info.getStackTrace())); + _threadBean.setThreadCpuTimeEnabled(true); + } + + String versionStr = System.getProperty("java.version"); + float version = Float.valueOf(versionStr.substring(0,versionStr.lastIndexOf('.'))); + try + { + if (version < 1.6) + { + findDeadlockedThreadsMethod = ThreadMXBean.class.getMethod("findMonitorDeadlockedThreads"); } + else + { + findDeadlockedThreadsMethod = ThreadMXBean.class.getMethod("findDeadlockedThreads"); + } + } + catch (Exception ex) + { + Log.debug(ex); } } - protected void dumpAll() - { - if (_extInfo.size() > 0) - { - List sorted = new ArrayList(_extInfo.values()); - Collections.sort(sorted, new Comparator() { - /* ------------------------------------------------------------ */ - public int compare(ExtThreadInfo eti1, ExtThreadInfo eti2) - { - return (int)Math.signum(eti2.getCpuUtilization()-eti1.getCpuUtilization()); - } - }); - - for (ExtThreadInfo info : sorted) - { - ThreadInfo threadInfo = getThreadInfo(info.getThreadId(), 0); - - if (info.getCpuUtilization() > 1.0f) - { - String state = threadInfo.isInNative() ? "IN_NATIVE" : - threadInfo.getThreadState().toString(); - _logger.info(String.format("Thread %s[id:%d,%s] is using %.2f%% of CPU", - threadInfo.getThreadName(), threadInfo.getThreadId(), - state, info.getCpuUtilization())); - } - - info.setDumpCpuTime(info.getLastCpuTime()); - info.setDumpSampleTime(info.getLastSampleTime()); - } - } - } - /* ------------------------------------------------------------ */ /** * @see java.lang.Runnable#run() @@ -338,7 +313,7 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable { try { - Thread.sleep(50); + Thread.sleep(100); } catch (InterruptedException ex) { @@ -347,135 +322,197 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable continue; } - List threadInfo = new ArrayList(); - - findSpinningThreads(threadInfo); - findDeadlockedThreads(threadInfo); - + collectThreadInfo(); lastTime = System.currentTimeMillis(); - - if (threadInfo.size() > 0) - { - dump(threadInfo); - } - if (_dumpInterval > 0 && lastTime > lastDumpTime + _dumpInterval) + if (_logInterval > 0 && lastTime > lastDumpTime + _logInterval) { + logCpuUsage(); lastDumpTime = lastTime; - - dumpAll(); } + logThreadState(); } } /* ------------------------------------------------------------ */ /** - * Find spinning threads. - * - * @param threadInfo thread info list to add the results - * @return thread info list + * Collect thread info. */ - private List findSpinningThreads(final List threadInfo) + private void collectThreadInfo() { - if (threadInfo != null) + try { - try + long[] allThreadId = getAllThreadIds(); + for (int idx=0; idx < allThreadId.length; idx++) { - long[] allThreadId = getAllThreadIds(); - for (int idx=0; idx < allThreadId.length; idx++) + long currId = allThreadId[idx]; + + if (currId == _runner.getId()) { - long currId = allThreadId[idx]; - - if (currId == _runner.getId()) - { - continue; - } - - long currCpuTime = getThreadCpuTime(currId); - long currNanoTime = System.nanoTime(); - - ExtThreadInfo currExtInfo = _extInfo.get(Long.valueOf(currId)); - if (currExtInfo != null) - { - long elapsedCpuTime = currCpuTime - currExtInfo.getLastCpuTime(); - long elapsedNanoTime = currNanoTime - currExtInfo.getLastSampleTime(); - - float cpuUtilization = Math.min((elapsedCpuTime * 100.0f) / elapsedNanoTime, 100.0f); - currExtInfo.setCpuUtilization(cpuUtilization); - if (cpuUtilization > _busyThreshold) - { - ThreadInfo currInfo = getThreadInfo(currId, Integer.MAX_VALUE); - if (currInfo != null) - { - StackTraceElement[] lastStackTrace = currExtInfo.getStackTrace(); - currExtInfo.setStackTrace(currInfo.getStackTrace()); + continue; + } - if (lastStackTrace != null - && matchStackTraces(lastStackTrace, currInfo.getStackTrace())) { - threadInfo.add(currInfo); - } - } - } + ThreadMonitorInfo currMonitorInfo = _monitorInfo.get(Long.valueOf(currId)); + if (currMonitorInfo == null) + { + currMonitorInfo = new ThreadMonitorInfo(getThreadInfo(currId,0)); + currMonitorInfo.setCpuTime(getThreadCpuTime(currId)); + currMonitorInfo.setSampleTime(System.nanoTime()); + _monitorInfo.put(Long.valueOf(currId), currMonitorInfo); + } + else + { + currMonitorInfo.setCpuTime(getThreadCpuTime(currId)); + currMonitorInfo.setSampleTime(System.nanoTime()); + + if (currMonitorInfo.getCpuUtilization() < _busyThreshold) + { + currMonitorInfo.setInfo(getThreadInfo(currId,0)); } else { - currExtInfo = new ExtThreadInfo(getThreadInfo(currId, 0)); - currExtInfo.setFirstCpuTime(currCpuTime); - currExtInfo.setFirstSampleTime(currNanoTime); - currExtInfo.setDumpCpuTime(currCpuTime); - currExtInfo.setDumpSampleTime(currNanoTime); - - _extInfo.put(Long.valueOf(currId), currExtInfo); - } - - currExtInfo.setLastCpuTime(currCpuTime); - currExtInfo.setLastSampleTime(currNanoTime); - } - } - catch (Exception ex) - { - Log.debug(ex); - } - } - - return threadInfo; - } - - /* ------------------------------------------------------------ */ - /** - * Find deadlocked threads. - * - * @param threadInfo thread info list to add the results - * @return thread info list - */ - private List findDeadlockedThreads(final List threadInfo) - { - if (threadInfo != null) - { - try - { - long[] threads = findDeadlockedThreads(); - if (threads != null && threads.length > 0) - { - ThreadInfo currInfo; - for (int idx=0; idx < threads.length; idx++) - { - currInfo = getThreadInfo(threads[idx], Integer.MAX_VALUE); - if (currInfo != null) + ThreadInfo threadInfo = getThreadInfo(currId,Integer.MAX_VALUE); + StackTraceElement[] lastStackTrace = currMonitorInfo.getStackTrace(); + currMonitorInfo.setInfo(threadInfo); + + if (lastStackTrace != null + && matchStackTraces(lastStackTrace, threadInfo.getStackTrace())) { - threadInfo.add(currInfo); + spinAnalyzer(currMonitorInfo); } } } } - catch (Exception ex) + } + catch (Exception ex) + { + Log.debug(ex); + } + } + + /* ------------------------------------------------------------ */ + /** + * Collect spin info. + * + * @param threadId the thread id + */ + protected void spinAnalyzer(ThreadMonitorInfo info) + { + info.setSpinning(true); + + if (_detectPeriod > 0 && _detectInterval > 0) + { + long threadId = info.getThreadId(); + long sampleTime = info.getSampleTime() / 1000000; + long endTime = System.currentTimeMillis() + _detectPeriod; + do { - Log.debug(ex); + if (sampleTime + _detectInterval < System.currentTimeMillis()) + { + ThreadInfo threadInfo = getThreadInfo(threadId,Integer.MAX_VALUE); + if (threadInfo != null) + { + info.addStackTrace(threadInfo.getStackTrace()); + sampleTime = System.currentTimeMillis(); + } + } + + } + while(System.currentTimeMillis() < endTime); + } + } + + /* ------------------------------------------------------------ */ + protected void logCpuUsage() + { + if (_monitorInfo.size() > 0) + { + long[] running = getAllThreadIds(); + List all = new ArrayList(); + for (int idx=0; idx() + { + /* ------------------------------------------------------------ */ + public int compare(ThreadMonitorInfo info1, ThreadMonitorInfo info2) + { + return (int)Math.signum(info2.getCpuUtilization()-info1.getCpuUtilization()); + } + }); + + String format = "Thread %1$s[id:%2$d,%3$s] - %4$.2f%%"; + for (ThreadMonitorInfo info : all) + { + if (info.getCpuUtilization() > _logThreshold) + { + String message = String.format(format, info.getThreadName(), + info.getThreadId(), info.getThreadState(), info.getCpuUtilization()); + _logger.info(message); + } + } + } + } + + /* ------------------------------------------------------------ */ + /** + * Output thread info to log. + * + * @param detected thread info list + */ + protected void logThreadState() + { + if (_monitorInfo.size() > 0) + { + String format = "Thread %1$s[id:%2$d,%3$s] is SPINNING"; + + long[] all = getAllThreadIds(); + for (int idx=0; idx stackTraces = info.getStackTraces(); + int size = stackTraces.size(); + for (int sti=1; sti 0) + { + for (int idx=0; idx=0 ) + { + StringBuilder builder = new StringBuilder(); + builder.append(String.format("Thread %s[id:%d,%s] is DEADLOCKED", + info.getThreadName(), info.getThreadId(), info.getThreadState())); + builder.append(String.format(" on %s owned by %s[id:%d]", + info.getLockName(), info.getLockOwnerName(), info.getLockOwnerId())); + StackTraceElement[] stackTrace = getThreadInfo(locked[idx],Integer.MAX_VALUE).getStackTrace(); + _logger.warn(new ThreadMonitorException(builder.toString(), stackTrace)); + } + } } } - - return threadInfo; } /* ------------------------------------------------------------ */ @@ -501,208 +538,4 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable } return match; } - - /* ------------------------------------------------------------ */ - private class ExtThreadInfo - { - private ThreadInfo _threadInfo; - - private long _firstCpuTime; - private long _firstSampleTime; - private long _lastCpuTime; - private long _lastSampleTime; - private long _dumpCpuTime; - private long _dumpSampleTime; - - private float _cpuUtilization; - - private StackTraceElement[] _stackTrace; - - /* ------------------------------------------------------------ */ - public ExtThreadInfo(ThreadInfo threadInfo) - { - _threadInfo = threadInfo; - } - - /* ------------------------------------------------------------ */ - /** - * @return thread id associated with the instance - */ - public ThreadInfo getThreadInfo() - { - return _threadInfo; - } - - /** - * @return the thread Id - */ - public long getThreadId() - { - return _threadInfo.getThreadId(); - } - - /* ------------------------------------------------------------ */ - /** - * @return the first CPU time of the thread - */ - public long getFirstCpuTime() - { - return _firstCpuTime; - } - - /* ------------------------------------------------------------ */ - /** - * Set the first CPU time. - * - * @param ns new last CPU time - */ - public void setFirstCpuTime(long ns) - { - _firstCpuTime = ns; - } - - /* ------------------------------------------------------------ */ - /** - * @return the time of first sample - */ - public long getFirstSampleTime() - { - return _firstSampleTime; - } - - /* ------------------------------------------------------------ */ - /** - * Sets the first sample time. - * - * @param ns the time of first sample - */ - public void setFirstSampleTime(long ns) - { - _firstSampleTime = ns; - } - - /* ------------------------------------------------------------ */ - /** - * @return the last CPU time of the thread - */ - public long getLastCpuTime() - { - return _lastCpuTime; - } - - /* ------------------------------------------------------------ */ - /** - * Set the last CPU time. - * - * @param ns new last CPU time - */ - public void setLastCpuTime(long ns) - { - _lastCpuTime = ns; - } - - /* ------------------------------------------------------------ */ - /** - * @return the time of last sample - */ - public long getLastSampleTime() - { - return _lastSampleTime; - } - - /* ------------------------------------------------------------ */ - /** - * Sets the last sample time. - * - * @param ns the time of last sample - */ - public void setLastSampleTime(long ns) - { - _lastSampleTime = ns; - } - - /* ------------------------------------------------------------ */ - /** - * @return the dump CPU time of the thread - */ - public long getDumpCpuTime() - { - return _dumpCpuTime; - } - - /* ------------------------------------------------------------ */ - /** - * Set the dump CPU time. - * - * @param ns new dump CPU time - */ - public void setDumpCpuTime(long ns) - { - _dumpCpuTime = ns; - } - - /* ------------------------------------------------------------ */ - /** - * @return the time of dump sample - */ - public long getDumpSampleTime() - { - return _dumpSampleTime; - } - - /* ------------------------------------------------------------ */ - /** - * Sets the dump sample time. - * - * @param ns the time of dump sample - */ - public void setDumpSampleTime(long ns) - { - _dumpSampleTime = ns; - } - - /* ------------------------------------------------------------ */ - /** - * Gets the CPU utilization. - * - * @return the CPU utilization percentage - */ - public float getCpuUtilization() - { - return _cpuUtilization; - } - - /* ------------------------------------------------------------ */ - /** - * Sets the CPU utilization. - * - * @param percentage the new CPU utilization percentage - */ - public void setCpuUtilization(float percentage) - { - _cpuUtilization = percentage; - } - - /* ------------------------------------------------------------ */ - /** - * Gets the stack trace. - * - * @return the stack trace - */ - public StackTraceElement[] getStackTrace() - { - return _stackTrace; - } - - /* ------------------------------------------------------------ */ - /** - * Sets the stack trace. - * - * @param stackTrace the new stack trace - */ - public void setStackTrace(StackTraceElement[] stackTrace) - { - _stackTrace = stackTrace; - } - } } diff --git a/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitorInfo.java b/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitorInfo.java new file mode 100644 index 00000000000..9f069235c5a --- /dev/null +++ b/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitorInfo.java @@ -0,0 +1,223 @@ +// ======================================================================== +// Copyright (c) Webtide LLC +// ------------------------------------------------------------------------ +// All rights reserved. This program and the accompanying materials +// are made available under the terms of the Eclipse Public License v1.0 +// and Apache License v2.0 which accompanies this distribution. +// The Eclipse Public License is available at +// http://www.eclipse.org/legal/epl-v10.html +// The Apache License v2.0 is available at +// http://www.opensource.org/licenses/apache2.0.php +// You may elect to redistribute this code under either of these licenses. +// ======================================================================== + + +package org.eclipse.jetty.monitor; + +import java.lang.management.ThreadInfo; +import java.util.ArrayList; +import java.util.List; + + +/* ------------------------------------------------------------ */ +/** + */ +public class ThreadMonitorInfo +{ + private long _threadId; + private String _threadName; + private String _threadState; + + private long _lockOwnerId; + private String _lockOwnerName; + private String _lockName; + + private List _stackTraces; + + private long _prevCpuTime; + private long _prevSampleTime; + private long _currCpuTime; + private long _currSampleTime; + + private boolean _threadSpinning; + + /* ------------------------------------------------------------ */ + /** + * Instantiates a new thread monitor info. + * + * @param threadInfo the thread info + */ + public ThreadMonitorInfo(ThreadInfo threadInfo) + { + _stackTraces = new ArrayList(); + + setInfo(threadInfo); + } + + /* ------------------------------------------------------------ */ + /** + * Sets the thread info. + * + * @param threadInfo the new thread info + */ + public void setInfo(ThreadInfo threadInfo) + { + _threadId = threadInfo.getThreadId(); + _threadName = threadInfo.getThreadName(); + _threadState = threadInfo.isInNative() ? "IN_NATIVE" : + threadInfo.getThreadState().toString(); + + _lockOwnerId = threadInfo.getLockOwnerId(); + _lockOwnerName = threadInfo.getLockOwnerName(); + _lockName = threadInfo.getLockName(); + + _stackTraces.clear(); + addStackTrace(threadInfo.getStackTrace()); + + _threadSpinning = false; + } + + /* ------------------------------------------------------------ */ + /** + * @return Id of the thread + */ + public long getThreadId() + { + return _threadId; + } + + /* ------------------------------------------------------------ */ + /** + * Gets the thread name. + * + * @return the thread name + */ + public String getThreadName() + { + return _threadName; + } + + /* ------------------------------------------------------------ */ + /** + * Gets the thread state. + * + * @return the thread state + */ + public String getThreadState() + { + return _threadState; + } + + /* ------------------------------------------------------------ */ + /** Get the lockOwnerId. + * @return the lockOwnerId + */ + public long getLockOwnerId() + { + return _lockOwnerId; + } + + /* ------------------------------------------------------------ */ + /** Get the lockOwnerName. + * @return the lockOwnerName + */ + public String getLockOwnerName() + { + return _lockOwnerName; + } + + /* ------------------------------------------------------------ */ + /** Get the lockName. + * @return the lockName + */ + public String getLockName() + { + return _lockName; + } + + public List getStackTraces() + { + return _stackTraces; + } + + public StackTraceElement[] getStackTrace() + { + return _stackTraces.size() == 0 ? null : _stackTraces.get(0); + } + + public void addStackTrace(StackTraceElement[] stackTrace) + { + if (stackTrace != null && stackTrace.length > 0) + { + _stackTraces.add(stackTrace); + } + } + + /* ------------------------------------------------------------ */ + /** + * @return the CPU time of the thread + */ + public long getCpuTime() + { + return _currCpuTime; + } + + /* ------------------------------------------------------------ */ + /** + * Set the CPU time. + * + * @param ns new CPU time + */ + public void setCpuTime(long ns) + { + _prevCpuTime = _currCpuTime; + _currCpuTime = ns; + } + + /* ------------------------------------------------------------ */ + /** + * @return the time of sample + */ + public long getSampleTime() + { + return _currSampleTime; + } + + /* ------------------------------------------------------------ */ + /** + * Sets the sample time. + * + * @param ns the time of sample + */ + public void setSampleTime(long ns) + { + _prevSampleTime = _currSampleTime; + _currSampleTime = ns; + } + + /* ------------------------------------------------------------ */ + /** + * Gets the CPU utilization. + * + * @return the CPU utilization percentage + */ + public float getCpuUtilization() + { + long elapsedCpuTime = _currCpuTime - _prevCpuTime; + long elapsedNanoTime = _currSampleTime - _prevSampleTime; + + return elapsedNanoTime > 0 ? Math.min((elapsedCpuTime * 100.0f) / elapsedNanoTime, 100.0f) : 0; + } + + /* ------------------------------------------------------------ */ + public void setSpinning(boolean value) + { + _threadSpinning = value; + } + + /* ------------------------------------------------------------ */ + public boolean isSpinning() + { + return _threadSpinning; + } +} diff --git a/jetty-monitor/src/test/java/org/eclipse/jetty/monitor/ThreadMonitorTest.java b/jetty-monitor/src/test/java/org/eclipse/jetty/monitor/ThreadMonitorTest.java index 5e15b930b4b..4ecaf710798 100644 --- a/jetty-monitor/src/test/java/org/eclipse/jetty/monitor/ThreadMonitorTest.java +++ b/jetty-monitor/src/test/java/org/eclipse/jetty/monitor/ThreadMonitorTest.java @@ -16,8 +16,6 @@ package org.eclipse.jetty.monitor; import static org.junit.Assert.assertTrue; -import java.lang.management.ThreadInfo; -import java.util.List; import java.util.concurrent.atomic.AtomicInteger; import org.junit.Test; @@ -29,42 +27,62 @@ import org.junit.Test; public class ThreadMonitorTest { public final static int DURATION=9000; - private AtomicInteger count=new AtomicInteger(0); - private AtomicInteger countDump=new AtomicInteger(0); @Test public void monitorTest() throws Exception { + final AtomicInteger countSpins=new AtomicInteger(0); + final AtomicInteger countCpuLogs=new AtomicInteger(0); + final AtomicInteger countStateLogs=new AtomicInteger(0); - ThreadMonitor monitor = new ThreadMonitor(1000,50,2) + ThreadMonitor monitor = new ThreadMonitor(1000,50,1) { @Override - protected void dump(List threads) + protected void spinAnalyzer(ThreadMonitorInfo info) { - count.incrementAndGet(); - super.dump(threads); + countSpins.incrementAndGet(); + super.spinAnalyzer(info); } @Override - protected void dumpAll() + protected void logCpuUsage() { - countDump.incrementAndGet(); - super.dumpAll(); + countCpuLogs.incrementAndGet(); + super.logCpuUsage(); + } + @Override + protected void logThreadState() + { + countStateLogs.incrementAndGet(); + super.logThreadState(); } }; - monitor.enableDumpAll(2000,1); + monitor.logCpuUsage(2000,1); + monitor.logSpinInfo(100,20); monitor.start(); Spinner spinner = new Spinner(); Thread runner = new Thread(spinner); runner.start(); + Locker locker1 = new Locker(); + Locker locker2 = new Locker(); + locker1.setLock(locker2); + locker2.setLock(locker1); + Thread runner1 = new Thread(locker1); + Thread runner2 = new Thread(locker2); + runner1.start(); + runner2.start(); + Thread.sleep(DURATION); spinner.setDone(); monitor.stop(); + runner1.interrupt(); + runner2.interrupt(); - assertTrue(count.get() >= 2); - assertTrue(countDump.get() >= 1); + assertTrue(countSpins.get() >= 1); + assertTrue(countCpuLogs.get() >= 1); + assertTrue(countStateLogs.get() >= 1); } @@ -100,6 +118,34 @@ public class ThreadMonitorTest if (result==42) System.err.println("Bingo!"); } + } + + private class Locker implements Runnable + { + private Object _lock; + public void setLock(Object lock) + { + _lock = lock; + } + + public void run() + { + try + { + lockOn(); + } + catch (InterruptedException ex) {} + } + + public synchronized void lockOn() throws InterruptedException + { + Thread.sleep(100); + + synchronized (_lock) + { + Thread.sleep(100); + } + } } } From f01c8f7ebf8cfbd2670da9ed5fbc01c343af8bb3 Mon Sep 17 00:00:00 2001 From: Michael Gorovoy Date: Wed, 10 Aug 2011 17:28:27 -0400 Subject: [PATCH 2/2] 352684 Rewrote thread monitor code, removed deadlock detection, removed spin analyzer that was slow --- .../eclipse/jetty/monitor/ThreadMonitor.java | 193 ++---------------- .../jetty/monitor/ThreadMonitorInfo.java | 135 ++++-------- .../jetty/monitor/ThreadMonitorTest.java | 49 ----- 3 files changed, 66 insertions(+), 311 deletions(-) diff --git a/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitor.java b/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitor.java index ffe3b88a3bf..ea63bc8f6b1 100644 --- a/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitor.java +++ b/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitor.java @@ -15,9 +15,7 @@ package org.eclipse.jetty.monitor; import java.lang.management.ManagementFactory; -import java.lang.management.ThreadInfo; import java.lang.management.ThreadMXBean; -import java.lang.reflect.Method; import java.util.ArrayList; import java.util.Collections; import java.util.Comparator; @@ -35,14 +33,11 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable { private int _scanInterval; private int _logInterval; - private int _detectInterval; - private int _detectPeriod; private int _busyThreshold; private int _logThreshold; private int _stackDepth; private ThreadMXBean _threadBean; - private Method findDeadlockedThreadsMethod; private Thread _runner; private Logger _logger; @@ -106,30 +101,6 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable _logInterval = ms; } - /* ------------------------------------------------------------ */ - public int getDetectInterval() - { - return _detectInterval; - } - - /* ------------------------------------------------------------ */ - public void setDetectInterval(int ms) - { - _detectInterval = ms; - } - - /* ------------------------------------------------------------ */ - public int getDetectPeriod() - { - return _detectPeriod; - } - - /* ------------------------------------------------------------ */ - public void setDetectPeriod(int ms) - { - _detectPeriod = ms; - } - /* ------------------------------------------------------------ */ public int getBusyThreshold() { @@ -167,19 +138,12 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable } /* ------------------------------------------------------------ */ - public void logCpuUsage(int ms, int percent) + public void logCpuUsage(int frequencyMs, int thresholdPercent) { - setLogInterval(ms); - setLogThreshold(percent); + setLogInterval(frequencyMs); + setLogThreshold(thresholdPercent); } - /* ------------------------------------------------------------ */ - public void logSpinInfo(int periodMs, int intervalMs) - { - setDetectPeriod(periodMs); - setDetectInterval(intervalMs); - } - /* ------------------------------------------------------------ */ /** * @see org.eclipse.jetty.util.component.AbstractLifeCycle#doStart() @@ -189,6 +153,7 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable _done = false; _runner = new Thread(this); + _runner.setDaemon(true); _runner.start(); Log.info("Thread Monitor started successfully"); @@ -211,25 +176,6 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable } } - /* ------------------------------------------------------------ */ - /** - * Find deadlocked threads. - * - * @return array of the deadlocked thread ids - */ - protected long[] findDeadlockedThreads() - { - try - { - return (long[])findDeadlockedThreadsMethod.invoke(_threadBean,(Object[])null); - } - catch (Exception ex) - { - Log.debug(ex); - return new long[0]; - } - } - /* ------------------------------------------------------------ */ /** * Retrieve all avaliable thread ids @@ -253,19 +199,6 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable return _threadBean.getThreadCpuTime(id); } - /* ------------------------------------------------------------ */ - /** - * Retrieve thread info. - * - * @param id thread id - * @param maxDepth maximum stack depth - * @return thread info - */ - protected ThreadInfo getThreadInfo(long id, int maxDepth) - { - return _threadBean.getThreadInfo(id,maxDepth); - } - /* ------------------------------------------------------------ */ /** * Initialize JMX objects. @@ -277,24 +210,6 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable { _threadBean.setThreadCpuTimeEnabled(true); } - - String versionStr = System.getProperty("java.version"); - float version = Float.valueOf(versionStr.substring(0,versionStr.lastIndexOf('.'))); - try - { - if (version < 1.6) - { - findDeadlockedThreadsMethod = ThreadMXBean.class.getMethod("findMonitorDeadlockedThreads"); - } - else - { - findDeadlockedThreadsMethod = ThreadMXBean.class.getMethod("findDeadlockedThreads"); - } - } - catch (Exception ex) - { - Log.debug(ex); - } } /* ------------------------------------------------------------ */ @@ -343,43 +258,41 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable { try { - long[] allThreadId = getAllThreadIds(); - for (int idx=0; idx < allThreadId.length; idx++) + Map all = Thread.getAllStackTraces(); + for (Map.Entry entry : all.entrySet()) { - long currId = allThreadId[idx]; + Thread thread = entry.getKey(); + long threadId = thread.getId(); - if (currId == _runner.getId()) + if (threadId == _runner.getId()) { continue; } - ThreadMonitorInfo currMonitorInfo = _monitorInfo.get(Long.valueOf(currId)); + ThreadMonitorInfo currMonitorInfo = _monitorInfo.get(Long.valueOf(threadId)); if (currMonitorInfo == null) { - currMonitorInfo = new ThreadMonitorInfo(getThreadInfo(currId,0)); - currMonitorInfo.setCpuTime(getThreadCpuTime(currId)); + currMonitorInfo = new ThreadMonitorInfo(thread); + currMonitorInfo.setStackTrace(entry.getValue()); + currMonitorInfo.setCpuTime(getThreadCpuTime(threadId)); currMonitorInfo.setSampleTime(System.nanoTime()); - _monitorInfo.put(Long.valueOf(currId), currMonitorInfo); + _monitorInfo.put(Long.valueOf(threadId), currMonitorInfo); } else { - currMonitorInfo.setCpuTime(getThreadCpuTime(currId)); + currMonitorInfo.setStackTrace(entry.getValue()); + currMonitorInfo.setCpuTime(getThreadCpuTime(threadId)); currMonitorInfo.setSampleTime(System.nanoTime()); - if (currMonitorInfo.getCpuUtilization() < _busyThreshold) + currMonitorInfo.setSpinning(false); + if (currMonitorInfo.getCpuUtilization() > _busyThreshold) { - currMonitorInfo.setInfo(getThreadInfo(currId,0)); - } - else - { - ThreadInfo threadInfo = getThreadInfo(currId,Integer.MAX_VALUE); StackTraceElement[] lastStackTrace = currMonitorInfo.getStackTrace(); - currMonitorInfo.setInfo(threadInfo); if (lastStackTrace != null - && matchStackTraces(lastStackTrace, threadInfo.getStackTrace())) + && matchStackTraces(lastStackTrace, entry.getValue())) { - spinAnalyzer(currMonitorInfo); + currMonitorInfo.setSpinning(true); } } } @@ -391,38 +304,6 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable } } - /* ------------------------------------------------------------ */ - /** - * Collect spin info. - * - * @param threadId the thread id - */ - protected void spinAnalyzer(ThreadMonitorInfo info) - { - info.setSpinning(true); - - if (_detectPeriod > 0 && _detectInterval > 0) - { - long threadId = info.getThreadId(); - long sampleTime = info.getSampleTime() / 1000000; - long endTime = System.currentTimeMillis() + _detectPeriod; - do - { - if (sampleTime + _detectInterval < System.currentTimeMillis()) - { - ThreadInfo threadInfo = getThreadInfo(threadId,Integer.MAX_VALUE); - if (threadInfo != null) - { - info.addStackTrace(threadInfo.getStackTrace()); - sampleTime = System.currentTimeMillis(); - } - } - - } - while(System.currentTimeMillis() < endTime); - } - } - /* ------------------------------------------------------------ */ protected void logCpuUsage() { @@ -471,47 +352,17 @@ public class ThreadMonitor extends AbstractLifeCycle implements Runnable { if (_monitorInfo.size() > 0) { - String format = "Thread %1$s[id:%2$d,%3$s] is SPINNING"; - long[] all = getAllThreadIds(); for (int idx=0; idx stackTraces = info.getStackTraces(); - int size = stackTraces.size(); - for (int sti=1; sti 0) - { - for (int idx=0; idx=0 ) - { - StringBuilder builder = new StringBuilder(); - builder.append(String.format("Thread %s[id:%d,%s] is DEADLOCKED", - info.getThreadName(), info.getThreadId(), info.getThreadState())); - builder.append(String.format(" on %s owned by %s[id:%d]", - info.getLockName(), info.getLockOwnerName(), info.getLockOwnerId())); - StackTraceElement[] stackTrace = getThreadInfo(locked[idx],Integer.MAX_VALUE).getStackTrace(); - _logger.warn(new ThreadMonitorException(builder.toString(), stackTrace)); - } - } - } } } diff --git a/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitorInfo.java b/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitorInfo.java index 9f069235c5a..7782ba43a0c 100644 --- a/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitorInfo.java +++ b/jetty-monitor/src/main/java/org/eclipse/jetty/monitor/ThreadMonitorInfo.java @@ -14,9 +14,6 @@ package org.eclipse.jetty.monitor; -import java.lang.management.ThreadInfo; -import java.util.ArrayList; -import java.util.List; /* ------------------------------------------------------------ */ @@ -24,57 +21,26 @@ import java.util.List; */ public class ThreadMonitorInfo { - private long _threadId; - private String _threadName; - private String _threadState; + private Thread _thread; - private long _lockOwnerId; - private String _lockOwnerName; - private String _lockName; - - private List _stackTraces; + private StackTraceElement[] _stackTrace; + private boolean _threadSpinning; private long _prevCpuTime; private long _prevSampleTime; private long _currCpuTime; private long _currSampleTime; - private boolean _threadSpinning; - + /* ------------------------------------------------------------ */ /** * Instantiates a new thread monitor info. * * @param threadInfo the thread info */ - public ThreadMonitorInfo(ThreadInfo threadInfo) + public ThreadMonitorInfo(Thread thread) { - _stackTraces = new ArrayList(); - - setInfo(threadInfo); - } - - /* ------------------------------------------------------------ */ - /** - * Sets the thread info. - * - * @param threadInfo the new thread info - */ - public void setInfo(ThreadInfo threadInfo) - { - _threadId = threadInfo.getThreadId(); - _threadName = threadInfo.getThreadName(); - _threadState = threadInfo.isInNative() ? "IN_NATIVE" : - threadInfo.getThreadState().toString(); - - _lockOwnerId = threadInfo.getLockOwnerId(); - _lockOwnerName = threadInfo.getLockOwnerName(); - _lockName = threadInfo.getLockName(); - - _stackTraces.clear(); - addStackTrace(threadInfo.getStackTrace()); - - _threadSpinning = false; + _thread = thread; } /* ------------------------------------------------------------ */ @@ -83,7 +49,7 @@ public class ThreadMonitorInfo */ public long getThreadId() { - return _threadId; + return _thread.getId(); } /* ------------------------------------------------------------ */ @@ -94,7 +60,7 @@ public class ThreadMonitorInfo */ public String getThreadName() { - return _threadName; + return _thread.getName(); } /* ------------------------------------------------------------ */ @@ -105,52 +71,51 @@ public class ThreadMonitorInfo */ public String getThreadState() { - return _threadState; + return _thread.getState().toString(); } /* ------------------------------------------------------------ */ - /** Get the lockOwnerId. - * @return the lockOwnerId + /** + * Gets the stack trace. + * + * @return the stack trace */ - public long getLockOwnerId() - { - return _lockOwnerId; - } - - /* ------------------------------------------------------------ */ - /** Get the lockOwnerName. - * @return the lockOwnerName - */ - public String getLockOwnerName() - { - return _lockOwnerName; - } - - /* ------------------------------------------------------------ */ - /** Get the lockName. - * @return the lockName - */ - public String getLockName() - { - return _lockName; - } - - public List getStackTraces() - { - return _stackTraces; - } - public StackTraceElement[] getStackTrace() { - return _stackTraces.size() == 0 ? null : _stackTraces.get(0); + return _stackTrace; + } + + /* ------------------------------------------------------------ */ + /** + * Sets the stack trace. + * + * @param stackTrace the new stack trace + */ + public void setStackTrace(StackTraceElement[] stackTrace) + { + _stackTrace = stackTrace; } - public void addStackTrace(StackTraceElement[] stackTrace) + /* ------------------------------------------------------------ */ + /** + * Checks if is spinning. + * + * @return true, if is spinning + */ + public boolean isSpinning() { - if (stackTrace != null && stackTrace.length > 0) - { - _stackTraces.add(stackTrace); - } + return _threadSpinning; + } + + /* ------------------------------------------------------------ */ + /** + * Sets the spinning flag. + * + * @param value the new value + */ + public void setSpinning(boolean value) + { + _threadSpinning = value; } /* ------------------------------------------------------------ */ @@ -208,16 +173,4 @@ public class ThreadMonitorInfo return elapsedNanoTime > 0 ? Math.min((elapsedCpuTime * 100.0f) / elapsedNanoTime, 100.0f) : 0; } - - /* ------------------------------------------------------------ */ - public void setSpinning(boolean value) - { - _threadSpinning = value; - } - - /* ------------------------------------------------------------ */ - public boolean isSpinning() - { - return _threadSpinning; - } } diff --git a/jetty-monitor/src/test/java/org/eclipse/jetty/monitor/ThreadMonitorTest.java b/jetty-monitor/src/test/java/org/eclipse/jetty/monitor/ThreadMonitorTest.java index 4ecaf710798..d715c84b3a5 100644 --- a/jetty-monitor/src/test/java/org/eclipse/jetty/monitor/ThreadMonitorTest.java +++ b/jetty-monitor/src/test/java/org/eclipse/jetty/monitor/ThreadMonitorTest.java @@ -31,18 +31,11 @@ public class ThreadMonitorTest @Test public void monitorTest() throws Exception { - final AtomicInteger countSpins=new AtomicInteger(0); final AtomicInteger countCpuLogs=new AtomicInteger(0); final AtomicInteger countStateLogs=new AtomicInteger(0); ThreadMonitor monitor = new ThreadMonitor(1000,50,1) { - @Override - protected void spinAnalyzer(ThreadMonitorInfo info) - { - countSpins.incrementAndGet(); - super.spinAnalyzer(info); - } @Override protected void logCpuUsage() { @@ -57,30 +50,17 @@ public class ThreadMonitorTest } }; monitor.logCpuUsage(2000,1); - monitor.logSpinInfo(100,20); monitor.start(); Spinner spinner = new Spinner(); Thread runner = new Thread(spinner); runner.start(); - Locker locker1 = new Locker(); - Locker locker2 = new Locker(); - locker1.setLock(locker2); - locker2.setLock(locker1); - Thread runner1 = new Thread(locker1); - Thread runner2 = new Thread(locker2); - runner1.start(); - runner2.start(); - Thread.sleep(DURATION); spinner.setDone(); monitor.stop(); - runner1.interrupt(); - runner2.interrupt(); - assertTrue(countSpins.get() >= 1); assertTrue(countCpuLogs.get() >= 1); assertTrue(countStateLogs.get() >= 1); } @@ -119,33 +99,4 @@ public class ThreadMonitorTest System.err.println("Bingo!"); } } - - private class Locker implements Runnable - { - private Object _lock; - - public void setLock(Object lock) - { - _lock = lock; - } - - public void run() - { - try - { - lockOn(); - } - catch (InterruptedException ex) {} - } - - public synchronized void lockOn() throws InterruptedException - { - Thread.sleep(100); - - synchronized (_lock) - { - Thread.sleep(100); - } - } - } }