1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
|
/* 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>
using mozilla::TimeDuration;
using mozilla::TimeStamp;
using mozilla::FireAndWaitForTracerEvent;
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)
{
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());
}
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
|
