Home | History | Annotate | Download | only in browser 
      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 
     28 using base::TimeDelta;
     29 using base::TimeTicks;
     30 
     31 namespace {
     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
     41 const int kMaxUIMessageDelayMs = 350;
     42 const int kMaxIOMessageDelayMs = 200;
     43 #else
     44 const int kMaxUIMessageDelayMs = 500;
     45 const int kMaxIOMessageDelayMs = 400;
     46 #endif
     47 
     48 // Maximum processing time (excluding queueing delay) for a message before
     49 // considering it delayed.
     50 const int kMaxMessageProcessingMs = 100;
     51 
     52 // TODO(brettw) Consider making this a pref.
     53 const bool kPlaySounds = false;
     54 
     55 //------------------------------------------------------------------------------
     56 // Provide a special watchdog to make it easy to set the breakpoint on this
     57 // class only.
     58 class 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 
     84 class 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 
    129 JankObserverHelper::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 
    152 JankObserverHelper::~JankObserverHelper() {}
    153 
    154 // Called when a message has just begun processing, initializes
    155 // per-message variables and timers.
    156 void 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.
    175 void 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 
    200 bool 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
    210 int JankObserverHelper::discard_count_ = 99;  // Measure only 1 in 100.
    211 
    212 //------------------------------------------------------------------------------
    213 class 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 //------------------------------------------------------------------------------
    269 class 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.
    358 const scoped_refptr<UIJankObserver>* ui_observer = NULL;
    359 const scoped_refptr<IOJankObserver>* io_observer = NULL;
    360 
    361 }  // namespace
    362 
    363 void 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 
    405 void 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