Skip to main content
aboutsummaryrefslogtreecommitdiffstats
blob: c09ea6babef05047ee8f4688acc69a7820dd0855 (plain) (blame)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
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);
			}
		}
	}
}

Back to the top