diff options
Diffstat (limited to 'examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/TimedEventWatchdog.java')
| -rw-r--r-- | examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/TimedEventWatchdog.java | 351 |
1 files changed, 351 insertions, 0 deletions
diff --git a/examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/TimedEventWatchdog.java b/examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/TimedEventWatchdog.java new file mode 100644 index 0000000000..c09ea6babe --- /dev/null +++ b/examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/TimedEventWatchdog.java @@ -0,0 +1,351 @@ +/******************************************************************************* + * 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); + } + } + } +} |