diff options
Diffstat (limited to 'toolkit/xre/EventTracer.cpp')
| -rw-r--r-- | toolkit/xre/EventTracer.cpp | 267 |
1 files changed, 267 insertions, 0 deletions
diff --git a/toolkit/xre/EventTracer.cpp b/toolkit/xre/EventTracer.cpp new file mode 100644 index 000000000..cb0d88524 --- /dev/null +++ b/toolkit/xre/EventTracer.cpp @@ -0,0 +1,267 @@ +/* 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 Runnable +{ + public: + explicit EventLoopLagDispatcher(int aLag) + : mLag(aLag) {} + + NS_IMETHOD Run() override + { + 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. + 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 |