Java tutorial
/** * Copyright (C) 2012 JBoss Inc * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package org.jboss.dashboard.profiler; import org.jboss.dashboard.commons.misc.Chronometer; import org.jboss.dashboard.error.ErrorReport; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.log4j.Layout; import org.apache.log4j.spi.LoggingEvent; import java.io.PrintWriter; import java.io.StringWriter; import java.util.*; /** * A thread profile holds detailed information about the execution of a given thread. It holds informations * like: * <ul> * <li>The code trace tree with all the code block traces generated within the thread execution. * <li>The sequence of stack traces generated within the thread execution (only when the sampling/instrumentation mode is enabled). * <li>The collection of logs events generated within the thread execution * </ul> * All the information above it makes very easy to diagnose performance problems. */ public class ThreadProfile { /** Logger */ private static transient Log log = LogFactory.getLog(ThreadProfile.class.getName()); /** The identifier */ protected String id; /** The begin date */ protected Date beginDate; /** The end date */ protected Date endDate; /** The thread */ protected Thread thread; /** The root trace. It stores all the executions traces generated within this thread. */ protected CodeBlockTrace rootCodeBlock; /** The current block in execution */ protected CodeBlockTrace codeBlockInProgress; /** Stack trace samples captured by the profiler. */ protected List<StackTrace> stackTraces; /** Maximum thread length allowed. */ protected long maxThreadDurationInMillis; /** Maximum stack trace length allowed. */ protected int maxStackTraceLength; /** Flag indicating that the thread elapsed time has overtaken a specified threshold (See the <code>maxThreadDurationInMillis</code> property). */ protected boolean elapsedTimeExceeded; /** Flag indicating that a too large stack trace (defined by the <code>maxStackTraceLength</code> property) has been produced by this thread. */ protected boolean stackTraceTooLarge; /** Number of large stack traces captured fot this thread */ protected int largeStackTracesCount; /** Context properties collected during profiling. */ protected Map<String, Object> contextProperties; /** All context property names that any thread profile can hold. */ protected static List<String> contextPropertyNames = new ArrayList<String>(); /** The thread's logs */ protected List<LogEvent> logEvents; /** The maximum log events to store. */ protected int maxLogEvents; /** The log overflow flag. Enabled when the log size exceeds the max. events allowed. */ protected transient boolean logOverflow; /** An error occurred during the thread execution (if any). */ protected ErrorReport errorReport; /** Force this thread to be kept by the profiler within the list of target threads. */ protected boolean targetThread; // Core property names public static final String THREAD_ID = "Thread id"; public static final String THREAD_BEGIN_DATE = "Thread begin date"; public static final String THREAD_GROUP = "Thread group"; public static final String USER_LOGIN = "User login"; public static final String USER_NAME = "User name"; // Final states public static final String STATE_ERROR = "ERROR"; public static final String STATE_COMPLETED = "COMPLETED"; public ThreadProfile() { this.stackTraces = new ArrayList<StackTrace>(); this.maxThreadDurationInMillis = 120000; this.maxStackTraceLength = 500; this.contextProperties = Collections.synchronizedMap(new LinkedHashMap<String, Object>()); this.logEvents = null; this.maxLogEvents = 10000; this.logOverflow = false; this.errorReport = null; this.targetThread = false; clearStackTraces(); } // Accessors public String getId() { return id; } public void setId(String id) { this.id = id; } public Date getBeginDate() { return beginDate; } public Date getEndDate() { return endDate; } public long getElapsedTime() { long endTime = (endDate != null ? endDate.getTime() : System.currentTimeMillis()); return endTime - beginDate.getTime(); } public Thread getThread() { return thread; } public boolean isRunning() { return thread != null; } public long getMaxThreadDurationInMillis() { return maxThreadDurationInMillis; } public void setMaxThreadDurationInMillis(long maxThreadDurationInMillis) { this.maxThreadDurationInMillis = maxThreadDurationInMillis; } public int getMaxStackTraceLength() { return maxStackTraceLength; } public void setMaxStackTraceLength(int maxStackTraceLength) { this.maxStackTraceLength = maxStackTraceLength; } public boolean isElapsedTimeExceeded() { return elapsedTimeExceeded; } public boolean isStackTraceTooLarge() { return stackTraceTooLarge; } public CodeBlockTrace getCodeBlockInProgress() { return codeBlockInProgress; } public CodeBlockTrace getRootCodeBlock() { return rootCodeBlock; } public int getMaxLogEvents() { return maxLogEvents; } public void setMaxLogEvents(int maxLogEvents) { this.maxLogEvents = maxLogEvents; } public ErrorReport getErrorReport() { return errorReport; } public void setErrorReport(ErrorReport errorReport) { this.errorReport = errorReport; if (errorReport != null) errorReport.setCodeBlock(codeBlockInProgress); } public String getState() { if (isRunning()) return thread.getState().toString(); if (errorReport != null) return STATE_ERROR; return STATE_COMPLETED; } // Context properties public void addContextProperty(String propName, Object propValue) { // Populate on demand the list of distinct property names. if (propName == null) return; if (!contextPropertyNames.contains(propName)) { contextPropertyNames.add(propName); } // Register the property value in the thread's context. contextProperties.put(propName, propValue); } public void addContextProperties(Map<String, Object> props) { for (String propName : props.keySet()) { if (propName == null) continue; addContextProperty(propName, props.get(propName)); } } public Object getContextProperty(String propName) { return contextProperties.get(propName); } public Set<String> getContextPropertyNames() { return contextProperties.keySet(); } public static List<String> getAllContextPropertyNames() { return Collections.unmodifiableList(contextPropertyNames); } public boolean isTargetThread() { return targetThread; } public void setTargetThread(boolean targetThread) { this.targetThread = targetThread; } // Lifecycle public void begin() { id = Thread.currentThread().getName(); thread = Thread.currentThread(); beginDate = new Date(); endDate = null; codeBlockInProgress = null; rootCodeBlock = new RootTrace(thread, beginDate); rootCodeBlock.begin(); } public void end() { endDate = new Date(); rootCodeBlock.end(); thread = null; } /** The very first trace added to the thread's execution just after its beginning. */ static class RootTrace extends CodeBlockTrace { protected String group; protected String state; protected Date beginDate; protected Map<String, Object> context; public RootTrace(Thread thread, Date beginDate) { super(thread.getName()); this.beginDate = beginDate; this.state = thread.getState().toString(); this.group = thread.getThreadGroup().getName(); this.context = buildContext(); } public CodeBlockType getType() { return CoreCodeBlockTypes.THREAD; } public String getDescription() { return id; } public Map<String, Object> getContext() { return context; } protected Map<String, Object> buildContext() { Map<String, Object> ctx = new LinkedHashMap<String, Object>(); ctx.put(THREAD_ID, id); ctx.put(THREAD_BEGIN_DATE, beginDate); ctx.put(THREAD_GROUP, group); ThreadProfile threadProfile = Profiler.lookup().getCurrentThreadProfile(); if (threadProfile != null) threadProfile.addContextProperties(ctx); return ctx; } } public static String printStackTrace(Thread t, int lines) { StringWriter sw = new StringWriter(); PrintWriter pw = new PrintWriter(sw); pw.println("'" + t.getName() + "' '" + t.getState().toString() + "' "); StackTraceElement[] trace = t.getStackTrace(); for (int i = 0; i < trace.length && i < lines; i++) { pw.println("\tat " + trace[i]); } return sw.toString(); } // Context handling public String printContext() { StringBuffer buf = new StringBuffer(); if (codeBlockInProgress != null) buf.append(codeBlockInProgress.printContext(true)); buf.append("\nElapsed time=").append(Chronometer.formatElapsedTime(getElapsedTime())); if (isRunning()) buf.append("\nCaller thread: ").append(printStackTrace(getThread(), 9999)); return buf.toString(); } // Profiling stuff public synchronized int getNumberOfSamples() { return stackTraces.size(); } public synchronized long getSampleAverageTimeMillis() { if (stackTraces.size() == 0) return 0; return getProfileTimeMillis() / stackTraces.size(); } public synchronized void clearStackTraces() { stackTraces.clear(); this.elapsedTimeExceeded = false; this.stackTraceTooLarge = false; this.largeStackTracesCount = 0; } public synchronized void dumpStackTrace() { if (elapsedTimeExceeded || stackTraceTooLarge) { return; } StackTrace st = new StackTrace(thread.getStackTrace(), codeBlockInProgress); stackTraces.add(st); // Do not accept more stack traces if the transaction is already too long. if (getProfileTimeMillis() > maxThreadDurationInMillis) { elapsedTimeExceeded = true; } // If the last five added stack traces are too large then stop recollecting traces. if (st.length() > maxStackTraceLength) { largeStackTracesCount++; stackTraceTooLarge = largeStackTracesCount > 5; } else { largeStackTracesCount = 0; } } public synchronized long getProfileTimeMillis() { if (stackTraces.isEmpty() || stackTraces.size() == 1) return 0; StackTrace first = stackTraces.get(0); StackTrace last = stackTraces.get(stackTraces.size() - 1); return last.getCreationTimeMillis() - first.getCreationTimeMillis(); } /** * Calculates the list of time traces. * Each time trace represents a method call and contains the estimated time spent by the thread in the execution of such method. */ public synchronized List<TimeTrace> calculateTimeTraces() { // Consider all samples and start at level 0. List<TimeTrace> traces = calculateTimeTraces(0, stackTraces.size(), 0); if (traces == null) return null; // Get a plain list of time traces ordered by its begin time. List<TimeTrace> timeTraces = new ArrayList<TimeTrace>(); toPlainList(traces, timeTraces); // Get a plain list of code traces ordered by its begin time. CodeBlockTraces codeTraces = rootCodeBlock.toPlainList(); // Populate the time traces with code block traces. for (int codeIndex = 0; codeIndex < codeTraces.size(); codeIndex++) { CodeBlockTrace codeTrace = codeTraces.get(codeIndex); boolean added = false; for (int traceIndex = timeTraces.size() - 1; traceIndex >= 0 && !added; traceIndex--) { TimeTrace timeTrace = timeTraces.get(traceIndex); if (codeTrace.getBeginTimeMillis() >= timeTrace.getBeginTimeMillis() && codeTrace.getEndTimeMillis() <= timeTrace.getEndTimeMillis()) { timeTrace.getCodeBlockTraces().add(codeTrace); added = true; } } if (!added && log.isDebugEnabled()) { log.debug("Time trace not found for code block.\n" + codeTrace.toString()); } } // Return the time traces each one containing its code block traces. return traces; } /** * Search for two consecutive stack traces in the specified sample interval & stack level. */ protected List<TimeTrace> calculateTimeTraces(int sampleStart, int sampleEnd, int stackLevel) { if (stackTraces == null || stackTraces.size() < 2) return null; // Look for samples List<TimeTrace> results = new ArrayList<TimeTrace>(); int newTraceStart = -1; for (int i = sampleStart + 1; i < sampleEnd; i++) { StackTrace previous = stackTraces.get(i - 1); StackTrace current = stackTraces.get(i); StackTraceElement prevEl = previous.get(stackLevel); StackTraceElement currEl = current.get(stackLevel); // Mark the beginning of a new stack trace. if (prevEl != null && prevEl.equals(currEl)) { if (newTraceStart == -1) { newTraceStart = i - 1; } } // New trace found. else if (newTraceStart != -1) { TimeTrace newStackTrace = createTimeTrace(newTraceStart, i, stackLevel); results.add(newStackTrace); newTraceStart = -1; } } // New trace found. if (newTraceStart != -1) { TimeTrace newStackTrace = createTimeTrace(newTraceStart, sampleEnd, stackLevel); results.add(newStackTrace); } return results; } /** * Create a time trace with samples belonging to the specified interval. */ protected TimeTrace createTimeTrace(int traceStart, int traceEnd, int stackLevel) { // Determine the stack length. int stackLength = stackLevel + 1; boolean stop = false; while (!stop) { StackTrace first = stackTraces.get(traceStart); StackTraceElement firstEl = first.get(stackLength); for (int i = traceStart + 1; i < traceEnd && !stop; i++) { StackTrace current = stackTraces.get(i); StackTraceElement currEl = current.get(stackLength); if (firstEl == null || !firstEl.equals(currEl)) { stop = true; } } if (!stop) { stackLength++; } } // Create the stack trace. StackTraceElement[] trace = stackTraces.get(traceStart).from(0, stackLength); List<StackTrace> samples = new ArrayList(stackTraces.subList(traceStart, traceEnd)); List<TimeTrace> children = calculateTimeTraces(traceStart, traceEnd, stackLength); return new TimeTrace(trace, samples, children, null); } protected void toPlainList(List<TimeTrace> traces, List<TimeTrace> results) { if (traces.isEmpty()) return; results.addAll(traces); for (TimeTrace trace : traces) { toPlainList(trace.getChildren(), results); } } // Log4J support public void addLog4JEvent(LoggingEvent event) { addLogEvent(new Log4JEvent(codeBlockInProgress, event)); } public void addCodeBlockBeginEvent(CodeBlockTrace trace) { addLogEvent(new CodeBlockBeginEvent(trace)); } public void addCodeBlockEndEvent(CodeBlockTrace trace) { addLogEvent(new CodeBlockEndEvent(trace)); } public void addLogEvent(LogEvent event) { if (logEvents == null) logEvents = new ArrayList<LogEvent>(); logEvents.add(event); // Avoid memory problems. if (logOverflow) logEvents.remove(1); else if (logOverflow = logEvents.size() > maxLogEvents) logEvents.add(0, createLogOverflowMessage()); } protected MessageEvent createLogOverflowMessage() { return new MessageEvent(codeBlockInProgress, "\n! AVOID MEMORY OVERFLOW. ONLY THE LOW " + maxLogEvents + " EVENTS RECORDED !\n"); } public List<LogEvent> getLogEvents(boolean includeCodeBlockEvents, boolean removeCodeBlocksWithoutLogs) { if (logEvents == null) return Collections.EMPTY_LIST; List<LogEvent> result = new ArrayList<LogEvent>(logEvents); if (!includeCodeBlockEvents) { // Return only Log4J events. Iterator<LogEvent> it = result.iterator(); while (it.hasNext()) { LogEvent event = it.next(); if (!(event instanceof Log4JEvent)) it.remove(); } } else if (removeCodeBlocksWithoutLogs) { // Return all events but those code block begin/end events containing no logs. int index = 0; while (index < result.size()) { // Look for two consecutive trace begin/end events (no log events between). if (!(result.get(index++) instanceof CodeBlockBeginEvent)) continue; if (index >= result.size()) continue; if (!(result.get(index) instanceof CodeBlockEndEvent)) continue; // Remove such begin/end events. result.remove(index--); result.remove(index--); if (index < 0) index = 0; } } else { // Return all the events. return Collections.unmodifiableList(logEvents); } return result; } /** * Base class for log events. */ public static abstract class LogEvent { CodeBlockTrace codeBlockTrace; long timestamp; protected LogEvent(CodeBlockTrace trace, long timestamp) { this.codeBlockTrace = trace; this.timestamp = timestamp; } public CodeBlockTrace getCodeBlockTrace() { return codeBlockTrace; } public long getTimestamp() { return timestamp; } public abstract String format(Map<String, Object> props); } /** * The CodeBlockTrace begin event. */ public static class CodeBlockBeginEvent extends LogEvent { public CodeBlockBeginEvent(CodeBlockTrace trace) { super(trace, trace.getBeginTimeMillis()); } public String format(Map<String, Object> props) { String traceTime = Chronometer.formatElapsedTime(codeBlockTrace.getElapsedTimeMillis()); String traceStr = codeBlockTrace.getType().getId() + " - " + codeBlockTrace.getDescription() + " - " + traceTime + "\n"; return "BEGIN " + traceStr; } } /** * The CodeBlockTrace end event. */ public static class CodeBlockEndEvent extends LogEvent { public CodeBlockEndEvent(CodeBlockTrace trace) { super(trace, trace.getEndTimeMillis()); } public String format(Map<String, Object> props) { String traceTime = Chronometer.formatElapsedTime(codeBlockTrace.getElapsedTimeMillis()); String traceStr = codeBlockTrace.getType().getId() + " - " + codeBlockTrace.getDescription() + " - " + traceTime + "\n"; return "END " + traceStr; } } /** * Class that holds events generated by the Log4j. */ public static class Log4JEvent extends LogEvent { public static final String LAYOUT = "layout"; LoggingEvent log4jEvent; private Log4JEvent(CodeBlockTrace codeBlockTrace, LoggingEvent log4jEvent) { super(codeBlockTrace, log4jEvent.getTimeStamp()); this.log4jEvent = log4jEvent; } public String format(Map<String, Object> props) { Layout layout = (Layout) props.get(LAYOUT); return layout.format(log4jEvent); } } /** * A simple event holding a message. */ public static class MessageEvent extends LogEvent { protected String message; private MessageEvent(CodeBlockTrace codeBlockTrace, String message) { super(codeBlockTrace, System.currentTimeMillis()); this.message = message; } public String format(Map<String, Object> props) { return message; } } }