Source code
Revision control
Copy as Markdown
Other Tools
/* 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
/*
* 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