chrome/browser/jankometer.cc

   1 // Copyright (c) 2006-2008 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/histogram.h"
  12 #include "base/message_loop.h"
  13 #include "base/ref_counted.h"
  14 #include "base/stats_counters.h"
  15 #include "base/thread.h"
  16 #include "base/time.h"
  17 #include "base/watchdog.h"
  18 #include "chrome/browser/browser_process.h"
  19 #include "chrome/common/chrome_switches.h"
  20
  21 namespace {
  22
  23 // The maximum threshold of delay of the message  before considering it a delay.
  24 // For a debug build, you may want to set IO delay around 500ms.
  25 // For a release build, setting it around 350ms is sensible.
  26 // Visit about:histograms to see what the distribution is on your system, with
  27 // your build. Be sure to do some work to get interesting stats.
  28 // The numbers below came from a warm start (you'll get about 5-10 alarms with
  29 // a cold start), and running the page-cycler for 5 rounds.
  30 #ifdef NDEBUG
  31 const int kMaxUIMessageDelayMs = 350;
  32 const int kMaxIOMessageDelayMs = 200;
  33 #else
  34 const int kMaxUIMessageDelayMs = 500;
  35 const int kMaxIOMessageDelayMs = 400;
  36 #endif
  37
  38 // Maximum processing time (excluding queueing delay) for a message before
  39 // considering it delayed.
  40 const int kMaxMessageProcessingMs = 100;
  41
  42 // TODO(brettw) Consider making this a pref.
  43 const bool kPlaySounds = false;
  44
  45 //------------------------------------------------------------------------------
  46 // Provide a special watchdog to make it easy to set the breakpoint on this
  47 // class only.
  48 class JankWatchdog : public Watchdog {
  49  public:
  50   JankWatchdog(const TimeDelta& duration,
  51                const std::wstring& thread_watched_name,
  52                bool enabled)
  53       : Watchdog(duration, thread_watched_name, enabled),
  54         thread_name_watched_(thread_watched_name),
  55         alarm_count_(0) {
  56   }
  57
  58   virtual ~JankWatchdog() {}
  59
  60   virtual void Alarm() {
  61     // Put break point here if you want to stop threads and look at what caused
  62     // the jankiness.
  63     alarm_count_++;
  64     Watchdog::Alarm();
  65   }
  66
  67  private:
  68   std::wstring thread_name_watched_;
  69   int alarm_count_;
  70
  71   DISALLOW_EVIL_CONSTRUCTORS(JankWatchdog);
  72 };
  73
  74 //------------------------------------------------------------------------------
  75 class JankObserver : public base::RefCountedThreadSafe<JankObserver>,
  76                      public MessageLoopForUI::Observer {
  77  public:
  78   JankObserver(const wchar_t* thread_name,
  79                const TimeDelta& excessive_duration,
  80                bool watchdog_enable)
  81       : MaxMessageDelay_(excessive_duration),
  82         slow_processing_counter_(std::wstring(L"Chrome.SlowMsg") + thread_name),
  83         queueing_delay_counter_(std::wstring(L"Chrome.DelayMsg") + thread_name),
  84         process_times_((std::wstring(L"Chrome.ProcMsgL ")
  85                         + thread_name).c_str(), 1, 3600000, 50),
  86         total_times_((std::wstring(L"Chrome.TotalMsgL ")
  87                       + thread_name).c_str(), 1, 3600000, 50),
  88         total_time_watchdog_(excessive_duration, std::wstring(thread_name),
  89                              watchdog_enable) {
  90     process_times_.SetFlags(kUmaTargetedHistogramFlag);
  91     total_times_.SetFlags(kUmaTargetedHistogramFlag);
  92   }
  93
  94   // Attaches the observer to the current thread's message loop. You can only
  95   // attach to the current thread, so this function can be invoked on another
  96   // thread to attach it.
  97   void AttachToCurrentThread() {
  98     // TODO(darin): support monitoring jankiness on non-UI threads!
  99     if (MessageLoop::current()->type() == MessageLoop::TYPE_UI)
 100       MessageLoopForUI::current()->AddObserver(this);
 101   }
 102
 103   // Detaches the observer to the current thread's message loop.
 104   void DetachFromCurrentThread() {
 105     if (MessageLoop::current()->type() == MessageLoop::TYPE_UI)
 106       MessageLoopForUI::current()->RemoveObserver(this);
 107   }
 108
 109   void WillProcessMessage(const MSG& msg) {
 110     begin_process_message_ = TimeTicks::Now();
 111
 112     // GetMessageTime returns a LONG (signed 32-bit) and GetTickCount returns
 113     // a DWORD (unsigned 32-bit). They both wrap around when the time is longer
 114     // than they can hold. I'm not sure if GetMessageTime wraps around to 0,
 115     // or if the original time comes from GetTickCount, it might wrap around
 116     // to -1.
 117     //
 118     // Therefore, I cast to DWORD so if it wraps to -1 we will correct it. If
 119     // it doesn't, then our time delta will be negative if a message happens
 120     // to straddle the wraparound point, it will still be OK.
 121     DWORD cur_message_issue_time = static_cast<DWORD>(msg.time);
 122     DWORD cur_time = GetTickCount();
 123     queueing_time_ = TimeDelta::FromMilliseconds(cur_time
 124                                                  - cur_message_issue_time);
 125     // Simulate arming when the message entered the queue.
 126     total_time_watchdog_.ArmSomeTimeDeltaAgo(queueing_time_);
 127     if (queueing_time_ > MaxMessageDelay_) {
 128       // Message is too delayed.
 129       queueing_delay_counter_.Increment();
 130       if (kPlaySounds)
 131         MessageBeep(MB_ICONASTERISK);
 132     }
 133   }
 134
 135   void DidProcessMessage(const MSG& msg) {
 136     total_time_watchdog_.Disarm();
 137     TimeTicks now = TimeTicks::Now();
 138     if (begin_process_message_ != TimeTicks()) {
 139       TimeDelta processing_time = now - begin_process_message_;
 140       process_times_.AddTime(processing_time);
 141       total_times_.AddTime(queueing_time_ + processing_time);
 142     }
 143     if (now - begin_process_message_ >
 144         TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) {
 145       // Message took too long to process.
 146       slow_processing_counter_.Increment();
 147       if (kPlaySounds)
 148         MessageBeep(MB_ICONHAND);
 149     }
 150   }
 151
 152  private:
 153   const TimeDelta MaxMessageDelay_;
 154   TimeTicks begin_process_message_;
 155   TimeDelta queueing_time_;
 156
 157   // Counters for the two types of jank we measure.
 158   StatsCounter slow_processing_counter_;  // Messages with long processing time.
 159   StatsCounter queueing_delay_counter_;   // Messages with long queueing delay.
 160   Histogram process_times_;           // Time spent processing task.
 161   Histogram total_times_;             // Total of queueing plus processing time.
 162   JankWatchdog total_time_watchdog_;  // Watching for excessive total_time.
 163
 164   DISALLOW_EVIL_CONSTRUCTORS(JankObserver);
 165 };
 166
 167 // These objects are created by InstallJankometer and leaked.
 168 JankObserver* ui_observer = NULL;
 169 JankObserver* io_observer = NULL;
 170
 171 }  // namespace
 172
 173 void InstallJankometer(const CommandLine &parsed_command_line) {
 174   if (ui_observer || io_observer) {
 175     NOTREACHED() << "Initializing jank-o-meter twice";
 176     return;
 177   }
 178
 179   bool ui_watchdog_enabled = false;
 180   bool io_watchdog_enabled = false;
 181   if (parsed_command_line.HasSwitch(switches::kEnableWatchdog)) {
 182     std::wstring list =
 183         parsed_command_line.GetSwitchValue(switches::kEnableWatchdog);
 184     if (list.npos != list.find(L"ui"))
 185       ui_watchdog_enabled = true;
 186     if (list.npos != list.find(L"io"))
 187       io_watchdog_enabled = true;
 188   }
 189
 190   // Install on the UI thread.
 191   ui_observer = new JankObserver(
 192       L"UI",
 193       TimeDelta::FromMilliseconds(kMaxUIMessageDelayMs),
 194       ui_watchdog_enabled);
 195   ui_observer->AddRef();
 196   ui_observer->AttachToCurrentThread();
 197
 198   // Now install on the I/O thread. Hiccups on that thread will block
 199   // interaction with web pages. We must proxy to that thread before we can
 200   // add our observer.
 201   io_observer = new JankObserver(
 202       L"IO",
 203       TimeDelta::FromMilliseconds(kMaxIOMessageDelayMs),
 204       io_watchdog_enabled);
 205   io_observer->AddRef();
 206   base::Thread* io_thread = g_browser_process->io_thread();
 207   if (io_thread) {
 208     io_thread->message_loop()->PostTask(FROM_HERE,
 209         NewRunnableMethod(io_observer,
 210             &JankObserver::AttachToCurrentThread));
 211   }
 212 }
 213
 214 void UninstallJankometer() {
 215   if (ui_observer) {
 216     ui_observer->DetachFromCurrentThread();
 217     ui_observer->Release();
 218     ui_observer = NULL;
 219   }
 220   if (io_observer) {
 221     // IO thread can't be running when we remove observers.
 222     DCHECK((!g_browser_process) || !(g_browser_process->io_thread()));
 223     io_observer->Release();
 224     io_observer = NULL;
 225   }
 226 }
 227