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