Changes to record via histograms when one watched thread is

not responding but all other watched threads are responding.

Each watched thread maintains unresponsive_count_ which is
set to zero when watched thread has responded with a pong
message. It is incremented by 1 whenever OnCheckResponsiveness
determines that the watched thread is not responding.

When unresponsive_count_ goes over kUnresponsiveCount, WatchDog
thread checks if all other threads are responding or not. If the
watched thread is the only thread that hasn't been responding and
all other threads are responding, then it records in histgorams
unresponsive_count_ for the watched thread.

WatchDog asks ThreadWatcherList (which has a list of all watched
threads) to see if all watched threads are responding or not.

BUG=79511
TEST=thread watcher unit tests
R=jar
Review URL: http://codereview.chromium.org/6857006

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

2 files changed, 116 insertions, 11 deletions

diff --git a/chrome/browser/metrics/thread_watcher.cc b/chrome/browser/metrics/thread_watcher.cc
index 8318f8c..fcc518a 100644
--- a/chrome/browser/metrics/thread_watcher.cc
+++ b/chrome/browser/metrics/thread_watcher.cc
@@ -25,10 +25,13 @@ ThreadWatcher::ThreadWatcher(const BrowserThread::ID& thread_id,
       sleep_time_(sleep_time),
       unresponsive_time_(unresponsive_time),
       ping_time_(base::TimeTicks::Now()),
+      pong_time_(ping_time_),
       ping_sequence_number_(0),
       active_(false),
       ping_count_(kPingCount),
-      histogram_(NULL),
+      response_time_histogram_(NULL),
+      unresponsive_time_histogram_(NULL),
+      unresponsive_count_(0),
       ALLOW_THIS_IN_INITIALIZER_LIST(method_factory_(this)) {
   Initialize();
 }
@@ -131,9 +134,14 @@ void ThreadWatcher::PostPingMessage() {
 
 void ThreadWatcher::OnPongMessage(uint64 ping_sequence_number) {
   DCHECK(WatchDogThread::CurrentlyOnWatchDogThread());
+
   // Record watched thread's response time.
-  base::TimeDelta response_time = base::TimeTicks::Now() - ping_time_;
-  histogram_->AddTime(response_time);
+  base::TimeTicks now = base::TimeTicks::Now();
+  base::TimeDelta response_time = now - ping_time_;
+  response_time_histogram_->AddTime(response_time);
+
+  // Save the current time when we have got pong message.
+  pong_time_ = now;
 
   // Check if there are any extra pings in flight.
   DCHECK_EQ(ping_sequence_number_, ping_sequence_number);
@@ -163,15 +171,39 @@ bool ThreadWatcher::OnCheckResponsiveness(uint64 ping_sequence_number) {
   // If the latest ping_sequence_number_ is not same as the ping_sequence_number
   // that is passed in, then we can assume OnPongMessage was called.
   // OnPongMessage increments ping_sequence_number_.
-  return ping_sequence_number_ != ping_sequence_number;
+  if (ping_sequence_number_ != ping_sequence_number) {
+    // Reset unresponsive_count_ to zero because we got a response from the
+    // watched thread.
+    GotGoodResponse();
+    return true;
+  }
+  // Record that we got no response from watched thread.
+  GotNoResponse();
+
+  // Post a task to check the responsiveness of watched thread.
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      method_factory_.NewRunnableMethod(
+          &ThreadWatcher::OnCheckResponsiveness, ping_sequence_number_),
+      unresponsive_time_.InMilliseconds());
+  return false;
 }
 
 void ThreadWatcher::Initialize() {
   ThreadWatcherList::Register(this);
-  const std::string histogram_name =
+
+  const std::string response_time_histogram_name =
       "ThreadWatcher.ResponseTime." + thread_name_;
-  histogram_ = base::Histogram::FactoryTimeGet(
-      histogram_name,
+  response_time_histogram_ = base::Histogram::FactoryTimeGet(
+      response_time_histogram_name,
+      base::TimeDelta::FromMilliseconds(1),
+      base::TimeDelta::FromSeconds(100), 50,
+      base::Histogram::kUmaTargetedHistogramFlag);
+
+  const std::string unresponsive_time_histogram_name =
+      "ThreadWatcher.Unresponsive." + thread_name_;
+  unresponsive_time_histogram_ = base::Histogram::FactoryTimeGet(
+      unresponsive_time_histogram_name,
       base::TimeDelta::FromMilliseconds(1),
       base::TimeDelta::FromSeconds(100), 50,
       base::Histogram::kUmaTargetedHistogramFlag);
@@ -185,10 +217,30 @@ void ThreadWatcher::OnPingMessage(const BrowserThread::ID& thread_id,
   WatchDogThread::PostTask(FROM_HERE, callback_task);
 }
 
+void ThreadWatcher::GotGoodResponse() {
+  DCHECK(WatchDogThread::CurrentlyOnWatchDogThread());
+  unresponsive_count_ = 0;
+}
+
+void ThreadWatcher::GotNoResponse() {
+  DCHECK(WatchDogThread::CurrentlyOnWatchDogThread());
+  ++unresponsive_count_;
+  // If watched thread is the only unresponsive thread and all other threads are
+  // responding then record total unresponsive_time since last pong message.
+  if (ThreadWatcherList::GetNumberOfUnresponsiveThreads() == 1) {
+    base::TimeDelta unresponse_time = base::TimeTicks::Now() - pong_time_;
+    unresponsive_time_histogram_->AddTime(unresponse_time);
+  }
+}
+
 // ThreadWatcherList methods and members.
 //
 // static
 ThreadWatcherList* ThreadWatcherList::global_ = NULL;
+// static
+const int ThreadWatcherList::kSleepSeconds = 2;
+// static
+const int ThreadWatcherList::kUnresponsiveSeconds = 4;
 
 ThreadWatcherList::ThreadWatcherList()
     : last_wakeup_time_(base::TimeTicks::Now()) {
@@ -227,12 +279,14 @@ void ThreadWatcherList::StartWatchingAll() {
     WatchDogThread::PostDelayedTask(
         FROM_HERE,
         NewRunnableFunction(&ThreadWatcherList::StartWatchingAll),
-        base::TimeDelta::FromSeconds(5).InMilliseconds());
+        base::TimeDelta::FromSeconds(kSleepSeconds).InMilliseconds());
     return;
   }
   DCHECK(WatchDogThread::CurrentlyOnWatchDogThread());
-  const base::TimeDelta kSleepTime = base::TimeDelta::FromSeconds(5);
-  const base::TimeDelta kUnresponsiveTime = base::TimeDelta::FromSeconds(10);
+  const base::TimeDelta kSleepTime =
+      base::TimeDelta::FromSeconds(kSleepSeconds);
+  const base::TimeDelta kUnresponsiveTime =
+      base::TimeDelta::FromSeconds(kUnresponsiveSeconds);
   if (BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
     ThreadWatcher::StartWatching(BrowserThread::UI, "UI", kSleepTime,
                                  kUnresponsiveTime);
@@ -283,6 +337,23 @@ void ThreadWatcherList::RemoveNotifications() {
   global_->registrar_.RemoveAll();
 }
 
+// static
+int ThreadWatcherList::GetNumberOfUnresponsiveThreads() {
+  DCHECK(WatchDogThread::CurrentlyOnWatchDogThread());
+  int no_of_unresponding_threads = 0;
+  if (!global_)
+    return no_of_unresponding_threads;
+
+  base::AutoLock auto_lock(global_->lock_);
+  for (RegistrationList::iterator it = global_->registered_.begin();
+       global_->registered_.end() != it;
+       ++it) {
+    if (it->second->unresponsive_count_ > 0)
+      ++no_of_unresponding_threads;
+  }
+  return no_of_unresponding_threads;
+}
+
 void ThreadWatcherList::DeleteAll() {
   DCHECK(WatchDogThread::CurrentlyOnWatchDogThread());
   base::AutoLock auto_lock(lock_);
diff --git a/chrome/browser/metrics/thread_watcher.h b/chrome/browser/metrics/thread_watcher.h
index 53cdb8d..5402c5f 100644
--- a/chrome/browser/metrics/thread_watcher.h
+++ b/chrome/browser/metrics/thread_watcher.h
@@ -149,6 +149,14 @@ class ThreadWatcher {
   static void OnPingMessage(const BrowserThread::ID& thread_id,
                             Task* callback_task);
 
+  // This method resets unresponsive_count_ to zero because watched thread is
+  // responding to the ping message with a pong message.
+  void GotGoodResponse();
+
+  // This method records watched thread is not responding to the ping message.
+  // It increments unresponsive_count_ by 1.
+  void GotNoResponse();
+
   // This is the number of ping messages to be sent when the user is idle.
   // ping_count_ will be initialized to kPingCount whenever user becomes active.
   static const int kPingCount;
@@ -171,6 +179,9 @@ class ThreadWatcher {
   // This is the last time when ping message was sent.
   base::TimeTicks ping_time_;
 
+  // This is the last time when we got pong message.
+  base::TimeTicks pong_time_;
+
   // This is the sequence number of the next ping for which there is no pong. If
   // the instance is sleeping, then it will be the sequence number for the next
   // ping.
@@ -186,7 +197,19 @@ class ThreadWatcher {
   int ping_count_;
 
   // Histogram that keeps track of response times for the watched thread.
-  base::Histogram* histogram_;
+  base::Histogram* response_time_histogram_;
+
+  // Histogram that keeps track of unresponsive time since the last pong message
+  // when we got no response (GotNoResponse) from the watched thread. We record
+  // this when the watched thread is the only unresponsive thread and all other
+  // threads are responsive.
+  base::Histogram* unresponsive_time_histogram_;
+
+  // This counter tracks the unresponsiveness of watched thread. If this value
+  // is zero then watched thread has responded with a pong message. This is
+  // incremented by 1 when we got no response (GotNoResponse) from the watched
+  // thread.
+  int unresponsive_count_;
 
   // We use this factory to create callback tasks for ThreadWatcher object. We
   // use this during ping-pong messaging between WatchDog thread and watched
@@ -231,6 +254,10 @@ class ThreadWatcherList : public NotificationObserver {
   // This method is accessible on UI thread.
   static void RemoveNotifications();
 
+  // This method returns number of watched threads that haven't responded with a
+  // pong message (number of threads with unresponsive_count_ greater than 0).
+  static int GetNumberOfUnresponsiveThreads();
+
  private:
   // Allow tests to access our innards for testing purposes.
   FRIEND_TEST_ALL_PREFIXES(ThreadWatcherTest, Registration);
@@ -262,6 +289,13 @@ class ThreadWatcherList : public NotificationObserver {
 
   static ThreadWatcherList* global_;  // The singleton of this class.
 
+  // This is the wait time between ping messages.
+  static const int kSleepSeconds;
+
+  // This is the wait time after ping message is sent, to check if we have
+  // received pong message or not.
+  static const int kUnresponsiveSeconds;
+
   // Lock for access to registered_.
   base::Lock lock_;