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