1.1 --- /dev/null Thu Jan 01 00:00:00 1970 +0000
1.2 +++ b/toolkit/xre/EventTracer.cpp Wed Dec 31 06:09:35 2014 +0100
1.3 @@ -0,0 +1,267 @@
1.4 +/* This Source Code Form is subject to the terms of the Mozilla Public
1.5 + * License, v. 2.0. If a copy of the MPL was not distributed with this
1.6 + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
1.7 +
1.8 +/*
1.9 + * Event loop instrumentation. This code attempts to measure the
1.10 + * latency of the UI-thread event loop by firing native events at it from
1.11 + * a background thread, and measuring how long it takes for them
1.12 + * to be serviced. The measurement interval (kMeasureInterval, below)
1.13 + * is also used as the upper bound of acceptable response time.
1.14 + * When an event takes longer than that interval to be serviced,
1.15 + * a sample will be written to the log.
1.16 + *
1.17 + * Usage:
1.18 + *
1.19 + * Set MOZ_INSTRUMENT_EVENT_LOOP=1 in the environment to enable
1.20 + * this instrumentation. Currently only the UI process is instrumented.
1.21 + *
1.22 + * Set MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT in the environment to a
1.23 + * file path to contain the log output, the default is to log to stdout.
1.24 + *
1.25 + * Set MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD in the environment to an
1.26 + * integer number of milliseconds to change the threshold for reporting.
1.27 + * The default is 20 milliseconds. Unresponsive periods shorter than this
1.28 + * threshold will not be reported.
1.29 + *
1.30 + * Set MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL in the environment to an
1.31 + * integer number of milliseconds to change the maximum sampling frequency.
1.32 + * This variable controls how often events will be sent to the main
1.33 + * thread's event loop to sample responsiveness. The sampler will not
1.34 + * send events twice within LOOP_INTERVAL milliseconds.
1.35 + * The default is 10 milliseconds.
1.36 + *
1.37 + * All logged output lines start with MOZ_EVENT_TRACE. All timestamps
1.38 + * output are milliseconds since the epoch (PRTime / 1000).
1.39 + *
1.40 + * On startup, a line of the form:
1.41 + * MOZ_EVENT_TRACE start <timestamp>
1.42 + * will be output.
1.43 + *
1.44 + * On shutdown, a line of the form:
1.45 + * MOZ_EVENT_TRACE stop <timestamp>
1.46 + * will be output.
1.47 + *
1.48 + * When an event servicing time exceeds the threshold, a line of the form:
1.49 + * MOZ_EVENT_TRACE sample <timestamp> <duration>
1.50 + * will be output, where <duration> is the number of milliseconds that
1.51 + * it took for the event to be serviced. Duration may contain a fractional
1.52 + * component.
1.53 + */
1.54 +
1.55 +#include "GeckoProfiler.h"
1.56 +
1.57 +#include "EventTracer.h"
1.58 +
1.59 +#include <stdio.h>
1.60 +
1.61 +#include "mozilla/Preferences.h"
1.62 +#include "mozilla/TimeStamp.h"
1.63 +#include "mozilla/WidgetTraceEvent.h"
1.64 +#include "nsDebug.h"
1.65 +#include <limits.h>
1.66 +#include <prenv.h>
1.67 +#include <prinrval.h>
1.68 +#include <prthread.h>
1.69 +#include <prtime.h>
1.70 +
1.71 +#ifdef MOZ_WIDGET_GONK
1.72 +#include "nsThreadUtils.h"
1.73 +#include "nsIObserverService.h"
1.74 +#include "mozilla/Services.h"
1.75 +#endif
1.76 +
1.77 +using mozilla::TimeDuration;
1.78 +using mozilla::TimeStamp;
1.79 +using mozilla::FireAndWaitForTracerEvent;
1.80 +
1.81 +namespace {
1.82 +
1.83 +PRThread* sTracerThread = nullptr;
1.84 +bool sExit = false;
1.85 +
1.86 +struct TracerStartClosure {
1.87 + bool mLogTracing;
1.88 + int32_t mThresholdInterval;
1.89 +};
1.90 +
1.91 +#ifdef MOZ_WIDGET_GONK
1.92 +class EventLoopLagDispatcher : public nsRunnable
1.93 +{
1.94 + public:
1.95 + explicit EventLoopLagDispatcher(int aLag)
1.96 + : mLag(aLag) {}
1.97 +
1.98 + NS_IMETHODIMP Run()
1.99 + {
1.100 + nsCOMPtr<nsIObserverService> obsService =
1.101 + mozilla::services::GetObserverService();
1.102 + if (!obsService) {
1.103 + return NS_ERROR_FAILURE;
1.104 + }
1.105 +
1.106 + nsAutoString value;
1.107 + value.AppendInt(mLag);
1.108 + return obsService->NotifyObservers(nullptr, "event-loop-lag", value.get());
1.109 + }
1.110 +
1.111 + private:
1.112 + int mLag;
1.113 +};
1.114 +#endif
1.115 +
1.116 +/*
1.117 + * The tracer thread fires events at the native event loop roughly
1.118 + * every kMeasureInterval. It will sleep to attempt not to send them
1.119 + * more quickly, but if the response time is longer than kMeasureInterval
1.120 + * it will not send another event until the previous response is received.
1.121 + *
1.122 + * The output defaults to stdout, but can be redirected to a file by
1.123 + * settting the environment variable MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT
1.124 + * to the name of a file to use.
1.125 + */
1.126 +void TracerThread(void *arg)
1.127 +{
1.128 + PR_SetCurrentThreadName("Event Tracer");
1.129 +
1.130 + TracerStartClosure* threadArgs = static_cast<TracerStartClosure*>(arg);
1.131 +
1.132 + // These are the defaults. They can be overridden by environment vars.
1.133 + // This should be set to the maximum latency we'd like to allow
1.134 + // for responsiveness.
1.135 + int32_t thresholdInterval = threadArgs->mThresholdInterval;
1.136 + PRIntervalTime threshold = PR_MillisecondsToInterval(thresholdInterval);
1.137 + // This is the sampling interval.
1.138 + PRIntervalTime interval = PR_MillisecondsToInterval(thresholdInterval / 2);
1.139 +
1.140 + sExit = false;
1.141 + FILE* log = nullptr;
1.142 + char* envfile = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT");
1.143 + if (envfile) {
1.144 + log = fopen(envfile, "w");
1.145 + }
1.146 + if (log == nullptr)
1.147 + log = stdout;
1.148 +
1.149 + char* thresholdenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD");
1.150 + if (thresholdenv && *thresholdenv) {
1.151 + int val = atoi(thresholdenv);
1.152 + if (val != 0 && val != INT_MAX && val != INT_MIN) {
1.153 + threshold = PR_MillisecondsToInterval(val);
1.154 + }
1.155 + }
1.156 +
1.157 + char* intervalenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL");
1.158 + if (intervalenv && *intervalenv) {
1.159 + int val = atoi(intervalenv);
1.160 + if (val != 0 && val != INT_MAX && val != INT_MIN) {
1.161 + interval = PR_MillisecondsToInterval(val);
1.162 + }
1.163 + }
1.164 +
1.165 + if (threadArgs->mLogTracing) {
1.166 + long long now = PR_Now() / PR_USEC_PER_MSEC;
1.167 + fprintf(log, "MOZ_EVENT_TRACE start %llu\n", now);
1.168 + }
1.169 +
1.170 + while (!sExit) {
1.171 + TimeStamp start(TimeStamp::Now());
1.172 + profiler_responsiveness(start);
1.173 + PRIntervalTime next_sleep = interval;
1.174 +
1.175 + //TODO: only wait up to a maximum of interval; return
1.176 + // early if that threshold is exceeded and dump a stack trace
1.177 + // or do something else useful.
1.178 + if (FireAndWaitForTracerEvent()) {
1.179 + TimeDuration duration = TimeStamp::Now() - start;
1.180 + // Only report samples that exceed our measurement threshold.
1.181 + long long now = PR_Now() / PR_USEC_PER_MSEC;
1.182 + if (threadArgs->mLogTracing && duration.ToMilliseconds() > threshold) {
1.183 + fprintf(log, "MOZ_EVENT_TRACE sample %llu %lf\n",
1.184 + now,
1.185 + duration.ToMilliseconds());
1.186 +#ifdef MOZ_WIDGET_GONK
1.187 + NS_DispatchToMainThread(
1.188 + new EventLoopLagDispatcher(int(duration.ToSecondsSigDigits() * 1000)));
1.189 +#endif
1.190 + }
1.191 +
1.192 + if (next_sleep > duration.ToMilliseconds()) {
1.193 + next_sleep -= int(duration.ToMilliseconds());
1.194 + }
1.195 + else {
1.196 + // Don't sleep at all if this event took longer than the measure
1.197 + // interval to deliver.
1.198 + next_sleep = 0;
1.199 + }
1.200 + }
1.201 +
1.202 + if (next_sleep != 0 && !sExit) {
1.203 + PR_Sleep(next_sleep);
1.204 + }
1.205 + }
1.206 +
1.207 + if (threadArgs->mLogTracing) {
1.208 + long long now = PR_Now() / PR_USEC_PER_MSEC;
1.209 + fprintf(log, "MOZ_EVENT_TRACE stop %llu\n", now);
1.210 + }
1.211 +
1.212 + if (log != stdout)
1.213 + fclose(log);
1.214 +
1.215 + delete threadArgs;
1.216 +}
1.217 +
1.218 +} // namespace
1.219 +
1.220 +namespace mozilla {
1.221 +
1.222 +bool InitEventTracing(bool aLog)
1.223 +{
1.224 + if (sTracerThread)
1.225 + return true;
1.226 +
1.227 + // Initialize the widget backend.
1.228 + if (!InitWidgetTracing())
1.229 + return false;
1.230 +
1.231 + // The tracer thread owns the object and will delete it.
1.232 + TracerStartClosure* args = new TracerStartClosure();
1.233 + args->mLogTracing = aLog;
1.234 +
1.235 + // Pass the default threshold interval.
1.236 + int32_t thresholdInterval = 20;
1.237 + Preferences::GetInt("devtools.eventlooplag.threshold", &thresholdInterval);
1.238 + args->mThresholdInterval = thresholdInterval;
1.239 +
1.240 + // Create a thread that will fire events back at the
1.241 + // main thread to measure responsiveness.
1.242 + NS_ABORT_IF_FALSE(!sTracerThread, "Event tracing already initialized!");
1.243 + sTracerThread = PR_CreateThread(PR_USER_THREAD,
1.244 + TracerThread,
1.245 + args,
1.246 + PR_PRIORITY_NORMAL,
1.247 + PR_GLOBAL_THREAD,
1.248 + PR_JOINABLE_THREAD,
1.249 + 0);
1.250 + return sTracerThread != nullptr;
1.251 +}
1.252 +
1.253 +void ShutdownEventTracing()
1.254 +{
1.255 + if (!sTracerThread)
1.256 + return;
1.257 +
1.258 + sExit = true;
1.259 + // Ensure that the tracer thread doesn't hang.
1.260 + SignalTracerThread();
1.261 +
1.262 + if (sTracerThread)
1.263 + PR_JoinThread(sTracerThread);
1.264 + sTracerThread = nullptr;
1.265 +
1.266 + // Allow the widget backend to clean up.
1.267 + CleanUpWidgetTracing();
1.268 +}
1.269 +
1.270 +} // namespace mozilla
