Line data Source code
1 : /* This Source Code Form is subject to the terms of the Mozilla Public
2 : * License, v. 2.0. If a copy of the MPL was not distributed with this
3 : * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
4 :
5 : /*
6 : * Event loop instrumentation. This code attempts to measure the
7 : * latency of the UI-thread event loop by firing native events at it from
8 : * a background thread, and measuring how long it takes for them
9 : * to be serviced. The measurement interval (kMeasureInterval, below)
10 : * is also used as the upper bound of acceptable response time.
11 : * When an event takes longer than that interval to be serviced,
12 : * a sample will be written to the log.
13 : *
14 : * Usage:
15 : *
16 : * Set MOZ_INSTRUMENT_EVENT_LOOP=1 in the environment to enable
17 : * this instrumentation. Currently only the UI process is instrumented.
18 : *
19 : * Set MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT in the environment to a
20 : * file path to contain the log output, the default is to log to stdout.
21 : *
22 : * Set MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD in the environment to an
23 : * integer number of milliseconds to change the threshold for reporting.
24 : * The default is 20 milliseconds. Unresponsive periods shorter than this
25 : * threshold will not be reported.
26 : *
27 : * Set MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL in the environment to an
28 : * integer number of milliseconds to change the maximum sampling frequency.
29 : * This variable controls how often events will be sent to the main
30 : * thread's event loop to sample responsiveness. The sampler will not
31 : * send events twice within LOOP_INTERVAL milliseconds.
32 : * The default is 10 milliseconds.
33 : *
34 : * All logged output lines start with MOZ_EVENT_TRACE. All timestamps
35 : * output are milliseconds since the epoch (PRTime / 1000).
36 : *
37 : * On startup, a line of the form:
38 : * MOZ_EVENT_TRACE start <timestamp>
39 : * will be output.
40 : *
41 : * On shutdown, a line of the form:
42 : * MOZ_EVENT_TRACE stop <timestamp>
43 : * will be output.
44 : *
45 : * When an event servicing time exceeds the threshold, a line of the form:
46 : * MOZ_EVENT_TRACE sample <timestamp> <duration>
47 : * will be output, where <duration> is the number of milliseconds that
48 : * it took for the event to be serviced. Duration may contain a fractional
49 : * component.
50 : */
51 :
52 : #include "GeckoProfiler.h"
53 :
54 : #include "EventTracer.h"
55 :
56 : #include <stdio.h>
57 :
58 : #include "mozilla/Preferences.h"
59 : #include "mozilla/TimeStamp.h"
60 : #include "mozilla/WidgetTraceEvent.h"
61 : #include "nsDebug.h"
62 : #include <limits.h>
63 : #include <prenv.h>
64 : #include <prinrval.h>
65 : #include <prthread.h>
66 : #include <prtime.h>
67 :
68 : #include "nsThreadUtils.h"
69 : #ifdef MOZ_WIDGET_GONK
70 : #include "nsIObserverService.h"
71 : #include "mozilla/Services.h"
72 : #endif
73 :
74 : using mozilla::TimeDuration;
75 : using mozilla::TimeStamp;
76 : using mozilla::FireAndWaitForTracerEvent;
77 :
78 : namespace {
79 :
80 : PRThread* sTracerThread = nullptr;
81 : bool sExit = false;
82 :
83 : struct TracerStartClosure {
84 : bool mLogTracing;
85 : int32_t mThresholdInterval;
86 : };
87 :
88 : #ifdef MOZ_WIDGET_GONK
89 : class EventLoopLagDispatcher : public Runnable
90 : {
91 : public:
92 : explicit EventLoopLagDispatcher(int aLag)
93 : : mLag(aLag) {}
94 :
95 : NS_IMETHOD Run() override
96 : {
97 : nsCOMPtr<nsIObserverService> obsService =
98 : mozilla::services::GetObserverService();
99 : if (!obsService) {
100 : return NS_ERROR_FAILURE;
101 : }
102 :
103 : nsAutoString value;
104 : value.AppendInt(mLag);
105 : return obsService->NotifyObservers(nullptr, "event-loop-lag", value.get());
106 : }
107 :
108 : private:
109 : int mLag;
110 : };
111 : #endif
112 :
113 : /*
114 : * The tracer thread fires events at the native event loop roughly
115 : * every kMeasureInterval. It will sleep to attempt not to send them
116 : * more quickly, but if the response time is longer than kMeasureInterval
117 : * it will not send another event until the previous response is received.
118 : *
119 : * The output defaults to stdout, but can be redirected to a file by
120 : * settting the environment variable MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT
121 : * to the name of a file to use.
122 : */
123 0 : void TracerThread(void *arg)
124 : {
125 0 : AutoProfilerRegisterThread registerThread("Event Tracer");
126 0 : NS_SetCurrentThreadName("Event Tracer");
127 :
128 0 : TracerStartClosure* threadArgs = static_cast<TracerStartClosure*>(arg);
129 :
130 : // These are the defaults. They can be overridden by environment vars.
131 : // This should be set to the maximum latency we'd like to allow
132 : // for responsiveness.
133 0 : int32_t thresholdInterval = threadArgs->mThresholdInterval;
134 0 : PRIntervalTime threshold = PR_MillisecondsToInterval(thresholdInterval);
135 : // This is the sampling interval.
136 0 : PRIntervalTime interval = PR_MillisecondsToInterval(thresholdInterval / 2);
137 :
138 0 : sExit = false;
139 0 : FILE* log = nullptr;
140 0 : char* envfile = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT");
141 0 : if (envfile) {
142 0 : log = fopen(envfile, "w");
143 : }
144 0 : if (log == nullptr)
145 0 : log = stdout;
146 :
147 0 : char* thresholdenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD");
148 0 : if (thresholdenv && *thresholdenv) {
149 0 : int val = atoi(thresholdenv);
150 0 : if (val != 0 && val != INT_MAX && val != INT_MIN) {
151 0 : threshold = PR_MillisecondsToInterval(val);
152 : }
153 : }
154 :
155 0 : char* intervalenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL");
156 0 : if (intervalenv && *intervalenv) {
157 0 : int val = atoi(intervalenv);
158 0 : if (val != 0 && val != INT_MAX && val != INT_MIN) {
159 0 : interval = PR_MillisecondsToInterval(val);
160 : }
161 : }
162 :
163 0 : if (threadArgs->mLogTracing) {
164 0 : long long now = PR_Now() / PR_USEC_PER_MSEC;
165 0 : fprintf(log, "MOZ_EVENT_TRACE start %llu\n", now);
166 : }
167 :
168 0 : while (!sExit) {
169 0 : TimeStamp start(TimeStamp::Now());
170 0 : PRIntervalTime next_sleep = interval;
171 :
172 : //TODO: only wait up to a maximum of interval; return
173 : // early if that threshold is exceeded and dump a stack trace
174 : // or do something else useful.
175 0 : if (FireAndWaitForTracerEvent()) {
176 0 : TimeDuration duration = TimeStamp::Now() - start;
177 : // Only report samples that exceed our measurement threshold.
178 0 : long long now = PR_Now() / PR_USEC_PER_MSEC;
179 0 : if (threadArgs->mLogTracing && duration.ToMilliseconds() > threshold) {
180 0 : fprintf(log, "MOZ_EVENT_TRACE sample %llu %lf\n",
181 : now,
182 0 : duration.ToMilliseconds());
183 : #ifdef MOZ_WIDGET_GONK
184 : NS_DispatchToMainThread(
185 : new EventLoopLagDispatcher(int(duration.ToSecondsSigDigits() * 1000)));
186 : #endif
187 : }
188 :
189 0 : if (next_sleep > duration.ToMilliseconds()) {
190 0 : next_sleep -= int(duration.ToMilliseconds());
191 : }
192 : else {
193 : // Don't sleep at all if this event took longer than the measure
194 : // interval to deliver.
195 0 : next_sleep = 0;
196 : }
197 : }
198 :
199 0 : if (next_sleep != 0 && !sExit) {
200 0 : PR_Sleep(next_sleep);
201 : }
202 : }
203 :
204 0 : if (threadArgs->mLogTracing) {
205 0 : long long now = PR_Now() / PR_USEC_PER_MSEC;
206 0 : fprintf(log, "MOZ_EVENT_TRACE stop %llu\n", now);
207 : }
208 :
209 0 : if (log != stdout)
210 0 : fclose(log);
211 :
212 : delete threadArgs;
213 0 : }
214 :
215 : } // namespace
216 :
217 : namespace mozilla {
218 :
219 0 : bool InitEventTracing(bool aLog)
220 : {
221 0 : if (sTracerThread)
222 0 : return true;
223 :
224 : // Initialize the widget backend.
225 0 : if (!InitWidgetTracing())
226 0 : return false;
227 :
228 : // The tracer thread owns the object and will delete it.
229 0 : TracerStartClosure* args = new TracerStartClosure();
230 0 : args->mLogTracing = aLog;
231 :
232 : // Pass the default threshold interval.
233 0 : int32_t thresholdInterval = 20;
234 0 : Preferences::GetInt("devtools.eventlooplag.threshold", &thresholdInterval);
235 0 : args->mThresholdInterval = thresholdInterval;
236 :
237 : // Create a thread that will fire events back at the
238 : // main thread to measure responsiveness.
239 0 : MOZ_ASSERT(!sTracerThread, "Event tracing already initialized!");
240 0 : sTracerThread = PR_CreateThread(PR_USER_THREAD,
241 : TracerThread,
242 : args,
243 : PR_PRIORITY_NORMAL,
244 : PR_GLOBAL_THREAD,
245 : PR_JOINABLE_THREAD,
246 : 0);
247 0 : return sTracerThread != nullptr;
248 : }
249 :
250 0 : void ShutdownEventTracing()
251 : {
252 0 : if (!sTracerThread)
253 0 : return;
254 :
255 0 : sExit = true;
256 : // Ensure that the tracer thread doesn't hang.
257 0 : SignalTracerThread();
258 :
259 0 : if (sTracerThread)
260 0 : PR_JoinThread(sTracerThread);
261 0 : sTracerThread = nullptr;
262 :
263 : // Allow the widget backend to clean up.
264 0 : CleanUpWidgetTracing();
265 : }
266 :
267 : } // namespace mozilla
|
