Home | History | Annotate | Download | only in browser 
      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 }
    395