chrome/browser/jankometer_win.cc

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