The Tor Browser / file revision

 /* 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>

 #ifdef MOZ_WIDGET_GONK

 #include "nsThreadUtils.h"

 #include "nsIObserverService.h"

 #include "mozilla/Services.h"

 #endif

 using mozilla::TimeDuration;

 using mozilla::TimeStamp;

 using mozilla::FireAndWaitForTracerEvent;

 namespace {

 PRThread* sTracerThread = nullptr;

 bool sExit = false;

 struct TracerStartClosure {

   bool mLogTracing;

   int32_t mThresholdInterval;

 };

 #ifdef MOZ_WIDGET_GONK

 class EventLoopLagDispatcher : public nsRunnable

 {

   public:

     explicit EventLoopLagDispatcher(int aLag)

       : mLag(aLag) {}

     NS_IMETHODIMP Run()

     {

       nsCOMPtr<nsIObserverService> obsService =

         mozilla::services::GetObserverService();

       if (!obsService) {

         return NS_ERROR_FAILURE;

       }

       nsAutoString value;

       value.AppendInt(mLag);

       return obsService->NotifyObservers(nullptr, "event-loop-lag", value.get());

     }

   private:

     int mLag;

 };

 #endif

 /*

  * 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)

 {

   PR_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());

     profiler_responsiveness(start);

     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());

 #ifdef MOZ_WIDGET_GONK

         NS_DispatchToMainThread(

          new EventLoopLagDispatcher(int(duration.ToSecondsSigDigits() * 1000)));

 #endif

       }

       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.

   NS_ABORT_IF_FALSE(!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