/**
* Update the information about completed thread that ran for runtime in milliseconds
*
* <p>This method updates all of the key timing and tracking information in the factory so that
* thread can be retired. After this call the factory shouldn't have a pointer to the thread any
* longer
*
* @param thread the thread whose information we are updating
*/
@Ensures({"getTotalTime() >= old(getTotalTime())"})
public synchronized void threadIsDone(final Thread thread) {
nThreadsAnalyzed++;
if (DEBUG) logger.warn("UpdateThreadInfo called");
final long threadID = thread.getId();
final ThreadInfo info = bean.getThreadInfo(thread.getId());
final long totalTimeNano = bean.getThreadCpuTime(threadID);
final long userTimeNano = bean.getThreadUserTime(threadID);
final long systemTimeNano = totalTimeNano - userTimeNano;
final long userTimeInMilliseconds = nanoToMilli(userTimeNano);
final long systemTimeInMilliseconds = nanoToMilli(systemTimeNano);
if (info != null) {
if (DEBUG)
logger.warn(
"Updating thread with user runtime "
+ userTimeInMilliseconds
+ " and system runtime "
+ systemTimeInMilliseconds
+ " of which blocked "
+ info.getBlockedTime()
+ " and waiting "
+ info.getWaitedTime());
incTimes(State.BLOCKING, info.getBlockedTime());
incTimes(State.WAITING, info.getWaitedTime());
incTimes(State.USER_CPU, userTimeInMilliseconds);
incTimes(State.WAITING_FOR_IO, systemTimeInMilliseconds);
}
}
/**
* Print all of the thread's information and stack traces.
*
* @param sb
* @param info
* @param indent
*/
public static void appendThreadInfo(StringBuilder sb, ThreadInfo info, String indent) {
boolean contention = threadBean.isThreadContentionMonitoringEnabled();
if (info == null) {
sb.append(indent).append("Inactive (perhaps exited while monitoring was done)\n");
return;
}
String taskName = getTaskName(info.getThreadId(), info.getThreadName());
sb.append(indent).append("Thread ").append(taskName).append(":\n");
Thread.State state = info.getThreadState();
sb.append(indent).append(" State: ").append(state).append("\n");
sb.append(indent).append(" Blocked count: ").append(info.getBlockedCount()).append("\n");
sb.append(indent).append(" Waited count: ").append(info.getWaitedCount()).append("\n");
if (contention) {
sb.append(indent).append(" Blocked time: " + info.getBlockedTime()).append("\n");
sb.append(indent).append(" Waited time: " + info.getWaitedTime()).append("\n");
}
if (state == Thread.State.WAITING) {
sb.append(indent).append(" Waiting on ").append(info.getLockName()).append("\n");
} else if (state == Thread.State.BLOCKED) {
sb.append(indent).append(" Blocked on ").append(info.getLockName()).append("\n");
sb.append(indent)
.append(" Blocked by ")
.append(getTaskName(info.getLockOwnerId(), info.getLockOwnerName()))
.append("\n");
}
sb.append(indent).append(" Stack:").append("\n");
for (StackTraceElement frame : info.getStackTrace()) {
sb.append(indent).append(" ").append(frame.toString()).append("\n");
}
}
MyThreadInfo(long cpuTime, ThreadInfo info) {
blockedCount = info.getBlockedCount();
blockedTime = info.getBlockedTime();
waitedCount = info.getWaitedCount();
waitedTime = info.getWaitedTime();
this.cpuTime = cpuTime;
this.info = info;
}
/**
* Update the information about completed thread that ran for runtime in milliseconds
*
* <p>This method updates all of the key timing and tracking information in the factory so that
* thread can be retired. After this call the factory shouldn't have a pointer to the thread any
* longer
*
* @param thread
* @param runtimeInMilliseconds
*/
@Ensures({
"activeThreads.size() < old(activeThreads.size())",
"! activeThreads.contains(thread)",
"getTotalTime() >= old(getTotalTime())",
"countDownLatch.getCount() < old(countDownLatch.getCount())"
})
private synchronized void threadIsDone(final Thread thread, final long runtimeInMilliseconds) {
if (DEBUG)
logger.warn(
" Countdown "
+ countDownLatch.getCount()
+ " in thread "
+ Thread.currentThread().getName());
if (DEBUG) logger.warn("UpdateThreadInfo called");
final ThreadInfo info = bean.getThreadInfo(thread.getId());
if (info != null) {
if (DEBUG)
logger.warn(
"Updating thread total runtime "
+ runtimeInMilliseconds
+ " of which blocked "
+ info.getBlockedTime()
+ " and waiting "
+ info.getWaitedTime());
incTimes(Thread.State.BLOCKED, info.getBlockedTime());
incTimes(Thread.State.WAITING, info.getWaitedTime());
incTimes(
Thread.State.RUNNABLE,
runtimeInMilliseconds - info.getWaitedTime() - info.getBlockedTime());
}
// remove the thread from the list of active activeThreads
if (!activeThreads.remove(thread))
throw new IllegalStateException("Thread " + thread + " not in list of active activeThreads");
// one less thread is live for those blocking on all activeThreads to be complete
countDownLatch.countDown();
if (DEBUG)
logger.warn(
" -> Countdown "
+ countDownLatch.getCount()
+ " in thread "
+ Thread.currentThread().getName());
}
void setDelta(long cpuTime, ThreadInfo info) {
if (deltaDone) throw new IllegalStateException("setDelta already called once");
blockedCount = info.getBlockedCount() - blockedCount;
blockedTime = info.getBlockedTime() - blockedTime;
waitedCount = info.getWaitedCount() - waitedCount;
waitedTime = info.getWaitedTime() - waitedTime;
this.cpuTime = cpuTime - this.cpuTime;
deltaDone = true;
this.info = info;
}
/**
* {@inheritDoc}
*
* @see com.wily.introscope.agent.trace.ITracer#ITracer_startTrace(int,
* com.wily.introscope.agent.trace.InvocationData)
*/
@Override
public void ITracer_startTrace(int tracerIndex, InvocationData data) {
final int currentIndex = reentrancyIndex.get().incrementAndGet();
final ThreadInfo ti = TMX.getThreadInfo(Thread.currentThread().getId());
waitCountBaselines.get().put(currentIndex, ti.getWaitedCount());
blockCountBaselines.get().put(currentIndex, ti.getBlockedCount());
if (timesEnabled) {
waitTimeBaselines.get().put(currentIndex, ti.getWaitedTime());
blockTimeBaselines.get().put(currentIndex, ti.getBlockedTime());
}
}
public static CharSequence getThreadStats(
boolean lockedMonitors, boolean lockedSynchronizers, boolean stackTrace) {
StringBuilder list = new StringBuilder();
int threadCount = threadMXbean.getThreadCount();
int daemonCount = threadMXbean.getThreadCount();
int nonDaemonCount = threadCount - daemonCount;
int peakCount = threadMXbean.getPeakThreadCount();
long totalCount = threadMXbean.getTotalStartedThreadCount();
list.append("Live: .................... ").append(threadCount).append(" threads").append("\n");
list.append(" Non-Daemon: ......... ")
.append(nonDaemonCount)
.append(" threads")
.append("\n");
list.append(" Daemon: ............. ").append(daemonCount).append(" threads").append("\n");
list.append("Peak: .................... ").append(peakCount).append(" threads").append("\n");
list.append("Total started: ........... ").append(totalCount).append(" threads").append("\n");
list.append("=================================================").append("\n");
for (ThreadInfo info : threadMXbean.dumpAllThreads(lockedMonitors, lockedSynchronizers)) {
list.append("Thread #")
.append(info.getThreadId())
.append(" (")
.append(info.getThreadName())
.append(")")
.append("\n");
list.append("=================================================\n");
list.append("\tgetThreadState: ...... ").append(info.getThreadState()).append("\n");
list.append("\tgetWaitedTime: ....... ").append(info.getWaitedTime()).append("\n");
list.append("\tgetBlockedTime: ...... ").append(info.getBlockedTime()).append("\n");
for (MonitorInfo monitorInfo : info.getLockedMonitors()) {
list.append("\tLocked monitor: ....... ").append(monitorInfo).append("\n");
list.append("\t\t[")
.append(monitorInfo.getLockedStackDepth())
.append(".]: at ")
.append(monitorInfo.getLockedStackFrame())
.append("\n");
}
for (LockInfo lockInfo : info.getLockedSynchronizers()) {
list.append("\tLocked synchronizer: ...").append(lockInfo).append("\n");
}
if (stackTrace) {
list.append("\tgetStackTace: ..........\n");
for (StackTraceElement trace : info.getStackTrace())
list.append("\t\tat ").append(trace).append("\n");
}
list.append("=================================================\n");
}
return list;
}
/**
* {@inheritDoc}
*
* @see com.wily.introscope.agent.trace.ITracer#ITracer_finishTrace(int,
* com.wily.introscope.agent.trace.InvocationData)
*/
@Override
public void ITracer_finishTrace(int tracerIndex, InvocationData data) {
final int currentIndex = reentrancyIndex.get().decrementAndGet();
try {
final int priorIndex = currentIndex + 1;
final ThreadInfo ti = TMX.getThreadInfo(Thread.currentThread().getId());
long newWaitCount = ti.getWaitedCount();
long newBlockCount = ti.getBlockedCount();
long priorWaitCount = waitCountBaselines.get().remove(priorIndex);
long priorBlockCount = blockCountBaselines.get().remove(priorIndex);
if (priorWaitCount != NO_ENTRY && !waitCountAcc.IDataAccumulator_isShutOff()) {
waitCountAcc.ILongAggregatingDataAccumulator_recordDataPoint(newWaitCount - priorWaitCount);
}
if (priorBlockCount != NO_ENTRY && !blockCountAcc.IDataAccumulator_isShutOff()) {
blockCountAcc.ILongAggregatingDataAccumulator_recordDataPoint(
newBlockCount - priorBlockCount);
}
if (timesEnabled) {
long newWaitTime = ti.getWaitedTime();
long newBlockTime = ti.getBlockedTime();
long priorWaitTime = waitTimeBaselines.get().remove(priorIndex);
long priorBlockTime = blockTimeBaselines.get().remove(priorIndex);
if (priorWaitTime != NO_ENTRY && !waitTimeAcc.IDataAccumulator_isShutOff()) {
waitTimeAcc.ILongAggregatingDataAccumulator_recordDataPoint(newWaitTime - priorWaitTime);
}
if (priorBlockTime != NO_ENTRY && !blockTimeAcc.IDataAccumulator_isShutOff()) {
blockTimeAcc.ILongAggregatingDataAccumulator_recordDataPoint(
newBlockTime - priorBlockTime);
}
}
} finally {
if (currentIndex < 1) {
waitCountBaselines.remove();
blockCountBaselines.remove();
if (timesEnabled) {
waitTimeBaselines.remove();
blockTimeBaselines.remove();
}
}
if (currentIndex < 0) {
log.warn("Reentrancy Index Underrun:", currentIndex);
reentrancyIndex.get().set(0);
}
}
}
/**
* Formats the thread dump header for one thread.
*
* @param ti the ThreadInfo describing the thread
* @return the formatted thread dump header
*/
private static String getThreadDumpHeader(ThreadInfo ti) {
StringBuilder sb = new StringBuilder("\"" + ti.getThreadName() + "\"");
sb.append(" Id=" + ti.getThreadId());
sb.append(" cpu=" + threadMXBean.getThreadCpuTime(ti.getThreadId()) + " ns");
sb.append(" usr="******" ns");
sb.append(" blocked " + ti.getBlockedCount() + " for " + ti.getBlockedTime() + " ms");
sb.append(" waited " + ti.getWaitedCount() + " for " + ti.getWaitedTime() + " ms");
if (ti.isSuspended()) {
sb.append(" (suspended)");
}
if (ti.isInNative()) {
sb.append(" (running in native)");
}
sb.append(CRLF);
sb.append(INDENT3 + "java.lang.Thread.State: " + ti.getThreadState());
sb.append(CRLF);
return sb.toString();
}
protected String generateThreadDump() {
StringBuilder dump = new StringBuilder();
ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
ThreadInfo[] threadInfos = threadMXBean.dumpAllThreads(true, true);
long currentThreadId = Thread.currentThread().getId();
for (ThreadInfo threadInfo : threadInfos) {
long threadId = threadInfo.getThreadId();
if (threadId == currentThreadId) {
continue;
}
dump.append('"');
dump.append(threadInfo.getThreadName());
dump.append("\" ");
Thread.State state = threadInfo.getThreadState();
dump.append("\n\tjava.lang.Thread.State: ");
dump.append(state);
if (threadInfo.getLockName() != null) {
dump.append(", on lock=").append(threadInfo.getLockName());
}
if (threadInfo.getLockOwnerName() != null) {
dump.append(", owned by ").append(threadInfo.getLockOwnerName());
dump.append(", id=").append(threadInfo.getLockOwnerId());
}
if (THREAD_CPU_TIME_INFO_AVAILABLE) {
dump.append(", cpu=").append(threadMXBean.getThreadCpuTime(threadId)).append(" nsecs");
dump.append(", usr="******" nsecs");
}
if (THREAD_CONTENTION_INFO_AVAILABLE) {
dump.append(", blocked=").append(threadInfo.getBlockedTime()).append(" msecs");
dump.append(", waited=").append(threadInfo.getWaitedTime()).append(" msecs");
}
StackTraceElement[] stackTraceElements = threadInfo.getStackTrace();
for (StackTraceElement stackTraceElement : stackTraceElements) {
dump.append("\n\t\tat ");
dump.append(stackTraceElement);
}
dump.append("\n\n");
}
return dump.toString();
}
/**
* Return current (raw) list of thread info objects wrapped in ThreadRankInfo type.
*
* @return list of threads
*/
protected List<ThreadRankInfo> rawList() {
// Platform MBean Server startup might be suspended (eg. for JBoss AS);
if (threadMXBean == null) {
if (mBeanServerRegistry.lookup("java") != null) {
threadMXBean = ManagementFactory.getThreadMXBean();
} else {
return new ArrayList<ThreadRankInfo>(1);
}
}
ThreadInfo[] ati = threadMXBean.getThreadInfo(threadMXBean.getAllThreadIds());
List<ThreadRankInfo> lst = new ArrayList<ThreadRankInfo>(ati.length);
for (ThreadInfo ti : ati) {
long tid = ti.getThreadId();
long cpuTime = threadMXBean.getThreadCpuTime(tid);
lst.add(new ThreadRankInfo(tid, ti.getThreadName(), cpuTime, ti.getBlockedTime()));
}
return lst;
}
private void printThread() {
long now = System.currentTimeMillis();
long diffLastThreadDump = now - lastThreadDump;
logger.info("diffLastThreadDump:" + diffLastThreadDump);
if (diffLastThreadDump > 60000) {
logger.info("had not sent all threads for a while.. will do so now");
lastThreadDump = now;
try {
ThreadMXBean t = ManagementFactory.getThreadMXBean();
long threads[] = t.getAllThreadIds();
ThreadInfo[] tinfo = t.getThreadInfo(threads, 40);
StringBuilder sb = new StringBuilder("All Threads");
for (int i = 0; i < tinfo.length; i++) {
ThreadInfo e = tinfo[i];
try {
StackTraceElement[] el = e.getStackTrace();
sb.append(
"\n\n"
+ e.getThreadName()
+ "\n"
+ " "
+ " Thread id = "
+ e.getThreadId()
+ " "
+ e.getThreadState());
if (e.getThreadState().equals(State.BLOCKED)) {
sb.append(
"\n\nBlocked info: "
+ e.getBlockedCount()
+ ":"
+ e.getBlockedTime()
+ ":"
+ e.getLockName()
+ ":"
+ e.getLockOwnerId()
+ ":"
+ e.getLockOwnerName()
+ "\n"
+ " "
+ " Thread id = "
+ e.getThreadId()
+ " "
+ e.getThreadState());
ThreadInfo eBlockedThread = t.getThreadInfo(e.getLockOwnerId(), 40);
StackTraceElement[] elBlockedThread = eBlockedThread.getStackTrace();
sb.append(
"\n\n "
+ e.getThreadName()
+ "\n"
+ " "
+ " Thread id = "
+ eBlockedThread.getThreadId()
+ " "
+ eBlockedThread.getThreadState());
if (elBlockedThread == null || elBlockedThread.length == 0) {
sb.append(" no stack trace available");
} else {
for (int n = 0; n < elBlockedThread.length; n++) {
if (n != 0) sb.append("\n");
StackTraceElement frame = elBlockedThread[n];
if (frame == null) {
sb.append(" null stack frame");
continue;
}
sb.append(" ");
sb.append(frame.toString());
}
}
}
if (el == null || el.length == 0) {
sb.append(" no stack trace available");
continue;
}
for (int n = 0; n < el.length; n++) {
if (n != 0) sb.append("\n");
StackTraceElement frame = el[n];
if (frame == null) {
sb.append(" null stack frame");
continue;
}
sb.append(" ");
sb.append(frame.toString());
}
} catch (Exception e2) {
}
}
String warningEmailReceiver = CmsPropertyHandler.getWarningEmailReceiver();
if (warningEmailReceiver != null
&& !warningEmailReceiver.equals("")
&& warningEmailReceiver.indexOf("@warningEmailReceiver@") == -1) {
try {
logger.info("Mailing..");
MailServiceFactory.getService()
.sendEmail(
CmsPropertyHandler.getMailContentType(),
warningEmailReceiver,
warningEmailReceiver,
null,
null,
null,
null,
message,
sb.toString().replaceAll("\n", "<br/>"),
"utf-8");
} catch (Exception e) {
logger.error("Could not send mail:" + e.getMessage(), e);
}
}
} catch (Throwable e) {
logger.error("Error generating message:" + e.getMessage(), e);
}
}
// Only sends if the last stack was sent more than 3 seconds ago.
if ((now - lastSentTimer) > 10000) {
lastSentTimer = System.currentTimeMillis();
StackTraceElement[] el = targetThread.getStackTrace();
ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
long stopTimeInNs = threadMXBean.getThreadUserTime(targetThread.getId());
long diff = (stopTimeInNs - startTimeInNs) / 1000000000;
StringBuffer stackString = new StringBuffer("\n\n" + message + "\n\n");
stackString.append("ServerName: " + getServerName() + "\n");
stackString.append("Maximum memory (MB): " + (maxMemory / 1024 / 1024) + "\n");
stackString.append("Used memory (MB): " + ((totalMemory - freeMemory) / 1024 / 1024) + "\n");
stackString.append("Free memory (MB): " + (freeMemory / 1024 / 1024) + "\n");
stackString.append("Total memory (MB): " + (totalMemory / 1024 / 1024) + "\n");
stackString.append("Number of current requests: " + numberOfCurrentRequests + "\n");
stackString.append("Number of active requests: " + numberOfActiveRequests + "\n");
stackString.append("Number of long requests: " + longThreadMonitorsSize + "\n");
stackString.append("Current thread time: " + diff + " seconds\n");
stackString.append(
"Average time: " + RequestAnalyser.getRequestAnalyser().getAverageElapsedTime() + "\n");
stackString.append(
"Longest time: " + RequestAnalyser.getRequestAnalyser().getMaxElapsedTime() + "\n");
stackString.append("Original url: " + getOriginalFullURL() + "\n");
stackString.append("UserInfo: " + getUserInfo() + "\n");
stackString.append("--------------------------------------------\n\n");
stackString.append("Thread with id [" + targetThread.getId() + "] at report time:\n");
if (el != null && el.length != 0) {
for (int j = 0; j < el.length; j++) {
StackTraceElement frame = el[j];
if (frame == null) stackString.append(" null stack frame" + "\n");
else stackString.append(" ").append(frame.toString()).append("\n");
// if((stackString.indexOf("infoglue") > -1 && j > 20) || j > 35)
// break;
}
}
if (targetThread.getState().equals(State.BLOCKED)) {
ThreadMXBean t = ManagementFactory.getThreadMXBean();
ThreadInfo e = t.getThreadInfo(targetThread.getId(), 40);
stackString.append(
"\n\nBlocked info: "
+ e.getBlockedCount()
+ ":"
+ e.getBlockedTime()
+ ":"
+ e.getLockName()
+ ":"
+ e.getLockOwnerId()
+ ":"
+ e.getLockOwnerName()
+ "\n"
+ " "
+ " Thread id = "
+ e.getThreadId()
+ " "
+ e.getThreadState());
ThreadInfo eBlockedThread = t.getThreadInfo(e.getLockOwnerId(), 40);
StackTraceElement[] elBlockedThread = eBlockedThread.getStackTrace();
stackString.append(
"\n\nBlocked thread: "
+ e.getThreadName()
+ "\n"
+ " "
+ " Thread id = "
+ eBlockedThread.getThreadId()
+ " "
+ eBlockedThread.getThreadState());
if (elBlockedThread == null || elBlockedThread.length == 0) {
stackString.append(" no stack trace available");
} else {
for (int n = 0; n < elBlockedThread.length; n++) {
if (n != 0) stackString.append("\n");
StackTraceElement frame = elBlockedThread[n];
if (frame == null) {
stackString.append(" null stack frame");
continue;
}
stackString.append(" ");
stackString.append(frame.toString());
}
}
}
stackString.append(
"\n\n**********************************\nConcurrent long threads (Only an excerpt of all)\n**********************************");
ThreadMXBean t = ManagementFactory.getThreadMXBean();
List threadMonitors = RequestAnalyser.getLongThreadMonitors();
Iterator threadMonitorsIterator = threadMonitors.iterator();
int threadCount = 0;
while (threadMonitorsIterator.hasNext() && threadCount < 5) {
SimpleThreadMonitor tm = (SimpleThreadMonitor) threadMonitorsIterator.next();
if (targetThread.getId() == tm.getThreadId()) continue;
long threads[] = {tm.getThreadId()};
ThreadInfo[] tinfo = t.getThreadInfo(threads, 40);
stackString
.append("\n\n---------------------------------\nConcurrent long thread [")
.append(tm.getThreadId())
.append("]:\n");
stackString
.append("Elapsed time:")
.append(tm.getElapsedTime())
.append("\n Thread id: ")
.append(tm.getThreadId())
.append("\n Original url: ")
.append(tm.getOriginalFullURL())
.append(")");
for (int i = 0; i < tinfo.length; i++) {
ThreadInfo e = tinfo[i];
el = e.getStackTrace();
if (el != null && el.length != 0) {
for (int n = 0; n < el.length; n++) {
StackTraceElement frame = el[n];
if (frame == null) stackString.append(" null stack frame\n");
else stackString.append(" null stack frame").append(frame.toString()).append("\n");
}
}
}
threadCount++;
}
logger.warn(stackString);
} else {
logger.warn(
"A thread took to long but the system seems to be really clogged so we don't send this one.");
}
}
