/toolkit/xre/EventTracer.cpp

  1/* ***** BEGIN LICENSE BLOCK *****
  2 * Version: MPL 1.1/GPL 2.0/LGPL 2.1
  3 *
  4 * The contents of this file are subject to the Mozilla Public License Version
  5 * 1.1 (the "License"); you may not use this file except in compliance with
  6 * the License. You may obtain a copy of the License at
  7 * http://www.mozilla.org/MPL/
  8 *
  9 * Software distributed under the License is distributed on an "AS IS" basis,
 10 * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
 11 * for the specific language governing rights and limitations under the
 12 * License.
 13 *
 14 * The Original Code is mozilla.org code.
 15 *
 16 * The Initial Developer of the Original Code is
 17 * The Mozilla Foundation.
 18 * Portions created by the Initial Developer are Copyright (C) 2011
 19 * the Initial Developer. All Rights Reserved.
 20 *
 21 * Contributor(s):
 22 *   Ted Mielczarek <ted.mielczarek@gmail.com>
 23 *
 24 * Alternatively, the contents of this file may be used under the terms of
 25 * either the GNU General Public License Version 2 or later (the "GPL"), or
 26 * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
 27 * in which case the provisions of the GPL or the LGPL are applicable instead
 28 * of those above. If you wish to allow use of your version of this file only
 29 * under the terms of either the GPL or the LGPL, and not to allow others to
 30 * use your version of this file under the terms of the MPL, indicate your
 31 * decision by deleting the provisions above and replace them with the notice
 32 * and other provisions required by the GPL or the LGPL. If you do not delete
 33 * the provisions above, a recipient may use your version of this file under
 34 * the terms of any one of the MPL, the GPL or the LGPL.
 35 *
 36 * ***** END LICENSE BLOCK ***** */
 37
 38/*
 39 * Event loop instrumentation. This code attempts to measure the
 40 * latency of the UI-thread event loop by firing native events at it from
 41 * a background thread, and measuring how long it takes for them
 42 * to be serviced. The measurement interval (kMeasureInterval, below)
 43 * is also used as the upper bound of acceptable response time.
 44 * When an event takes longer than that interval to be serviced,
 45 * a sample will be written to the log.
 46 *
 47 * Usage:
 48 *
 49 * Set MOZ_INSTRUMENT_EVENT_LOOP=1 in the environment to enable
 50 * this instrumentation. Currently only the UI process is instrumented.
 51 *
 52 * Set MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT in the environment to a
 53 * file path to contain the log output, the default is to log to stdout.
 54 *
 55 * Set MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD in the environment to an
 56 * integer number of milliseconds to change the threshold for reporting.
 57 * The default is 20 milliseconds. Unresponsive periods shorter than this
 58 * threshold will not be reported.
 59 *
 60 * Set MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL in the environment to an
 61 * integer number of milliseconds to change the maximum sampling frequency.
 62 * This variable controls how often events will be sent to the main
 63 * thread's event loop to sample responsiveness. The sampler will not
 64 * send events twice within LOOP_INTERVAL milliseconds.
 65 * The default is 10 milliseconds.
 66 *
 67 * All logged output lines start with MOZ_EVENT_TRACE. All timestamps
 68 * output are milliseconds since the epoch (PRTime / 1000).
 69 *
 70 * On startup, a line of the form:
 71 *   MOZ_EVENT_TRACE start <timestamp>
 72 * will be output.
 73 *
 74 * On shutdown, a line of the form:
 75 *   MOZ_EVENT_TRACE stop <timestamp>
 76 * will be output.
 77 *
 78 * When an event servicing time exceeds the threshold, a line of the form:
 79 *   MOZ_EVENT_TRACE sample <timestamp> <duration>
 80 * will be output, where <duration> is the number of milliseconds that
 81 * it took for the event to be serviced.
 82 */
 83
 84#include "sampler.h"
 85
 86#include "EventTracer.h"
 87
 88#include <stdio.h>
 89
 90#include "mozilla/TimeStamp.h"
 91#include "mozilla/WidgetTraceEvent.h"
 92#include <limits.h>
 93#include <prenv.h>
 94#include <prinrval.h>
 95#include <prthread.h>
 96#include <prtime.h>
 97
 98using mozilla::TimeDuration;
 99using mozilla::TimeStamp;
100using mozilla::FireAndWaitForTracerEvent;
101
102namespace {
103
104PRThread* sTracerThread = NULL;
105bool sExit = false;
106
107/*
108 * The tracer thread fires events at the native event loop roughly
109 * every kMeasureInterval. It will sleep to attempt not to send them
110 * more quickly, but if the response time is longer than kMeasureInterval
111 * it will not send another event until the previous response is received.
112 *
113 * The output defaults to stdout, but can be redirected to a file by
114 * settting the environment variable MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT
115 * to the name of a file to use.
116 */
117void TracerThread(void *arg)
118{
119  // These are the defaults. They can be overridden by environment vars.
120  // This should be set to the maximum latency we'd like to allow
121  // for responsiveness.
122  PRIntervalTime threshold = PR_MillisecondsToInterval(20);
123  // This is the sampling interval.
124  PRIntervalTime interval = PR_MillisecondsToInterval(10);
125
126  sExit = false;
127  FILE* log = NULL;
128  char* envfile = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_OUTPUT");
129  if (envfile) {
130    log = fopen(envfile, "w");
131  }
132  if (log == NULL)
133    log = stdout;
134
135  char* thresholdenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_THRESHOLD");
136  if (thresholdenv && *thresholdenv) {
137    int val = atoi(thresholdenv);
138    if (val != 0 && val != INT_MAX && val != INT_MIN) {
139      threshold = PR_MillisecondsToInterval(val);
140    }
141  }
142
143  char* intervalenv = PR_GetEnv("MOZ_INSTRUMENT_EVENT_LOOP_INTERVAL");
144  if (intervalenv && *intervalenv) {
145    int val = atoi(intervalenv);
146    if (val != 0 && val != INT_MAX && val != INT_MIN) {
147      interval = PR_MillisecondsToInterval(val);
148    }
149  }
150
151  fprintf(log, "MOZ_EVENT_TRACE start %llu\n", PR_Now() / PR_USEC_PER_MSEC);
152
153  while (!sExit) {
154    TimeStamp start(TimeStamp::Now());
155    SAMPLER_RESPONSIVENESS(start);
156    PRIntervalTime next_sleep = interval;
157
158    //TODO: only wait up to a maximum of interval; return
159    // early if that threshold is exceeded and dump a stack trace
160    // or do something else useful.
161    if (FireAndWaitForTracerEvent()) {
162      TimeDuration duration = TimeStamp::Now() - start;
163      // Only report samples that exceed our measurement threshold.
164      if (duration.ToMilliseconds() > threshold) {
165        fprintf(log, "MOZ_EVENT_TRACE sample %llu %d\n",
166                PR_Now() / PR_USEC_PER_MSEC,
167                int(duration.ToSecondsSigDigits() * 1000));
168      }
169
170      if (next_sleep > duration.ToMilliseconds()) {
171        next_sleep -= int(duration.ToMilliseconds());
172      }
173      else {
174        // Don't sleep at all if this event took longer than the measure
175        // interval to deliver.
176        next_sleep = 0;
177      }
178    }
179
180    if (next_sleep != 0 && !sExit) {
181      PR_Sleep(next_sleep);
182    }
183  }
184
185  fprintf(log, "MOZ_EVENT_TRACE stop %llu\n", PR_Now() / PR_USEC_PER_MSEC);
186
187  if (log != stdout)
188    fclose(log);
189}
190
191} // namespace
192
193namespace mozilla {
194
195bool InitEventTracing()
196{
197  if (sTracerThread)
198    return true;
199
200  // Initialize the widget backend.
201  if (!InitWidgetTracing())
202    return false;
203
204  // Create a thread that will fire events back at the
205  // main thread to measure responsiveness.
206  NS_ABORT_IF_FALSE(!sTracerThread, "Event tracing already initialized!");
207  sTracerThread = PR_CreateThread(PR_USER_THREAD,
208                                  TracerThread,
209                                  NULL,
210                                  PR_PRIORITY_NORMAL,
211                                  PR_GLOBAL_THREAD,
212                                  PR_JOINABLE_THREAD,
213                                  0);
214  return sTracerThread != NULL;
215}
216
217void ShutdownEventTracing()
218{
219  if (!sTracerThread)
220    return;
221
222  sExit = true;
223  // Ensure that the tracer thread doesn't hang.
224  SignalTracerThread();
225
226  if (sTracerThread)
227    PR_JoinThread(sTracerThread);
228  sTracerThread = NULL;
229
230  // Allow the widget backend to clean up.
231  CleanUpWidgetTracing();
232}
233
234}  // namespace mozilla