toolkit/xre/EventTracer.cpp

   1 /* This Source Code Form is subject to the terms of the Mozilla Public
   2  * License, v. 2.0. If a copy of the MPL was not distributed with this
   3  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
   4
   5 /*
   6  * Event loop instrumentation. This code attempts to measure the
   7  * latency of the UI-thread event loop by firing native events at it from
   8  * a background thread, and measuring how long it takes for them
   9  * to be serviced. The measurement interval (kMeasureInterval, below)
  10  * is also used as the upper bound of acceptable response time.
  11  * When an event takes longer than that interval to be serviced,
  12  * a sample will be written to the log.
  13  *
  14  * Usage:
  15  *
  16  * Set MOZ_INSTRUMENT_EVENT_LOOP=1 in the environment to enable
  17  * this instrumentation. Currently only the UI process is instrumented.
  18  *
  19  * Set MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT in the environment to a
  20  * file path to contain the log output, the default is to log to stdout.
  21  *
  22  * Set MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD in the environment to an
  23  * integer number of milliseconds to change the threshold for reporting.
  24  * The default is 20 milliseconds. Unresponsive periods shorter than this
  25  * threshold will not be reported.
  26  *
  27  * Set MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL in the environment to an
  28  * integer number of milliseconds to change the maximum sampling frequency.
  29  * This variable controls how often events will be sent to the main
  30  * thread's event loop to sample responsiveness. The sampler will not
  31  * send events twice within LOOP_INTERVAL milliseconds.
  32  * The default is 10 milliseconds.
  33  *
  34  * All logged output lines start with MOZ_EVENT_TRACE. All timestamps
  35  * output are milliseconds since the epoch (PRTime / 1000).
  36  *
  37  * On startup, a line of the form:
  38  *   MOZ_EVENT_TRACE start <timestamp>
  39  * will be output.
  40  *
  41  * On shutdown, a line of the form:
  42  *   MOZ_EVENT_TRACE stop <timestamp>
  43  * will be output.
  44  *
  45  * When an event servicing time exceeds the threshold, a line of the form:
  46  *   MOZ_EVENT_TRACE sample <timestamp> <duration>
  47  * will be output, where <duration> is the number of milliseconds that
  48  * it took for the event to be serviced. Duration may contain a fractional
  49  * component.
  50  */
  51
  52 #include "GeckoProfiler.h"
  53
  54 #include "EventTracer.h"
  55
  56 #include <stdio.h>
  57
  58 #include "mozilla/Preferences.h"
  59 #include "mozilla/TimeStamp.h"
  60 #include "mozilla/WidgetTraceEvent.h"
  61 #include "nsDebug.h"
  62 #include <limits.h>
  63 #include <prenv.h>
  64 #include <prinrval.h>
  65 #include <prthread.h>
  66 #include <prtime.h>
  67
  68 #include "nsThreadUtils.h"
  69
  70 using mozilla::FireAndWaitForTracerEvent;
  71 using mozilla::TimeDuration;
  72 using mozilla::TimeStamp;
  73
  74 namespace {
  75
  76 PRThread* sTracerThread = nullptr;
  77 bool sExit = false;
  78
  79 struct TracerStartClosure {
  80   bool mLogTracing;
  81   int32_t mThresholdInterval;
  82 };
  83
  84 /*
  85  * The tracer thread fires events at the native event loop roughly
  86  * every kMeasureInterval. It will sleep to attempt not to send them
  87  * more quickly, but if the response time is longer than kMeasureInterval
  88  * it will not send another event until the previous response is received.
  89  *
  90  * The output defaults to stdout, but can be redirected to a file by
  91  * settting the environment variable MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT
  92  * to the name of a file to use.
  93  */
  94 void TracerThread(void* arg) {
  95   AUTO_PROFILER_REGISTER_THREAD("Event Tracer");
  96   NS_SetCurrentThreadName("Event Tracer");
  97
  98   TracerStartClosure* threadArgs = static_cast<TracerStartClosure*>(arg);
  99
 100   // These are the defaults. They can be overridden by environment vars.
 101   // This should be set to the maximum latency we'd like to allow
 102   // for responsiveness.
 103   int32_t thresholdInterval = threadArgs->mThresholdInterval;
 104   PRIntervalTime threshold = PR_MillisecondsToInterval(thresholdInterval);
 105   // This is the sampling interval.
 106   PRIntervalTime interval = PR_MillisecondsToInterval(thresholdInterval / 2);
 107
 108   sExit = false;
 109   FILE* log = nullptr;
 110   char* envfile = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT");
 111   if (envfile) {
 112     log = fopen(envfile, "w");
 113   }
 114   if (log == nullptr) log = stdout;
 115
 116   char* thresholdenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD");
 117   if (thresholdenv && *thresholdenv) {
 118     int val = atoi(thresholdenv);
 119     if (val != 0 && val != INT_MAX && val != INT_MIN) {
 120       threshold = PR_MillisecondsToInterval(val);
 121     }
 122   }
 123
 124   char* intervalenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL");
 125   if (intervalenv && *intervalenv) {
 126     int val = atoi(intervalenv);
 127     if (val != 0 && val != INT_MAX && val != INT_MIN) {
 128       interval = PR_MillisecondsToInterval(val);
 129     }
 130   }
 131
 132   if (threadArgs->mLogTracing) {
 133     long long now = PR_Now() / PR_USEC_PER_MSEC;
 134     fprintf(log, "MOZ_EVENT_TRACE start %llu\n", now);
 135   }
 136
 137   while (!sExit) {
 138     TimeStamp start(TimeStamp::Now());
 139     PRIntervalTime next_sleep = interval;
 140
 141     // TODO: only wait up to a maximum of interval; return
 142     // early if that threshold is exceeded and dump a stack trace
 143     // or do something else useful.
 144     if (FireAndWaitForTracerEvent()) {
 145       TimeDuration duration = TimeStamp::Now() - start;
 146       // Only report samples that exceed our measurement threshold.
 147       long long now = PR_Now() / PR_USEC_PER_MSEC;
 148       if (threadArgs->mLogTracing && duration.ToMilliseconds() > threshold) {
 149         fprintf(log, "MOZ_EVENT_TRACE sample %llu %lf\n", now,
 150                 duration.ToMilliseconds());
 151       }
 152
 153       if (next_sleep > duration.ToMilliseconds()) {
 154         next_sleep -= int(duration.ToMilliseconds());
 155       } else {
 156         // Don't sleep at all if this event took longer than the measure
 157         // interval to deliver.
 158         next_sleep = 0;
 159       }
 160     }
 161
 162     if (next_sleep != 0 && !sExit) {
 163       PR_Sleep(next_sleep);
 164     }
 165   }
 166
 167   if (threadArgs->mLogTracing) {
 168     long long now = PR_Now() / PR_USEC_PER_MSEC;
 169     fprintf(log, "MOZ_EVENT_TRACE stop %llu\n", now);
 170   }
 171
 172   if (log != stdout) fclose(log);
 173
 174   delete threadArgs;
 175 }
 176
 177 }  // namespace
 178
 179 namespace mozilla {
 180
 181 bool InitEventTracing(bool aLog) {
 182   if (sTracerThread) return true;
 183
 184   // Initialize the widget backend.
 185   if (!InitWidgetTracing()) return false;
 186
 187   // The tracer thread owns the object and will delete it.
 188   TracerStartClosure* args = new TracerStartClosure();
 189   args->mLogTracing = aLog;
 190
 191   // Pass the default threshold interval.
 192   int32_t thresholdInterval = 20;
 193   Preferences::GetInt("devtools.eventlooplag.threshold", &thresholdInterval);
 194   args->mThresholdInterval = thresholdInterval;
 195
 196   // Create a thread that will fire events back at the
 197   // main thread to measure responsiveness.
 198   MOZ_ASSERT(!sTracerThread, "Event tracing already initialized!");
 199   sTracerThread =
 200       PR_CreateThread(PR_USER_THREAD, TracerThread, args, PR_PRIORITY_NORMAL,
 201                       PR_GLOBAL_THREAD, PR_JOINABLE_THREAD, 0);
 202   return sTracerThread != nullptr;
 203 }
 204
 205 void ShutdownEventTracing() {
 206   if (!sTracerThread) return;
 207
 208   sExit = true;
 209   // Ensure that the tracer thread doesn't hang.
 210   SignalTracerThread();
 211
 212   if (sTracerThread) PR_JoinThread(sTracerThread);
 213   sTracerThread = nullptr;
 214
 215   // Allow the widget backend to clean up.
 216   CleanUpWidgetTracing();
 217 }
 218
 219 }  // namespace mozilla