Jankometer: Generalize the code more. Add better support for monitoring IO thread.

Previously, the Jankometer only monitored windows messages on the UI thread (or gtk events).
I've added observers for tasks and IO events.  This lets us monitor all events on UI & IO threads (UI messages, all Tasks, and IO events).
Replaces the JankObserver with a UIJankObserver and an IOJankObserver.
Shares common code in JankObserverHelper.  The JankObserverHelper and JankWatchdog are generic enough that they can probably move out to chrome/common and be reused by the renderer.

Review URL: http://codereview.chromium.org/2098020

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@49188 0039d316-1c4b-4281-b951-d872f2087c98

1 files changed, 189 insertions, 96 deletions

diff --git a/chrome/browser/jankometer.cc b/chrome/browser/jankometer.cc
index 97816ad..d4a70a2 100644
--- a/chrome/browser/jankometer.cc
+++ b/chrome/browser/jankometer.cc
@@ -81,80 +81,187 @@ class JankWatchdog : public Watchdog {
   DISALLOW_COPY_AND_ASSIGN(JankWatchdog);
 };
 
+class JankObserverHelper {
+ public:
+  JankObserverHelper(const std::string& thread_name,
+                     const TimeDelta& excessive_duration,
+                     bool watchdog_enable);
+  ~JankObserverHelper();
+
+  void StartProcessingTimers(const TimeDelta& queueing_time);
+  void EndProcessingTimers();
+
+ private:
+  const TimeDelta max_message_delay_;
+
+  // Time at which the current message processing began.
+  TimeTicks begin_process_message_;
+
+  // Time the current message spent in the queue -- delta between message
+  // construction time and message processing time.
+  TimeDelta queueing_time_;
+
+  // Counters for the two types of jank we measure.
+  StatsCounter slow_processing_counter_;  // Messages with long processing time.
+  StatsCounter queueing_delay_counter_;   // Messages with long queueing delay.
+  scoped_refptr<Histogram> process_times_;  // Time spent processing task.
+  scoped_refptr<Histogram> total_times_;  // Total queueing plus processing.
+  JankWatchdog total_time_watchdog_;  // Watching for excessive total_time.
+
+  DISALLOW_COPY_AND_ASSIGN(JankObserverHelper);
+};
+
+JankObserverHelper::JankObserverHelper(
+    const std::string& thread_name,
+    const TimeDelta& excessive_duration,
+    bool watchdog_enable)
+    : max_message_delay_(excessive_duration),
+      slow_processing_counter_(std::string("Chrome.SlowMsg") + thread_name),
+      queueing_delay_counter_(std::string("Chrome.DelayMsg") + thread_name),
+      total_time_watchdog_(excessive_duration, thread_name, watchdog_enable) {
+  process_times_ = Histogram::FactoryGet(
+      std::string("Chrome.ProcMsgL ") + thread_name,
+      1, 3600000, 50, Histogram::kUmaTargetedHistogramFlag);
+  total_times_ = Histogram::FactoryGet(
+      std::string("Chrome.TotalMsgL ") + thread_name,
+      1, 3600000, 50, Histogram::kUmaTargetedHistogramFlag);
+}
+
+JankObserverHelper::~JankObserverHelper() {}
+
+// Called when a message has just begun processing, initializes
+// per-message variables and timers.
+void JankObserverHelper::StartProcessingTimers(const TimeDelta& queueing_time) {
+  begin_process_message_ = TimeTicks::Now();
+  queueing_time_ = queueing_time;
+
+  // Simulate arming when the message entered the queue.
+  total_time_watchdog_.ArmSomeTimeDeltaAgo(queueing_time_);
+  if (queueing_time_ > max_message_delay_) {
+    // Message is too delayed.
+    queueing_delay_counter_.Increment();
+#if defined(OS_WIN)
+    if (kPlaySounds)
+      MessageBeep(MB_ICONASTERISK);
+#endif
+  }
+}
+
+// Called when a message has just finished processing, finalizes
+// per-message variables and timers.
+void JankObserverHelper::EndProcessingTimers() {
+  total_time_watchdog_.Disarm();
+  TimeTicks now = TimeTicks::Now();
+  if (begin_process_message_ != TimeTicks()) {
+    TimeDelta processing_time = now - begin_process_message_;
+    process_times_->AddTime(processing_time);
+    total_times_->AddTime(queueing_time_ + processing_time);
+  }
+  if (now - begin_process_message_ >
+      TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) {
+    // Message took too long to process.
+    slow_processing_counter_.Increment();
+#if defined(OS_WIN)
+    if (kPlaySounds)
+      MessageBeep(MB_ICONHAND);
+#endif
+  }
+
+  // Reset message specific times.
+  begin_process_message_ = base::TimeTicks();
+  queueing_time_ = base::TimeDelta();
+}
+
 //------------------------------------------------------------------------------
-class JankObserver : public base::RefCountedThreadSafe<JankObserver>,
-                     public MessageLoopForUI::Observer {
+class IOJankObserver : public base::RefCountedThreadSafe<IOJankObserver>,
+                       public MessageLoopForIO::IOObserver,
+                       public MessageLoop::TaskObserver {
  public:
-  JankObserver(const char* thread_name,
-               const TimeDelta& excessive_duration,
-               bool watchdog_enable)
-      : MaxMessageDelay_(excessive_duration),
-        slow_processing_counter_(std::string("Chrome.SlowMsg") + thread_name),
-        queueing_delay_counter_(std::string("Chrome.DelayMsg") + thread_name),
-        total_time_watchdog_(excessive_duration, thread_name, watchdog_enable) {
-    process_times_ = Histogram::FactoryGet(
-        std::string("Chrome.ProcMsgL ") + thread_name,
-        1, 3600000, 50, Histogram::kUmaTargetedHistogramFlag);
-    total_times_ = Histogram::FactoryGet(
-        std::string("Chrome.TotalMsgL ") + thread_name,
-        1, 3600000, 50, Histogram::kUmaTargetedHistogramFlag);
+  IOJankObserver(const char* thread_name,
+                 TimeDelta excessive_duration,
+                 bool watchdog_enable)
+      : helper_(thread_name, excessive_duration, watchdog_enable) {}
+
+  ~IOJankObserver() {}
+
+  // Attaches the observer to the current thread's message loop. You can only
+  // attach to the current thread, so this function can be invoked on another
+  // thread to attach it.
+  void AttachToCurrentThread() {
+    MessageLoop::current()->AddTaskObserver(this);
+    MessageLoopForIO::current()->AddIOObserver(this);
+  }
+
+  // Detaches the observer to the current thread's message loop.
+  void DetachFromCurrentThread() {
+    MessageLoopForIO::current()->RemoveIOObserver(this);
+    MessageLoop::current()->RemoveTaskObserver(this);
   }
 
+  virtual void WillProcessIOEvent() {
+    helper_.StartProcessingTimers(base::TimeDelta());
+  }
+
+  virtual void DidProcessIOEvent() {
+    helper_.EndProcessingTimers();
+  }
+
+  virtual void WillProcessTask(base::TimeTicks birth_time) {
+    base::TimeTicks now = base::TimeTicks::Now();
+    const base::TimeDelta queueing_time = now - birth_time;
+    helper_.StartProcessingTimers(queueing_time);
+  }
+
+  virtual void DidProcessTask() {
+    helper_.EndProcessingTimers();
+  }
+
+ private:
+  friend class base::RefCountedThreadSafe<IOJankObserver>;
+
+  JankObserverHelper helper_;
+
+  DISALLOW_COPY_AND_ASSIGN(IOJankObserver);
+};
+
+//------------------------------------------------------------------------------
+class UIJankObserver : public base::RefCountedThreadSafe<UIJankObserver>,
+                       public MessageLoop::TaskObserver,
+                       public MessageLoopForUI::Observer {
+ public:
+  UIJankObserver(const char* thread_name,
+                 TimeDelta excessive_duration,
+                 bool watchdog_enable)
+      : helper_(thread_name, excessive_duration, watchdog_enable) {}
+
   // Attaches the observer to the current thread's message loop. You can only
   // attach to the current thread, so this function can be invoked on another
   // thread to attach it.
   void AttachToCurrentThread() {
-    // TODO(darin): support monitoring jankiness on non-UI threads!
-    if (MessageLoop::current()->type() == MessageLoop::TYPE_UI)
-      MessageLoopForUI::current()->AddObserver(this);
+    DCHECK_EQ(MessageLoop::current()->type(), MessageLoop::TYPE_UI);
+    MessageLoopForUI::current()->AddObserver(this);
+    MessageLoop::current()->AddTaskObserver(this);
   }
 
   // Detaches the observer to the current thread's message loop.
   void DetachFromCurrentThread() {
-    if (MessageLoop::current()->type() == MessageLoop::TYPE_UI)
-      MessageLoopForUI::current()->RemoveObserver(this);
+    DCHECK_EQ(MessageLoop::current()->type(), MessageLoop::TYPE_UI);
+    MessageLoop::current()->RemoveTaskObserver(this);
+    MessageLoopForUI::current()->RemoveObserver(this);
   }
 
-  // Called when a message has just begun processing, initializes
-  // per-message variables and timers.
-  void StartProcessingTimers() {
-    // Simulate arming when the message entered the queue.
-    total_time_watchdog_.ArmSomeTimeDeltaAgo(queueing_time_);
-    if (queueing_time_ > MaxMessageDelay_) {
-      // Message is too delayed.
-      queueing_delay_counter_.Increment();
-#if defined(OS_WIN)
-      if (kPlaySounds)
-        MessageBeep(MB_ICONASTERISK);
-#endif
-    }
+  virtual void WillProcessTask(base::TimeTicks birth_time) {
+    base::TimeTicks now = base::TimeTicks::Now();
+    const base::TimeDelta queueing_time = now - birth_time;
+    helper_.StartProcessingTimers(queueing_time);
   }
 
-  // Called when a message has just finished processing, finalizes
-  // per-message variables and timers.
-  void EndProcessingTimers() {
-    total_time_watchdog_.Disarm();
-    TimeTicks now = TimeTicks::Now();
-    if (begin_process_message_ != TimeTicks()) {
-      TimeDelta processing_time = now - begin_process_message_;
-      process_times_->AddTime(processing_time);
-      total_times_->AddTime(queueing_time_ + processing_time);
-    }
-    if (now - begin_process_message_ >
-        TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) {
-      // Message took too long to process.
-      slow_processing_counter_.Increment();
-#if defined(OS_WIN)
-      if (kPlaySounds)
-        MessageBeep(MB_ICONHAND);
-#endif
-    }
+  virtual void DidProcessTask() {
+    helper_.EndProcessingTimers();
   }
 
 #if defined(OS_WIN)
   virtual void WillProcessMessage(const MSG& msg) {
-    begin_process_message_ = TimeTicks::Now();
-
     // GetMessageTime returns a LONG (signed 32-bit) and GetTickCount returns
     // a DWORD (unsigned 32-bit). They both wrap around when the time is longer
     // than they can hold. I'm not sure if GetMessageTime wraps around to 0,
@@ -166,58 +273,43 @@ class JankObserver : public base::RefCountedThreadSafe<JankObserver>,
     // to straddle the wraparound point, it will still be OK.
     DWORD cur_message_issue_time = static_cast<DWORD>(msg.time);
     DWORD cur_time = GetTickCount();
-    queueing_time_ =
+    base::TimeDelta queueing_time =
         base::TimeDelta::FromMilliseconds(cur_time - cur_message_issue_time);
 
-    StartProcessingTimers();
+    helper_.StartProcessingTimers(queueing_time);
   }
 
   virtual void DidProcessMessage(const MSG& msg) {
-    EndProcessingTimers();
+    helper_.EndProcessingTimers();
   }
 #elif defined(TOOLKIT_USES_GTK)
   virtual void WillProcessEvent(GdkEvent* event) {
-    begin_process_message_ = TimeTicks::Now();
     // TODO(evanm): we want to set queueing_time_ using
     // gdk_event_get_time, but how do you convert that info
     // into a delta?
     // guint event_time = gdk_event_get_time(event);
-    queueing_time_ = base::TimeDelta::FromMilliseconds(0);
-    StartProcessingTimers();
+    base::TimeDelta queueing_time = base::TimeDelta::FromMilliseconds(0);
+    helper_.StartProcessingTimers(queueing_time);
   }
 
   virtual void DidProcessEvent(GdkEvent* event) {
-    EndProcessingTimers();
+    helper_.EndProcessingTimers();
   }
 #endif
 
  private:
-  friend class base::RefCountedThreadSafe<JankObserver>;
-
-  ~JankObserver() {}
-
-  const TimeDelta MaxMessageDelay_;
-
-  // Time at which the current message processing began.
-  TimeTicks begin_process_message_;
+  friend class base::RefCountedThreadSafe<UIJankObserver>;
 
-  // Time the current message spent in the queue -- delta between message
-  // construction time and message processing time.
-  TimeDelta queueing_time_;
+  ~UIJankObserver() {}
 
-  // Counters for the two types of jank we measure.
-  StatsCounter slow_processing_counter_;  // Messages with long processing time.
-  StatsCounter queueing_delay_counter_;   // Messages with long queueing delay.
-  scoped_refptr<Histogram> process_times_;  // Time spent processing task.
-  scoped_refptr<Histogram> total_times_;  // Total queueing plus processing.
-  JankWatchdog total_time_watchdog_;  // Watching for excessive total_time.
+  JankObserverHelper helper_;
 
-  DISALLOW_COPY_AND_ASSIGN(JankObserver);
+  DISALLOW_COPY_AND_ASSIGN(UIJankObserver);
 };
 
 // These objects are created by InstallJankometer and leaked.
-JankObserver* ui_observer = NULL;
-JankObserver* io_observer = NULL;
+const scoped_refptr<UIJankObserver>* ui_observer = NULL;
+const scoped_refptr<IOJankObserver>* io_observer = NULL;
 
 }  // namespace
 
@@ -239,36 +331,37 @@ void InstallJankometer(const CommandLine& parsed_command_line) {
   }
 
   // Install on the UI thread.
-  ui_observer = new JankObserver(
-      "UI",
-      TimeDelta::FromMilliseconds(kMaxUIMessageDelayMs),
-      ui_watchdog_enabled);
-  ui_observer->AddRef();
-  ui_observer->AttachToCurrentThread();
+  ui_observer = new scoped_refptr<UIJankObserver>(
+      new UIJankObserver(
+          "UI",
+          TimeDelta::FromMilliseconds(kMaxUIMessageDelayMs),
+          ui_watchdog_enabled));
+  (*ui_observer)->AttachToCurrentThread();
 
   // Now install on the I/O thread. Hiccups on that thread will block
   // interaction with web pages. We must proxy to that thread before we can
   // add our observer.
-  io_observer = new JankObserver(
-      "IO",
-      TimeDelta::FromMilliseconds(kMaxIOMessageDelayMs),
-      io_watchdog_enabled);
-  io_observer->AddRef();
+  io_observer = new scoped_refptr<IOJankObserver>(
+      new IOJankObserver(
+          "IO",
+          TimeDelta::FromMilliseconds(kMaxIOMessageDelayMs),
+          io_watchdog_enabled));
   ChromeThread::PostTask(
       ChromeThread::IO, FROM_HERE,
-      NewRunnableMethod(io_observer, &JankObserver::AttachToCurrentThread));
+      NewRunnableMethod(io_observer->get(),
+                        &IOJankObserver::AttachToCurrentThread));
 }
 
 void UninstallJankometer() {
   if (ui_observer) {
-    ui_observer->DetachFromCurrentThread();
-    ui_observer->Release();
+    (*ui_observer)->DetachFromCurrentThread();
+    delete ui_observer;
     ui_observer = NULL;
   }
   if (io_observer) {
     // IO thread can't be running when we remove observers.
     DCHECK((!g_browser_process) || !(g_browser_process->io_thread()));
-    io_observer->Release();
+    delete io_observer;
     io_observer = NULL;
   }
 }