summaryrefslogtreecommitdiffstats
path: root/toolkit/xre/EventTracer.cpp
diff options
context:
space:
mode:
Diffstat (limited to 'toolkit/xre/EventTracer.cpp')
-rw-r--r--toolkit/xre/EventTracer.cpp219
1 files changed, 219 insertions, 0 deletions
diff --git a/toolkit/xre/EventTracer.cpp b/toolkit/xre/EventTracer.cpp
new file mode 100644
index 0000000000..aae3fee8e3
--- /dev/null
+++ b/toolkit/xre/EventTracer.cpp
@@ -0,0 +1,219 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+/*
+ * Event loop instrumentation. This code attempts to measure the
+ * latency of the UI-thread event loop by firing native events at it from
+ * a background thread, and measuring how long it takes for them
+ * to be serviced. The measurement interval (kMeasureInterval, below)
+ * is also used as the upper bound of acceptable response time.
+ * When an event takes longer than that interval to be serviced,
+ * a sample will be written to the log.
+ *
+ * Usage:
+ *
+ * Set MOZ_INSTRUMENT_EVENT_LOOP=1 in the environment to enable
+ * this instrumentation. Currently only the UI process is instrumented.
+ *
+ * Set MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT in the environment to a
+ * file path to contain the log output, the default is to log to stdout.
+ *
+ * Set MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD in the environment to an
+ * integer number of milliseconds to change the threshold for reporting.
+ * The default is 20 milliseconds. Unresponsive periods shorter than this
+ * threshold will not be reported.
+ *
+ * Set MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL in the environment to an
+ * integer number of milliseconds to change the maximum sampling frequency.
+ * This variable controls how often events will be sent to the main
+ * thread's event loop to sample responsiveness. The sampler will not
+ * send events twice within LOOP_INTERVAL milliseconds.
+ * The default is 10 milliseconds.
+ *
+ * All logged output lines start with MOZ_EVENT_TRACE. All timestamps
+ * output are milliseconds since the epoch (PRTime / 1000).
+ *
+ * On startup, a line of the form:
+ * MOZ_EVENT_TRACE start <timestamp>
+ * will be output.
+ *
+ * On shutdown, a line of the form:
+ * MOZ_EVENT_TRACE stop <timestamp>
+ * will be output.
+ *
+ * When an event servicing time exceeds the threshold, a line of the form:
+ * MOZ_EVENT_TRACE sample <timestamp> <duration>
+ * will be output, where <duration> is the number of milliseconds that
+ * it took for the event to be serviced. Duration may contain a fractional
+ * component.
+ */
+
+#include "GeckoProfiler.h"
+
+#include "EventTracer.h"
+
+#include <stdio.h>
+
+#include "mozilla/Preferences.h"
+#include "mozilla/TimeStamp.h"
+#include "mozilla/WidgetTraceEvent.h"
+#include "nsDebug.h"
+#include <limits.h>
+#include <prenv.h>
+#include <prinrval.h>
+#include <prthread.h>
+#include <prtime.h>
+
+#include "nsThreadUtils.h"
+
+using mozilla::FireAndWaitForTracerEvent;
+using mozilla::TimeDuration;
+using mozilla::TimeStamp;
+
+namespace {
+
+PRThread* sTracerThread = nullptr;
+bool sExit = false;
+
+struct TracerStartClosure {
+ bool mLogTracing;
+ int32_t mThresholdInterval;
+};
+
+/*
+ * The tracer thread fires events at the native event loop roughly
+ * every kMeasureInterval. It will sleep to attempt not to send them
+ * more quickly, but if the response time is longer than kMeasureInterval
+ * it will not send another event until the previous response is received.
+ *
+ * The output defaults to stdout, but can be redirected to a file by
+ * settting the environment variable MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT
+ * to the name of a file to use.
+ */
+void TracerThread(void* arg) {
+ AUTO_PROFILER_REGISTER_THREAD("Event Tracer");
+ NS_SetCurrentThreadName("Event Tracer");
+
+ TracerStartClosure* threadArgs = static_cast<TracerStartClosure*>(arg);
+
+ // These are the defaults. They can be overridden by environment vars.
+ // This should be set to the maximum latency we'd like to allow
+ // for responsiveness.
+ int32_t thresholdInterval = threadArgs->mThresholdInterval;
+ PRIntervalTime threshold = PR_MillisecondsToInterval(thresholdInterval);
+ // This is the sampling interval.
+ PRIntervalTime interval = PR_MillisecondsToInterval(thresholdInterval / 2);
+
+ sExit = false;
+ FILE* log = nullptr;
+ char* envfile = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT");
+ if (envfile) {
+ log = fopen(envfile, "w");
+ }
+ if (log == nullptr) log = stdout;
+
+ char* thresholdenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD");
+ if (thresholdenv && *thresholdenv) {
+ int val = atoi(thresholdenv);
+ if (val != 0 && val != INT_MAX && val != INT_MIN) {
+ threshold = PR_MillisecondsToInterval(val);
+ }
+ }
+
+ char* intervalenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL");
+ if (intervalenv && *intervalenv) {
+ int val = atoi(intervalenv);
+ if (val != 0 && val != INT_MAX && val != INT_MIN) {
+ interval = PR_MillisecondsToInterval(val);
+ }
+ }
+
+ if (threadArgs->mLogTracing) {
+ long long now = PR_Now() / PR_USEC_PER_MSEC;
+ fprintf(log, "MOZ_EVENT_TRACE start %llu\n", now);
+ }
+
+ while (!sExit) {
+ TimeStamp start(TimeStamp::Now());
+ PRIntervalTime next_sleep = interval;
+
+ // TODO: only wait up to a maximum of interval; return
+ // early if that threshold is exceeded and dump a stack trace
+ // or do something else useful.
+ if (FireAndWaitForTracerEvent()) {
+ TimeDuration duration = TimeStamp::Now() - start;
+ // Only report samples that exceed our measurement threshold.
+ long long now = PR_Now() / PR_USEC_PER_MSEC;
+ if (threadArgs->mLogTracing && duration.ToMilliseconds() > threshold) {
+ fprintf(log, "MOZ_EVENT_TRACE sample %llu %lf\n", now,
+ duration.ToMilliseconds());
+ }
+
+ if (next_sleep > duration.ToMilliseconds()) {
+ next_sleep -= int(duration.ToMilliseconds());
+ } else {
+ // Don't sleep at all if this event took longer than the measure
+ // interval to deliver.
+ next_sleep = 0;
+ }
+ }
+
+ if (next_sleep != 0 && !sExit) {
+ PR_Sleep(next_sleep);
+ }
+ }
+
+ if (threadArgs->mLogTracing) {
+ long long now = PR_Now() / PR_USEC_PER_MSEC;
+ fprintf(log, "MOZ_EVENT_TRACE stop %llu\n", now);
+ }
+
+ if (log != stdout) fclose(log);
+
+ delete threadArgs;
+}
+
+} // namespace
+
+namespace mozilla {
+
+bool InitEventTracing(bool aLog) {
+ if (sTracerThread) return true;
+
+ // Initialize the widget backend.
+ if (!InitWidgetTracing()) return false;
+
+ // The tracer thread owns the object and will delete it.
+ TracerStartClosure* args = new TracerStartClosure();
+ args->mLogTracing = aLog;
+
+ // Pass the default threshold interval.
+ int32_t thresholdInterval = 20;
+ Preferences::GetInt("devtools.eventlooplag.threshold", &thresholdInterval);
+ args->mThresholdInterval = thresholdInterval;
+
+ // Create a thread that will fire events back at the
+ // main thread to measure responsiveness.
+ MOZ_ASSERT(!sTracerThread, "Event tracing already initialized!");
+ sTracerThread =
+ PR_CreateThread(PR_USER_THREAD, TracerThread, args, PR_PRIORITY_NORMAL,
+ PR_GLOBAL_THREAD, PR_JOINABLE_THREAD, 0);
+ return sTracerThread != nullptr;
+}
+
+void ShutdownEventTracing() {
+ if (!sTracerThread) return;
+
+ sExit = true;
+ // Ensure that the tracer thread doesn't hang.
+ SignalTracerThread();
+
+ if (sTracerThread) PR_JoinThread(sTracerThread);
+ sTracerThread = nullptr;
+
+ // Allow the widget backend to clean up.
+ CleanUpWidgetTracing();
+}
+
+} // namespace mozilla