| /******************************************************************************* |
| * Copyright (c) 2013, Google Inc. and others. |
| * All rights reserved. This program and the accompanying materials |
| * are made available under the terms of the Eclipse Public License v1.0 |
| * which accompanies this distribution, and is available at |
| * http://www.eclipse.org/legal/epl-v10.html |
| * |
| * Contributors: |
| * Google Inc - initial API and implementation |
| *******************************************************************************/ |
| package org.eclipse.swt.examples.watchdog; |
| |
| import org.eclipse.core.runtime.IStatus; |
| import org.eclipse.core.runtime.Status; |
| import org.eclipse.swt.SWT; |
| import org.eclipse.swt.widgets.Display; |
| import org.eclipse.swt.widgets.Event; |
| import org.eclipse.swt.widgets.Listener; |
| import org.eclipse.swt.widgets.Synchronizer; |
| |
| import java.text.SimpleDateFormat; |
| import java.util.Date; |
| import java.util.Timer; |
| import java.util.TimerTask; |
| |
| /** |
| * This watchdog uses a {@link Timer} to take a stack trace during long events, trying to catch a |
| * single long-running event in action. |
| */ |
| class TimedEventWatchdog implements Listener { |
| /** |
| * Information captured about a set of events. |
| * <p> |
| * When a set contains more than 1 event, it means that additional events were processed |
| * recursively before the first event finished. If events are invoked recursively and any event |
| * is longer than a watchdog's threshold, each enclosing event will also be longer than the |
| * threshold and will be reported as the stack unwinds. |
| * |
| * @noextend This class is not intended to be subclassed by clients. |
| */ |
| private static class LongEventInfo { |
| /** |
| * The sequence number of the first event in this set |
| */ |
| public final int startingSequenceNumber; |
| |
| /** |
| * The sequence number of the last event in this set |
| */ |
| public final int endingSequenceNumber; |
| |
| /** |
| * The start time of the first event, in milliseconds since 00:00 of 1 January 1970 Z. |
| * @see System#currentTimeMillis |
| */ |
| public final long start; |
| |
| /** |
| * The total duration of all events, in milliseconds |
| */ |
| public final long duration; |
| |
| /** |
| * The recursive depth of calls to events when this LongEventInfo was created. |
| */ |
| public final int depth; |
| |
| /** |
| * The maximum recursive depth of calls to events during this set of events |
| */ |
| public final int maxDepth; |
| |
| /** |
| * Constructs an event snapshot object from a contiguous range of events. |
| * |
| * @param startSeqNo the first event in this snapshot |
| * @param endSeqNo the last event in this snapshot |
| * @param start the start timestamp in milliseconds since 00:00 of 1 Jan 1970 |
| * @param duration the duration of the captured events, in milliseconds |
| * @param depth the depth at which this snapshot started and ended |
| * @param maxDepth the maximum depth reached by any event captured by this snapshot |
| */ |
| public LongEventInfo(int startSeqNo, int endSeqNo, long start, long duration, int depth, |
| int maxDepth) { |
| this.startingSequenceNumber = startSeqNo; |
| this.endingSequenceNumber = endSeqNo; |
| this.start = start; |
| this.duration = duration; |
| this.depth = depth; |
| this.maxDepth = maxDepth; |
| } |
| } |
| |
| private static final class StackTrace { |
| public final Date captureTime; |
| public final StackTraceElement[] stack; |
| |
| public StackTrace(Thread thread, long time_ms) { |
| captureTime = new Date(time_ms); |
| stack = thread.getStackTrace(); |
| } |
| } |
| |
| private class StackNode { |
| public int startingSequenceNumber = -1; |
| public long startTime = -1; |
| } |
| |
| private static final SimpleDateFormat TIME_FORMAT = new SimpleDateFormat("HH:mm:ss.SSS"); |
| |
| private static final String EVENT_STR_FORMAT = |
| "Event #%1$d-#%2$d: %3$dms from %4$s [depth = %5$d, max = %6$d]"; |
| |
| private final long dataCollectionDelay; // in milliseconds |
| private final long threshold_ms; // in milliseconds |
| |
| private StackNode[] stack = new StackNode[16]; |
| |
| // Count of how many nested {@link Dispatch#readAndDisplay} calls are on the stack |
| private int recursiveDepth = 0; |
| |
| // Sequence numbers should always be >0 so the logged sequence numbers progress in an intuitive |
| // way and -1 can be used as a sentinel value |
| private int dispatchSequenceNumber = 1; |
| |
| private int maxRecursiveDepth = 0; |
| |
| private final Timer timer; |
| private final TimerTask onTickTask; |
| private final Thread uiThread; |
| |
| private volatile StackTrace stackTrace; |
| private volatile long grabStackAt; |
| |
| public TimedEventWatchdog(Thread uiThread, long threshold_ms) { |
| if (uiThread == null) { |
| throw new NullPointerException(); |
| } |
| |
| this.threshold_ms = threshold_ms; |
| this.dataCollectionDelay = threshold_ms / 2; |
| |
| this.uiThread = uiThread; |
| this.timer = new Timer("Monitoring data collection timer", true); |
| this.onTickTask = new TimerTask() { |
| @Override |
| public void run() { |
| poll(); |
| } |
| }; |
| |
| grabStackAt = Long.MAX_VALUE; |
| timer.scheduleAtFixedRate(onTickTask, 0, Math.max(dataCollectionDelay / 2, 1)); |
| } |
| |
| @Override |
| public void handleEvent(Event event) { |
| if (event.type == SWT.PreEvent) { |
| beginEvent(); |
| } else if (event.type == SWT.PostEvent) { |
| endEvent(); |
| } |
| } |
| |
| /** |
| * Called at the start of every event, just before invoking the event handler. This function is |
| * called on the UI thread very frequently and can have a significant impact on performance, so |
| * it should be as fast as possible. |
| */ |
| public void beginEvent() { |
| int depth = recursiveDepth++; |
| int seqNo = dispatchSequenceNumber; |
| seqNo = (seqNo < Integer.MAX_VALUE ? seqNo + 1 : 1); |
| dispatchSequenceNumber = seqNo; |
| |
| if (depth > maxRecursiveDepth) { |
| maxRecursiveDepth = depth; |
| } |
| |
| StackNode s; |
| if (depth < stack.length) { |
| s = stack[depth]; |
| } else { |
| s = null; |
| StackNode[] newStack = new StackNode[2 * depth]; |
| System.arraycopy(stack, 0, newStack, 0, stack.length); |
| stack = newStack; |
| } |
| |
| if (s == null) { |
| stack[depth] = s = new StackNode(); |
| } |
| |
| s.startTime = getTimestamp(); |
| s.startingSequenceNumber = seqNo; |
| |
| // This function gets called very often, so it needs to be fast! |
| stackTrace = null; |
| grabStackAt = System.currentTimeMillis() + dataCollectionDelay; // Linearization point |
| } |
| |
| /** |
| * Called at the end of every event, after that event has returned. This function is called on |
| * the UI thread very frequently and can have a significant impact on performance, so it |
| * should be as fast as possible. |
| */ |
| public void endEvent() { |
| if (recursiveDepth == 0) return; |
| int depth = --recursiveDepth; |
| |
| // If a subscriber is added during an asyncExec event (the typical way to subscribe), |
| // then we don't have any start information collected and stack[depth] will still be |
| // null, so skip reporting that event. |
| StackNode s = depth < stack.length ? stack[depth] : null; |
| if (s != null) { |
| int duration = (int) (getTimestamp() - s.startTime); |
| LongEventInfo info = null; |
| |
| if (duration >= threshold_ms) { |
| if (info == null) { |
| info = new LongEventInfo(s.startingSequenceNumber, |
| dispatchSequenceNumber, s.startTime, duration, depth, |
| maxRecursiveDepth); |
| } |
| |
| onLongEvent(info); |
| } |
| } |
| |
| if (depth == 0) { |
| maxRecursiveDepth = 0; |
| } |
| |
| // This function gets called very often, so it needs to be fast! |
| grabStackAt = Long.MAX_VALUE; // Linearization point |
| } |
| |
| private long getTimestamp() { |
| return System.currentTimeMillis(); |
| } |
| |
| /** |
| * If the duration of any single event was longer than a client's duration threshold, this |
| * callback is invoked after the event completes and before {@link #endEvent}. If the event |
| * completed faster than the threshold, this callback is not invoked. |
| * <p> |
| * When an event at depth > 0 is longer than a client's threshold, the enclosing event will |
| * also be longer and will be reported separately as the call stack unwinds. |
| * <p> |
| * This example simply logs stack traces for off-line analysis. |
| * <p> |
| * Example output: |
| * <pre> |
| * !ENTRY org.eclipse.swt.examples.watchdog 1 0 2013-05-20 11:43:59.253 |
| * !MESSAGE Event #217-#217: 250ms from 11:43:59.002 [depth = 1, max = 1] |
| * Trace 11:43:59.150 (+148.0ms) |
| * org.eclipse.swt.examples.watchdog.WatchdogPlugin.longExample(WatchdogPlugin.java:68) |
| * org.eclipse.swt.examples.watchdog.WatchdogPlugin$1.run(WatchdogPlugin.java:62) |
| * org.eclipse.swt.widgets.Synchronizer.instrumentedRun(Synchronizer.java:247) |
| * org.eclipse.swt.widgets.Synchronizer.syncExec(Synchronizer.java:223) |
| * org.eclipse.ui.internal.UISynchronizer.syncExec(UISynchronizer.java:150) |
| * org.eclipse.swt.widgets.Display.syncExec(Display.java:4491) |
| * org.eclipse.swt.examples.watchdog.WatchdogPlugin$2.run(WatchdogPlugin.java:78) |
| * ... 27 more |
| * </pre> |
| * @param event captured information about the long event |
| */ |
| public void onLongEvent(LongEventInfo event) { |
| grabStackAt = Long.MAX_VALUE; // Linearization point |
| StackTrace trace = stackTrace; |
| stackTrace = null; |
| |
| if (trace != null) { |
| String msg = String.format(EVENT_STR_FORMAT, event.startingSequenceNumber, |
| event.endingSequenceNumber, event.duration, |
| TIME_FORMAT.format(new Date(event.start)), event.depth, event.maxDepth); |
| |
| StringBuilder str = new StringBuilder(msg); |
| |
| str.append('\n'); |
| str.append('\t').append("Trace ").append(TIME_FORMAT.format(trace.captureTime)); |
| |
| // Calculate when the stack trace happened relative to the start of the dispatch. |
| double deltaTimeFromEventStart = trace.captureTime.getTime() - event.start; |
| String unit = "ms"; |
| if (deltaTimeFromEventStart > 1000.0) { |
| deltaTimeFromEventStart /= 1000.0; |
| unit = "s"; |
| } |
| deltaTimeFromEventStart = Math.round(deltaTimeFromEventStart * 10.0) / 10.0; |
| str.append(" (+").append(deltaTimeFromEventStart).append(unit).append(')').append('\n'); |
| |
| final String displayClassName = Display.class.getName(); |
| final String syncClassName = Synchronizer.class.getName(); |
| |
| int numPrinted = 0; |
| int maxToPrint = -1; |
| for (StackTraceElement e : trace.stack) { |
| str.append('\t').append('\t').append(e.toString()).append('\n'); |
| ++numPrinted; |
| |
| // Limit number of stack elements printed to reasonable size |
| if (traceElementIs(e, displayClassName, "readAndDispatch")) { |
| maxToPrint = 0; |
| } else if (traceElementIs(e, displayClassName, "syncExec")) { |
| maxToPrint = 3; |
| } else if (traceElementIs(e, syncClassName, "syncExec")) { |
| maxToPrint = 3; |
| } |
| |
| if (maxToPrint == 0) { |
| str.append('\t').append('\t').append("... ") |
| .append(trace.stack.length - numPrinted).append(" more").append('\n'); |
| break; |
| } else if (maxToPrint > 0) { |
| maxToPrint--; |
| } |
| } |
| |
| WatchdogPlugin.getDefault().getLog().log(new Status(IStatus.INFO, |
| WatchdogPlugin.getDefault().getBundle().getSymbolicName(), str.toString())); |
| } |
| } |
| |
| private static boolean traceElementIs(StackTraceElement e, String className, String method) { |
| return className.equals(e.getClassName()) && method.equals(e.getMethodName()); |
| } |
| |
| /** |
| * The data-collection is kept very simple for this example to focus on how to use the API |
| * without adding too much multithreading complexity. |
| * <p> |
| * For additional data collection, you could collect multiple stack traces, then log some or |
| * all of them in {@link #onLongEvent}. The timer can also log if too much time elapses between |
| * {@link #beginEvent} and {@link #endEvent} to help diagnose UI freezes and potential |
| * deadlocks. |
| * <p> |
| * This example uses {@link Timer} for simplicity. Using Timer does introduce an upper-bound on |
| * how much data can be collected. More in-depth or precise collection may require replacing |
| * the {@link Timer}-based polling with a dedicated thread. |
| */ |
| private void poll() { |
| if (stackTrace == null) { |
| long currTime = System.currentTimeMillis(); |
| |
| if (currTime - grabStackAt > 0) { // Linearization point |
| stackTrace = new StackTrace(uiThread, currTime); |
| } |
| } |
| } |
| } |