Skip to main content
aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorforemans2013-08-12 13:20:15 -0400
committerGerrit Code Review @ Eclipse.org2013-09-10 17:40:38 -0400
commit2d3beee4f0d4b43249f8bdd6a151b724c5f0feae (patch)
tree3f974993b938cd2f8a1a62bbad1c65b2701d6e16 /examples/org.eclipse.swt.examples.watchdog
parente1ed2e305b572c142219fc5140ca7b70afdb4469 (diff)
downloadeclipse.platform.swt-2d3beee4f0d4b43249f8bdd6a151b724c5f0feae.tar.gz
eclipse.platform.swt-2d3beee4f0d4b43249f8bdd6a151b724c5f0feae.tar.xz
eclipse.platform.swt-2d3beee4f0d4b43249f8bdd6a151b724c5f0feae.zip
Review for Bug 360052 - New API for monitoring UI delays
New API for the SWT synchronizer to enable in-band monitoring of UI events. The instrumentation hooks are useful for collecting information related to UI responsiveness (freezes, sluggishness, stuttering, etc). Change-Id: I381ff82120c570e032a55bc7ad5585d9b4818dcc Signed-off-by: foremans <foremans@google.com>
Diffstat (limited to 'examples/org.eclipse.swt.examples.watchdog')
-rw-r--r--examples/org.eclipse.swt.examples.watchdog/.classpath7
-rw-r--r--examples/org.eclipse.swt.examples.watchdog/.project28
-rw-r--r--examples/org.eclipse.swt.examples.watchdog/META-INF/MANIFEST.MF11
-rw-r--r--examples/org.eclipse.swt.examples.watchdog/build.properties4
-rw-r--r--examples/org.eclipse.swt.examples.watchdog/plugin.xml7
-rw-r--r--examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/TimedEventWatchdog.java351
-rw-r--r--examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/WatchdogPlugin.java75
7 files changed, 483 insertions, 0 deletions
diff --git a/examples/org.eclipse.swt.examples.watchdog/.classpath b/examples/org.eclipse.swt.examples.watchdog/.classpath
new file mode 100644
index 0000000000..64c5e31b7a
--- /dev/null
+++ b/examples/org.eclipse.swt.examples.watchdog/.classpath
@@ -0,0 +1,7 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<classpath>
+ <classpathentry kind="con" path="org.eclipse.jdt.launching.JRE_CONTAINER/org.eclipse.jdt.internal.debug.ui.launcher.StandardVMType/J2SE-1.5"/>
+ <classpathentry kind="con" path="org.eclipse.pde.core.requiredPlugins"/>
+ <classpathentry kind="src" path="src"/>
+ <classpathentry kind="output" path="bin"/>
+</classpath>
diff --git a/examples/org.eclipse.swt.examples.watchdog/.project b/examples/org.eclipse.swt.examples.watchdog/.project
new file mode 100644
index 0000000000..00b90f38e5
--- /dev/null
+++ b/examples/org.eclipse.swt.examples.watchdog/.project
@@ -0,0 +1,28 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<projectDescription>
+ <name>org.eclipse.swt.examples.watchdog</name>
+ <comment></comment>
+ <projects>
+ </projects>
+ <buildSpec>
+ <buildCommand>
+ <name>org.eclipse.jdt.core.javabuilder</name>
+ <arguments>
+ </arguments>
+ </buildCommand>
+ <buildCommand>
+ <name>org.eclipse.pde.ManifestBuilder</name>
+ <arguments>
+ </arguments>
+ </buildCommand>
+ <buildCommand>
+ <name>org.eclipse.pde.SchemaBuilder</name>
+ <arguments>
+ </arguments>
+ </buildCommand>
+ </buildSpec>
+ <natures>
+ <nature>org.eclipse.pde.PluginNature</nature>
+ <nature>org.eclipse.jdt.core.javanature</nature>
+ </natures>
+</projectDescription>
diff --git a/examples/org.eclipse.swt.examples.watchdog/META-INF/MANIFEST.MF b/examples/org.eclipse.swt.examples.watchdog/META-INF/MANIFEST.MF
new file mode 100644
index 0000000000..48230ae2cd
--- /dev/null
+++ b/examples/org.eclipse.swt.examples.watchdog/META-INF/MANIFEST.MF
@@ -0,0 +1,11 @@
+Manifest-Version: 1.0
+Bundle-ManifestVersion: 2
+Bundle-Name: Event Watchdog
+Bundle-SymbolicName: org.eclipse.swt.examples.watchdog;singleton:=true
+Bundle-Version: 1.0.0.qualifier
+Bundle-Activator: org.eclipse.swt.examples.watchdog.WatchdogPlugin
+Bundle-RequiredExecutionEnvironment: J2SE-1.5
+Bundle-ActivationPolicy: lazy
+Require-Bundle: org.eclipse.core.runtime,
+ org.eclipse.swt,
+ org.eclipse.ui.workbench
diff --git a/examples/org.eclipse.swt.examples.watchdog/build.properties b/examples/org.eclipse.swt.examples.watchdog/build.properties
new file mode 100644
index 0000000000..34d2e4d2da
--- /dev/null
+++ b/examples/org.eclipse.swt.examples.watchdog/build.properties
@@ -0,0 +1,4 @@
+source.. = src/
+output.. = bin/
+bin.includes = META-INF/,\
+ .
diff --git a/examples/org.eclipse.swt.examples.watchdog/plugin.xml b/examples/org.eclipse.swt.examples.watchdog/plugin.xml
new file mode 100644
index 0000000000..e3281e757f
--- /dev/null
+++ b/examples/org.eclipse.swt.examples.watchdog/plugin.xml
@@ -0,0 +1,7 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<?eclipse version="3.4"?>
+<plugin>
+ <extension point="org.eclipse.ui.startup">
+ <startup class="org.eclipse.swt.examples.watchdog.WatchdogPlugin"/>
+ </extension>
+</plugin>
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);
+ }
+ }
+ }
+}
diff --git a/examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/WatchdogPlugin.java b/examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/WatchdogPlugin.java
new file mode 100644
index 0000000000..4712bab223
--- /dev/null
+++ b/examples/org.eclipse.swt.examples.watchdog/src/org/eclipse/swt/examples/watchdog/WatchdogPlugin.java
@@ -0,0 +1,75 @@
+/*******************************************************************************
+ * 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.swt.SWT;
+import org.eclipse.swt.widgets.Display;
+import org.eclipse.ui.IStartup;
+import org.eclipse.ui.IWorkbench;
+import org.eclipse.ui.plugin.AbstractUIPlugin;
+import org.osgi.framework.BundleContext;
+
+public class WatchdogPlugin extends AbstractUIPlugin implements IStartup {
+ private static final int EVENT_DURATION_THRESHOLD = 1001;
+
+ private static WatchdogPlugin plugin;
+ private final Display display;
+ private final TimedEventWatchdog watchdog;
+
+ public WatchdogPlugin() {
+ super();
+ plugin = this;
+
+ IWorkbench workbench = getWorkbench();
+ display = (workbench != null) ? workbench.getDisplay() : null;
+
+ Thread displayThread = (display != null) ? display.getThread() : null;
+ this.watchdog = displayThread != null
+ ? new TimedEventWatchdog(displayThread, EVENT_DURATION_THRESHOLD)
+ : null;
+ }
+
+ @Override
+ public void earlyStartup() {
+ if (display != null) {
+ display.asyncExec(new Runnable() {
+ @Override
+ public void run() {
+ display.addListener(SWT.PreEvent, watchdog);
+ display.addListener(SWT.PostEvent, watchdog);
+ }
+ });
+ }
+ }
+
+ @Override
+ public void stop(BundleContext context) throws Exception {
+ try {
+ if (display != null && !display.isDisposed()) {
+ display.asyncExec(new Runnable() {
+ @Override
+ public void run() {
+ if (!display.isDisposed()) {
+ display.removeListener(SWT.PreEvent, watchdog);
+ display.removeListener(SWT.PostEvent, watchdog);
+ }
+ }
+ });
+ }
+ } finally {
+ super.stop(context);
+ }
+ }
+
+ public static WatchdogPlugin getDefault() {
+ return plugin;
+ }
+}

Back to the top