1// Copyright (c) 2011 The Chromium Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include <limits>
6
7#include "chrome/browser/jankometer.h"
8
9#include "base/basictypes.h"
10#include "base/command_line.h"
11#include "base/memory/ref_counted.h"
12#include "base/message_loop.h"
13#include "base/metrics/histogram.h"
14#include "base/metrics/stats_counters.h"
15#include "base/string_util.h"
16#include "base/threading/thread.h"
17#include "base/threading/watchdog.h"
18#include "base/time.h"
19#include "build/build_config.h"
20#include "chrome/browser/browser_process.h"
21#include "chrome/common/chrome_switches.h"
22#include "content/browser/browser_thread.h"
23
24#if defined(TOOLKIT_USES_GTK)
25#include "chrome/browser/ui/gtk/gtk_util.h"
26#endif
27
28using base::TimeDelta;
29using base::TimeTicks;
30
31namespace {
32
33// The maximum threshold of delay of the message  before considering it a delay.
34// For a debug build, you may want to set IO delay around 500ms.
35// For a release build, setting it around 350ms is sensible.
36// Visit about:histograms to see what the distribution is on your system, with
37// your build. Be sure to do some work to get interesting stats.
38// The numbers below came from a warm start (you'll get about 5-10 alarms with
39// a cold start), and running the page-cycler for 5 rounds.
40#ifdef NDEBUG
41const int kMaxUIMessageDelayMs = 350;
42const int kMaxIOMessageDelayMs = 200;
43#else
44const int kMaxUIMessageDelayMs = 500;
45const int kMaxIOMessageDelayMs = 400;
46#endif
47
48// Maximum processing time (excluding queueing delay) for a message before
49// considering it delayed.
50const int kMaxMessageProcessingMs = 100;
51
52// TODO(brettw) Consider making this a pref.
53const bool kPlaySounds = false;
54
55//------------------------------------------------------------------------------
56// Provide a special watchdog to make it easy to set the breakpoint on this
57// class only.
58class JankWatchdog : public base::Watchdog {
59 public:
60  JankWatchdog(const TimeDelta& duration,
61               const std::string& thread_watched_name,
62               bool enabled)
63      : Watchdog(duration, thread_watched_name, enabled),
64        thread_name_watched_(thread_watched_name),
65        alarm_count_(0) {
66  }
67
68  virtual ~JankWatchdog() {}
69
70  virtual void Alarm() {
71    // Put break point here if you want to stop threads and look at what caused
72    // the jankiness.
73    alarm_count_++;
74    Watchdog::Alarm();
75  }
76
77 private:
78  std::string thread_name_watched_;
79  int alarm_count_;
80
81  DISALLOW_COPY_AND_ASSIGN(JankWatchdog);
82};
83
84class JankObserverHelper {
85 public:
86  JankObserverHelper(const std::string& thread_name,
87                     const TimeDelta& excessive_duration,
88                     bool watchdog_enable);
89  ~JankObserverHelper();
90
91  void StartProcessingTimers(const TimeDelta& queueing_time);
92  void EndProcessingTimers();
93
94  // Indicate if we will bother to measuer this message.
95  bool MessageWillBeMeasured();
96
97  static void SetDefaultMessagesToSkip(int count) { discard_count_ = count; }
98
99 private:
100  const TimeDelta max_message_delay_;
101
102  // Indicate if we'll bother measuring this message.
103  bool measure_current_message_;
104
105  // Down counter which will periodically hit 0, and only then bother to measure
106  // the corresponding message.
107  int events_till_measurement_;
108
109  // The value to re-initialize events_till_measurement_ after it reaches 0.
110  static int discard_count_;
111
112  // Time at which the current message processing began.
113  TimeTicks begin_process_message_;
114
115  // Time the current message spent in the queue -- delta between message
116  // construction time and message processing time.
117  TimeDelta queueing_time_;
118
119  // Counters for the two types of jank we measure.
120  base::StatsCounter slow_processing_counter_;  // Msgs w/ long proc time.
121  base::StatsCounter queueing_delay_counter_;   // Msgs w/ long queueing delay.
122  base::Histogram* const process_times_;  // Time spent proc. task.
123  base::Histogram* const total_times_;  // Total queueing plus proc.
124  JankWatchdog total_time_watchdog_;  // Watching for excessive total_time.
125
126  DISALLOW_COPY_AND_ASSIGN(JankObserverHelper);
127};
128
129JankObserverHelper::JankObserverHelper(
130    const std::string& thread_name,
131    const TimeDelta& excessive_duration,
132    bool watchdog_enable)
133    : max_message_delay_(excessive_duration),
134      measure_current_message_(true),
135      events_till_measurement_(0),
136      slow_processing_counter_(std::string("Chrome.SlowMsg") + thread_name),
137      queueing_delay_counter_(std::string("Chrome.DelayMsg") + thread_name),
138      process_times_(base::Histogram::FactoryGet(
139          std::string("Chrome.ProcMsgL ") + thread_name,
140          1, 3600000, 50, base::Histogram::kUmaTargetedHistogramFlag)),
141      total_times_(base::Histogram::FactoryGet(
142          std::string("Chrome.TotalMsgL ") + thread_name,
143          1, 3600000, 50, base::Histogram::kUmaTargetedHistogramFlag)),
144      total_time_watchdog_(excessive_duration, thread_name, watchdog_enable) {
145  if (discard_count_ > 0) {
146    // Select a vaguely random sample-start-point.
147    events_till_measurement_ = static_cast<int>(
148        (TimeTicks::Now() - TimeTicks()).InSeconds() % (discard_count_ + 1));
149  }
150}
151
152JankObserverHelper::~JankObserverHelper() {}
153
154// Called when a message has just begun processing, initializes
155// per-message variables and timers.
156void JankObserverHelper::StartProcessingTimers(const TimeDelta& queueing_time) {
157  DCHECK(measure_current_message_);
158  begin_process_message_ = TimeTicks::Now();
159  queueing_time_ = queueing_time;
160
161  // Simulate arming when the message entered the queue.
162  total_time_watchdog_.ArmSomeTimeDeltaAgo(queueing_time_);
163  if (queueing_time_ > max_message_delay_) {
164    // Message is too delayed.
165    queueing_delay_counter_.Increment();
166#if defined(OS_WIN)
167    if (kPlaySounds)
168      MessageBeep(MB_ICONASTERISK);
169#endif
170  }
171}
172
173// Called when a message has just finished processing, finalizes
174// per-message variables and timers.
175void JankObserverHelper::EndProcessingTimers() {
176  if (!measure_current_message_)
177    return;
178  total_time_watchdog_.Disarm();
179  TimeTicks now = TimeTicks::Now();
180  if (begin_process_message_ != TimeTicks()) {
181    TimeDelta processing_time = now - begin_process_message_;
182    process_times_->AddTime(processing_time);
183    total_times_->AddTime(queueing_time_ + processing_time);
184  }
185  if (now - begin_process_message_ >
186      TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) {
187    // Message took too long to process.
188    slow_processing_counter_.Increment();
189#if defined(OS_WIN)
190    if (kPlaySounds)
191      MessageBeep(MB_ICONHAND);
192#endif
193  }
194
195  // Reset message specific times.
196  begin_process_message_ = base::TimeTicks();
197  queueing_time_ = base::TimeDelta();
198}
199
200bool JankObserverHelper::MessageWillBeMeasured() {
201  measure_current_message_ = events_till_measurement_ <= 0;
202  if (!measure_current_message_)
203    --events_till_measurement_;
204  else
205    events_till_measurement_ = discard_count_;
206  return measure_current_message_;
207}
208
209// static
210int JankObserverHelper::discard_count_ = 99;  // Measure only 1 in 100.
211
212//------------------------------------------------------------------------------
213class IOJankObserver : public base::RefCountedThreadSafe<IOJankObserver>,
214                       public MessageLoopForIO::IOObserver,
215                       public MessageLoop::TaskObserver {
216 public:
217  IOJankObserver(const char* thread_name,
218                 TimeDelta excessive_duration,
219                 bool watchdog_enable)
220      : helper_(thread_name, excessive_duration, watchdog_enable) {}
221
222  ~IOJankObserver() {}
223
224  // Attaches the observer to the current thread's message loop. You can only
225  // attach to the current thread, so this function can be invoked on another
226  // thread to attach it.
227  void AttachToCurrentThread() {
228    MessageLoop::current()->AddTaskObserver(this);
229    MessageLoopForIO::current()->AddIOObserver(this);
230  }
231
232  // Detaches the observer to the current thread's message loop.
233  void DetachFromCurrentThread() {
234    MessageLoopForIO::current()->RemoveIOObserver(this);
235    MessageLoop::current()->RemoveTaskObserver(this);
236  }
237
238  virtual void WillProcessIOEvent() {
239    if (!helper_.MessageWillBeMeasured())
240      return;
241    helper_.StartProcessingTimers(base::TimeDelta());
242  }
243
244  virtual void DidProcessIOEvent() {
245    helper_.EndProcessingTimers();
246  }
247
248  virtual void WillProcessTask(const Task* task) {
249    if (!helper_.MessageWillBeMeasured())
250      return;
251    base::TimeTicks now = base::TimeTicks::Now();
252    const base::TimeDelta queueing_time = now - task->tracked_birth_time();
253    helper_.StartProcessingTimers(queueing_time);
254  }
255
256  virtual void DidProcessTask(const Task* task) {
257    helper_.EndProcessingTimers();
258  }
259
260 private:
261  friend class base::RefCountedThreadSafe<IOJankObserver>;
262
263  JankObserverHelper helper_;
264
265  DISALLOW_COPY_AND_ASSIGN(IOJankObserver);
266};
267
268//------------------------------------------------------------------------------
269class UIJankObserver : public base::RefCountedThreadSafe<UIJankObserver>,
270                       public MessageLoop::TaskObserver,
271                       public MessageLoopForUI::Observer {
272 public:
273  UIJankObserver(const char* thread_name,
274                 TimeDelta excessive_duration,
275                 bool watchdog_enable)
276      : helper_(thread_name, excessive_duration, watchdog_enable) {}
277
278  // Attaches the observer to the current thread's message loop. You can only
279  // attach to the current thread, so this function can be invoked on another
280  // thread to attach it.
281  void AttachToCurrentThread() {
282    DCHECK_EQ(MessageLoop::current()->type(), MessageLoop::TYPE_UI);
283    MessageLoopForUI::current()->AddObserver(this);
284    MessageLoop::current()->AddTaskObserver(this);
285  }
286
287  // Detaches the observer to the current thread's message loop.
288  void DetachFromCurrentThread() {
289    DCHECK_EQ(MessageLoop::current()->type(), MessageLoop::TYPE_UI);
290    MessageLoop::current()->RemoveTaskObserver(this);
291    MessageLoopForUI::current()->RemoveObserver(this);
292  }
293
294  virtual void WillProcessTask(const Task* task) {
295    if (!helper_.MessageWillBeMeasured())
296      return;
297    base::TimeTicks now = base::TimeTicks::Now();
298    const base::TimeDelta queueing_time = now - task->tracked_birth_time();
299    helper_.StartProcessingTimers(queueing_time);
300  }
301
302  virtual void DidProcessTask(const Task* task) {
303    helper_.EndProcessingTimers();
304  }
305
306#if defined(OS_WIN)
307  virtual void WillProcessMessage(const MSG& msg) {
308    if (!helper_.MessageWillBeMeasured())
309      return;
310    // GetMessageTime returns a LONG (signed 32-bit) and GetTickCount returns
311    // a DWORD (unsigned 32-bit). They both wrap around when the time is longer
312    // than they can hold. I'm not sure if GetMessageTime wraps around to 0,
313    // or if the original time comes from GetTickCount, it might wrap around
314    // to -1.
315    //
316    // Therefore, I cast to DWORD so if it wraps to -1 we will correct it. If
317    // it doesn't, then our time delta will be negative if a message happens
318    // to straddle the wraparound point, it will still be OK.
319    DWORD cur_message_issue_time = static_cast<DWORD>(msg.time);
320    DWORD cur_time = GetTickCount();
321    base::TimeDelta queueing_time =
322        base::TimeDelta::FromMilliseconds(cur_time - cur_message_issue_time);
323
324    helper_.StartProcessingTimers(queueing_time);
325  }
326
327  virtual void DidProcessMessage(const MSG& msg) {
328    helper_.EndProcessingTimers();
329  }
330#elif defined(TOOLKIT_USES_GTK)
331  virtual void WillProcessEvent(GdkEvent* event) {
332    if (!helper_.MessageWillBeMeasured())
333      return;
334    // TODO(evanm): we want to set queueing_time_ using
335    // gdk_event_get_time, but how do you convert that info
336    // into a delta?
337    // guint event_time = gdk_event_get_time(event);
338    base::TimeDelta queueing_time = base::TimeDelta::FromMilliseconds(0);
339    helper_.StartProcessingTimers(queueing_time);
340  }
341
342  virtual void DidProcessEvent(GdkEvent* event) {
343    helper_.EndProcessingTimers();
344  }
345#endif
346
347 private:
348  friend class base::RefCountedThreadSafe<UIJankObserver>;
349
350  ~UIJankObserver() {}
351
352  JankObserverHelper helper_;
353
354  DISALLOW_COPY_AND_ASSIGN(UIJankObserver);
355};
356
357// These objects are created by InstallJankometer and leaked.
358const scoped_refptr<UIJankObserver>* ui_observer = NULL;
359const scoped_refptr<IOJankObserver>* io_observer = NULL;
360
361}  // namespace
362
363void InstallJankometer(const CommandLine& parsed_command_line) {
364  if (ui_observer || io_observer) {
365    NOTREACHED() << "Initializing jank-o-meter twice";
366    return;
367  }
368
369  bool ui_watchdog_enabled = false;
370  bool io_watchdog_enabled = false;
371  if (parsed_command_line.HasSwitch(switches::kEnableWatchdog)) {
372    std::string list =
373        parsed_command_line.GetSwitchValueASCII(switches::kEnableWatchdog);
374    if (list.npos != list.find("ui"))
375      ui_watchdog_enabled = true;
376    if (list.npos != list.find("io"))
377      io_watchdog_enabled = true;
378  }
379
380  if (ui_watchdog_enabled || io_watchdog_enabled)
381    JankObserverHelper::SetDefaultMessagesToSkip(0);  // Watch everything.
382
383  // Install on the UI thread.
384  ui_observer = new scoped_refptr<UIJankObserver>(
385      new UIJankObserver(
386          "UI",
387          TimeDelta::FromMilliseconds(kMaxUIMessageDelayMs),
388          ui_watchdog_enabled));
389  (*ui_observer)->AttachToCurrentThread();
390
391  // Now install on the I/O thread. Hiccups on that thread will block
392  // interaction with web pages. We must proxy to that thread before we can
393  // add our observer.
394  io_observer = new scoped_refptr<IOJankObserver>(
395      new IOJankObserver(
396          "IO",
397          TimeDelta::FromMilliseconds(kMaxIOMessageDelayMs),
398          io_watchdog_enabled));
399  BrowserThread::PostTask(
400      BrowserThread::IO, FROM_HERE,
401      NewRunnableMethod(io_observer->get(),
402                        &IOJankObserver::AttachToCurrentThread));
403}
404
405void UninstallJankometer() {
406  if (ui_observer) {
407    (*ui_observer)->DetachFromCurrentThread();
408    delete ui_observer;
409    ui_observer = NULL;
410  }
411  if (io_observer) {
412    // IO thread can't be running when we remove observers.
413    DCHECK((!g_browser_process) || !(g_browser_process->io_thread()));
414    delete io_observer;
415    io_observer = NULL;
416  }
417}
418