Home | History | Annotate | Download | only in metrics 
      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 "base/basictypes.h"
      6 #include "base/logging.h"
      7 #include "base/memory/scoped_ptr.h"
      8 #include "base/message_loop.h"
      9 #include "base/message_loop_proxy.h"
     10 #include "base/synchronization/condition_variable.h"
     11 #include "base/synchronization/lock.h"
     12 #include "base/threading/platform_thread.h"
     13 #include "base/time.h"
     14 #include "build/build_config.h"
     15 #include "chrome/browser/metrics/thread_watcher.h"
     16 #include "testing/gtest/include/gtest/gtest.h"
     17 #include "testing/platform_test.h"
     18 
     19 using base::TimeDelta;
     20 using base::TimeTicks;
     21 
     22 enum State {
     23   INITIALIZED,        // Created ThreadWatch object.
     24   ACTIVATED,          // Thread watching activated.
     25   SENT_PING,          // Sent ping message to watched thread.
     26   RECEIVED_PONG,      // Received Pong message.
     27   DEACTIVATED,        // Thread watching de-activated.
     28 };
     29 
     30 enum WaitState {
     31   UNINITIALIZED,
     32   STARTED_WAITING,    // Start waiting for state_ to change to expected_state.
     33   STOPPED_WAITING,    // Done with the waiting.
     34   ALL_DONE,           // Done with waiting for STOPPED_WAITING.
     35 };
     36 
     37 enum CheckResponseState {
     38   UNKNOWN,
     39   SUCCESSFUL,         // CheckResponse was successful.
     40   FAILED,             // CheckResponse has failed.
     41 };
     42 
     43 // This class helps to track and manipulate thread state during tests. This
     44 // class also has utility method to simulate hanging of watched thread by making
     45 // the watched thread wait for a very long time by posting a task on watched
     46 // thread that keeps it busy. It also has an utility method to block running of
     47 // tests until ThreadWatcher object's post-condition state changes to an
     48 // expected state.
     49 class CustomThreadWatcher : public ThreadWatcher {
     50  public:
     51   base::Lock custom_lock_;
     52   base::ConditionVariable state_changed_;
     53   State thread_watcher_state_;
     54   WaitState wait_state_;
     55   CheckResponseState check_response_state_;
     56   uint64 ping_sent_;
     57   uint64 pong_received_;
     58   uint64 success_response_;
     59   uint64 failed_response_;
     60   base::TimeTicks saved_ping_time_;
     61   uint64 saved_ping_sequence_number_;
     62 
     63   CustomThreadWatcher(const BrowserThread::ID thread_id,
     64                       const std::string thread_name,
     65                       const TimeDelta& sleep_time,
     66                       const TimeDelta& unresponsive_time)
     67       : ThreadWatcher(thread_id, thread_name, sleep_time, unresponsive_time),
     68         state_changed_(&custom_lock_),
     69         thread_watcher_state_(INITIALIZED),
     70         wait_state_(UNINITIALIZED),
     71         check_response_state_(UNKNOWN),
     72         ping_sent_(0),
     73         pong_received_(0),
     74         success_response_(0),
     75         failed_response_(0),
     76         saved_ping_time_(base::TimeTicks::Now()),
     77         saved_ping_sequence_number_(0) {
     78   }
     79 
     80   State UpdateState(State new_state) {
     81     State old_state;
     82     {
     83       base::AutoLock auto_lock(custom_lock_);
     84       old_state = thread_watcher_state_;
     85       if (old_state != DEACTIVATED)
     86         thread_watcher_state_ = new_state;
     87       if (new_state == SENT_PING)
     88         ++ping_sent_;
     89       if (new_state == RECEIVED_PONG)
     90         ++pong_received_;
     91       saved_ping_time_ = ping_time();
     92       saved_ping_sequence_number_ = ping_sequence_number();
     93     }
     94     state_changed_.Broadcast();
     95     return old_state;
     96   }
     97 
     98   WaitState UpdateWaitState(WaitState new_state) {
     99     WaitState old_state;
    100     {
    101       base::AutoLock auto_lock(custom_lock_);
    102       old_state = wait_state_;
    103       wait_state_ = new_state;
    104     }
    105     state_changed_.Broadcast();
    106     return old_state;
    107   }
    108 
    109   void ActivateThreadWatching() {
    110     State old_state = UpdateState(ACTIVATED);
    111     EXPECT_EQ(old_state, INITIALIZED);
    112     ThreadWatcher::ActivateThreadWatching();
    113   }
    114 
    115   void DeActivateThreadWatching() {
    116     State old_state = UpdateState(DEACTIVATED);
    117     EXPECT_TRUE(old_state == ACTIVATED || old_state == SENT_PING ||
    118                 old_state == RECEIVED_PONG);
    119     ThreadWatcher::DeActivateThreadWatching();
    120   }
    121 
    122   void PostPingMessage() {
    123     State old_state = UpdateState(SENT_PING);
    124     EXPECT_TRUE(old_state == ACTIVATED || old_state == RECEIVED_PONG);
    125     ThreadWatcher::PostPingMessage();
    126   }
    127 
    128   void OnPongMessage(uint64 ping_sequence_number) {
    129     State old_state = UpdateState(RECEIVED_PONG);
    130     EXPECT_TRUE(old_state == SENT_PING || old_state == DEACTIVATED);
    131     ThreadWatcher::OnPongMessage(ping_sequence_number);
    132   }
    133 
    134   bool OnCheckResponsiveness(uint64 ping_sequence_number) {
    135     bool responsive =
    136         ThreadWatcher::OnCheckResponsiveness(ping_sequence_number);
    137     {
    138       base::AutoLock auto_lock(custom_lock_);
    139       if (responsive) {
    140         ++success_response_;
    141         check_response_state_ = SUCCESSFUL;
    142       } else {
    143         ++failed_response_;
    144         check_response_state_ = FAILED;
    145       }
    146     }
    147     // Broadcast to indicate we have checked responsiveness of the thread that
    148     // is watched.
    149     state_changed_.Broadcast();
    150     return responsive;
    151   }
    152 
    153   void WaitForWaitStateChange(TimeDelta wait_time, WaitState expected_state) {
    154     DCHECK(!WatchDogThread::CurrentlyOnWatchDogThread());
    155     TimeTicks end_time = TimeTicks::Now() + wait_time;
    156     {
    157       base::AutoLock auto_lock(custom_lock_);
    158       while (wait_state_ != expected_state && TimeTicks::Now() < end_time)
    159         state_changed_.TimedWait(end_time - TimeTicks::Now());
    160     }
    161   }
    162 
    163   void VeryLongMethod(TimeDelta wait_time) {
    164     DCHECK(!WatchDogThread::CurrentlyOnWatchDogThread());
    165     WaitForWaitStateChange(wait_time, STOPPED_WAITING);
    166     UpdateWaitState(ALL_DONE);
    167   }
    168 
    169   State WaitForStateChange(const TimeDelta& wait_time, State expected_state) {
    170     DCHECK(!WatchDogThread::CurrentlyOnWatchDogThread());
    171     UpdateWaitState(STARTED_WAITING);
    172 
    173     State exit_state;
    174     // Keep the thread that is running the tests waiting until ThreadWatcher
    175     // object's state changes to the expected_state or until wait_time elapses.
    176     for (int i = 0; i < 3; ++i) {
    177         TimeTicks end_time = TimeTicks::Now() + wait_time;
    178         {
    179           base::AutoLock auto_lock(custom_lock_);
    180           while (thread_watcher_state_ != expected_state &&
    181                  TimeTicks::Now() < end_time) {
    182             TimeDelta state_change_wait_time = end_time - TimeTicks::Now();
    183             state_changed_.TimedWait(state_change_wait_time);
    184           }
    185           // Capture the thread_watcher_state_ before it changes and return it
    186           // to the caller.
    187           exit_state = thread_watcher_state_;
    188           if (exit_state == expected_state)
    189             break;
    190         }
    191     }
    192     UpdateWaitState(STOPPED_WAITING);
    193     return exit_state;
    194   }
    195 
    196   CheckResponseState WaitForCheckResponse(const TimeDelta& wait_time,
    197                                           CheckResponseState expected_state) {
    198     DCHECK(!WatchDogThread::CurrentlyOnWatchDogThread());
    199     UpdateWaitState(STARTED_WAITING);
    200 
    201     CheckResponseState exit_state;
    202     // Keep the thread that is running the tests waiting until ThreadWatcher
    203     // object's check_response_state_ changes to the expected_state or until
    204     // wait_time elapses.
    205     for (int i = 0; i < 3; ++i) {
    206         TimeTicks end_time = TimeTicks::Now() + wait_time;
    207         {
    208           base::AutoLock auto_lock(custom_lock_);
    209           while (check_response_state_ != expected_state &&
    210                  TimeTicks::Now() < end_time) {
    211             TimeDelta state_change_wait_time = end_time - TimeTicks::Now();
    212             state_changed_.TimedWait(state_change_wait_time);
    213           }
    214           // Capture the check_response_state_ before it changes and return it
    215           // to the caller.
    216           exit_state = check_response_state_;
    217           if (exit_state == expected_state)
    218             break;
    219         }
    220     }
    221     UpdateWaitState(STOPPED_WAITING);
    222     return exit_state;
    223   }
    224 };
    225 
    226 DISABLE_RUNNABLE_METHOD_REFCOUNT(CustomThreadWatcher);
    227 
    228 class ThreadWatcherTest : public ::testing::Test {
    229  public:
    230   static const TimeDelta kSleepTime;
    231   static const TimeDelta kUnresponsiveTime;
    232   static const BrowserThread::ID io_thread_id;
    233   static const std::string io_thread_name;
    234   static const BrowserThread::ID webkit_thread_id;
    235   static const std::string webkit_thread_name;
    236   CustomThreadWatcher* io_watcher_;
    237   CustomThreadWatcher* webkit_watcher_;
    238 
    239   ThreadWatcherTest() {
    240     webkit_thread_.reset(new BrowserThread(BrowserThread::WEBKIT));
    241     io_thread_.reset(new BrowserThread(BrowserThread::IO));
    242     watchdog_thread_.reset(new WatchDogThread());
    243     webkit_thread_->Start();
    244     io_thread_->Start();
    245     watchdog_thread_->Start();
    246 
    247     // Setup the registry for thread watchers.
    248     thread_watcher_list_ = new ThreadWatcherList();
    249 
    250     // Create thread watcher object for the IO thread.
    251     io_watcher_ = new CustomThreadWatcher(io_thread_id, io_thread_name,
    252                                           kSleepTime, kUnresponsiveTime);
    253 
    254     // Create thread watcher object for the WEBKIT thread.
    255     webkit_watcher_ = new CustomThreadWatcher(
    256         webkit_thread_id, webkit_thread_name, kSleepTime, kUnresponsiveTime);
    257   }
    258 
    259   ~ThreadWatcherTest() {
    260     ThreadWatcherList::StopWatchingAll();
    261     io_watcher_ = NULL;
    262     webkit_watcher_ = NULL;
    263     io_thread_.reset();
    264     webkit_thread_.reset();
    265     watchdog_thread_.reset();
    266     delete thread_watcher_list_;
    267   }
    268 
    269  private:
    270   scoped_ptr<BrowserThread> webkit_thread_;
    271   scoped_ptr<BrowserThread> io_thread_;
    272   scoped_ptr<WatchDogThread> watchdog_thread_;
    273   ThreadWatcherList* thread_watcher_list_;
    274 };
    275 
    276 // Define static constants.
    277 const TimeDelta ThreadWatcherTest::kSleepTime =
    278     TimeDelta::FromMilliseconds(50);
    279 const TimeDelta ThreadWatcherTest::kUnresponsiveTime =
    280     TimeDelta::FromMilliseconds(500);
    281 const BrowserThread::ID ThreadWatcherTest::io_thread_id = BrowserThread::IO;
    282 const std::string ThreadWatcherTest::io_thread_name = "IO";
    283 const BrowserThread::ID ThreadWatcherTest::webkit_thread_id =
    284     BrowserThread::WEBKIT;
    285 const std::string ThreadWatcherTest::webkit_thread_name = "WEBKIT";
    286 
    287 // Test registration. When thread_watcher_list_ goes out of scope after
    288 // TearDown, all thread watcher objects will be deleted.
    289 TEST_F(ThreadWatcherTest, Registration) {
    290   EXPECT_EQ(io_watcher_, ThreadWatcherList::Find(io_thread_id));
    291   EXPECT_EQ(webkit_watcher_, ThreadWatcherList::Find(webkit_thread_id));
    292 
    293   // Check ThreadWatcher object has all correct parameters.
    294   EXPECT_EQ(io_thread_id, io_watcher_->thread_id());
    295   EXPECT_EQ(io_thread_name, io_watcher_->thread_name());
    296   EXPECT_EQ(kSleepTime, io_watcher_->sleep_time());
    297   EXPECT_EQ(kUnresponsiveTime, io_watcher_->unresponsive_time());
    298   EXPECT_FALSE(io_watcher_->active());
    299 
    300   // Check ThreadWatcher object of watched WEBKIT thread has correct data.
    301   EXPECT_EQ(webkit_thread_id, webkit_watcher_->thread_id());
    302   EXPECT_EQ(webkit_thread_name, webkit_watcher_->thread_name());
    303   EXPECT_EQ(kSleepTime, webkit_watcher_->sleep_time());
    304   EXPECT_EQ(kUnresponsiveTime, webkit_watcher_->unresponsive_time());
    305   EXPECT_FALSE(webkit_watcher_->active());
    306 }
    307 
    308 // Test ActivateThreadWatching and DeActivateThreadWatching of IO thread. This
    309 // method also checks that pong message was sent by the watched thread and pong
    310 // message was received by the WatchDogThread. It also checks that
    311 // OnCheckResponsiveness has verified the ping-pong mechanism and the watched
    312 // thread is not hung.
    313 TEST_F(ThreadWatcherTest, ThreadResponding) {
    314   TimeTicks time_before_ping = TimeTicks::Now();
    315   // Activate watching IO thread.
    316   WatchDogThread::PostTask(
    317       FROM_HERE,
    318       NewRunnableMethod(io_watcher_, &ThreadWatcher::ActivateThreadWatching));
    319 
    320   // Activate would have started ping/pong messaging. Expect atleast one
    321   // ping/pong messaging sequence to happen.
    322   io_watcher_->WaitForStateChange(kSleepTime + TimeDelta::FromMinutes(1),
    323                                   RECEIVED_PONG);
    324   EXPECT_GT(io_watcher_->ping_sent_, static_cast<uint64>(0));
    325   EXPECT_GT(io_watcher_->pong_received_, static_cast<uint64>(0));
    326   EXPECT_TRUE(io_watcher_->active());
    327   EXPECT_GE(io_watcher_->saved_ping_time_, time_before_ping);
    328   EXPECT_GE(io_watcher_->saved_ping_sequence_number_, static_cast<uint64>(0));
    329 
    330   // Verify watched thread is responding with ping/pong messaging.
    331   io_watcher_->WaitForCheckResponse(
    332       kUnresponsiveTime + TimeDelta::FromMinutes(1), SUCCESSFUL);
    333   EXPECT_GT(io_watcher_->success_response_, static_cast<uint64>(0));
    334   EXPECT_EQ(io_watcher_->failed_response_, static_cast<uint64>(0));
    335 
    336   // DeActivate thread watching for shutdown.
    337   WatchDogThread::PostTask(
    338       FROM_HERE,
    339       NewRunnableMethod(io_watcher_, &ThreadWatcher::DeActivateThreadWatching));
    340 }
    341 
    342 // This test posts a task on watched thread that takes very long time (this is
    343 // to simulate hanging of watched thread). It then checks for
    344 // OnCheckResponsiveness raising an alert (OnCheckResponsiveness returns false
    345 // if the watched thread is not responding).
    346 TEST_F(ThreadWatcherTest, ThreadNotResponding) {
    347   // Simulate hanging of watched thread by making the watched thread wait for a
    348   // very long time by posting a task on watched thread that keeps it busy.
    349   BrowserThread::PostTask(
    350       io_thread_id,
    351       FROM_HERE,
    352       NewRunnableMethod(
    353           io_watcher_,
    354           &CustomThreadWatcher::VeryLongMethod,
    355           kUnresponsiveTime * 10));
    356 
    357   // Activate thread watching.
    358   WatchDogThread::PostTask(
    359       FROM_HERE,
    360       NewRunnableMethod(io_watcher_, &ThreadWatcher::ActivateThreadWatching));
    361 
    362   // Verify watched thread is not responding for ping messages.
    363   io_watcher_->WaitForCheckResponse(
    364       kUnresponsiveTime + TimeDelta::FromMinutes(1), FAILED);
    365   EXPECT_EQ(io_watcher_->success_response_, static_cast<uint64>(0));
    366   EXPECT_GT(io_watcher_->failed_response_, static_cast<uint64>(0));
    367 
    368   // DeActivate thread watching for shutdown.
    369   WatchDogThread::PostTask(
    370       FROM_HERE,
    371       NewRunnableMethod(io_watcher_, &ThreadWatcher::DeActivateThreadWatching));
    372 
    373   // Wait for the io_watcher_'s VeryLongMethod to finish.
    374   io_watcher_->WaitForWaitStateChange(kUnresponsiveTime * 10, ALL_DONE);
    375 }
    376 
    377 // Test watching of multiple threads with all threads not responding.
    378 TEST_F(ThreadWatcherTest, MultipleThreadsResponding) {
    379   // Check for WEBKIT thread to perform ping/pong messaging.
    380   WatchDogThread::PostTask(
    381       FROM_HERE,
    382       NewRunnableMethod(
    383           webkit_watcher_, &ThreadWatcher::ActivateThreadWatching));
    384 
    385   // Check for IO thread to perform ping/pong messaging.
    386   WatchDogThread::PostTask(
    387       FROM_HERE,
    388       NewRunnableMethod(io_watcher_, &ThreadWatcher::ActivateThreadWatching));
    389 
    390   // Verify WEBKIT thread is responding with ping/pong messaging.
    391   webkit_watcher_->WaitForCheckResponse(
    392       kUnresponsiveTime + TimeDelta::FromMinutes(1), SUCCESSFUL);
    393   EXPECT_GT(webkit_watcher_->ping_sent_, static_cast<uint64>(0));
    394   EXPECT_GT(webkit_watcher_->pong_received_, static_cast<uint64>(0));
    395   EXPECT_GE(webkit_watcher_->ping_sequence_number_, static_cast<uint64>(0));
    396   EXPECT_GT(webkit_watcher_->success_response_, static_cast<uint64>(0));
    397   EXPECT_EQ(webkit_watcher_->failed_response_, static_cast<uint64>(0));
    398 
    399   // Verify IO thread is responding with ping/pong messaging.
    400   io_watcher_->WaitForCheckResponse(
    401       kUnresponsiveTime + TimeDelta::FromMinutes(1), SUCCESSFUL);
    402   EXPECT_GT(io_watcher_->ping_sent_, static_cast<uint64>(0));
    403   EXPECT_GT(io_watcher_->pong_received_, static_cast<uint64>(0));
    404   EXPECT_GE(io_watcher_->ping_sequence_number_, static_cast<uint64>(0));
    405   EXPECT_GT(io_watcher_->success_response_, static_cast<uint64>(0));
    406   EXPECT_EQ(io_watcher_->failed_response_, static_cast<uint64>(0));
    407 
    408   // DeActivate thread watching for shutdown.
    409   WatchDogThread::PostTask(
    410       FROM_HERE,
    411       NewRunnableMethod(io_watcher_, &ThreadWatcher::DeActivateThreadWatching));
    412 
    413   WatchDogThread::PostTask(
    414       FROM_HERE,
    415       NewRunnableMethod(
    416           webkit_watcher_, &ThreadWatcher::DeActivateThreadWatching));
    417 }
    418 
    419 // Test watching of multiple threads with one of the threads not responding.
    420 TEST_F(ThreadWatcherTest, MultipleThreadsNotResponding) {
    421   // Simulate hanging of watched thread by making the watched thread wait for a
    422   // very long time by posting a task on watched thread that keeps it busy.
    423   BrowserThread::PostTask(
    424       io_thread_id,
    425       FROM_HERE,
    426       NewRunnableMethod(
    427           io_watcher_,
    428           &CustomThreadWatcher::VeryLongMethod,
    429           kUnresponsiveTime * 10));
    430 
    431   // Activate watching of WEBKIT thread.
    432   WatchDogThread::PostTask(
    433       FROM_HERE,
    434       NewRunnableMethod(
    435           webkit_watcher_, &ThreadWatcher::ActivateThreadWatching));
    436 
    437   // Activate watching of IO thread.
    438   WatchDogThread::PostTask(
    439       FROM_HERE,
    440       NewRunnableMethod(io_watcher_, &ThreadWatcher::ActivateThreadWatching));
    441 
    442   // Verify WEBKIT thread is responding with ping/pong messaging.
    443   webkit_watcher_->WaitForCheckResponse(
    444       kUnresponsiveTime + TimeDelta::FromMinutes(1), SUCCESSFUL);
    445   EXPECT_GT(webkit_watcher_->success_response_, static_cast<uint64>(0));
    446   EXPECT_EQ(webkit_watcher_->failed_response_, static_cast<uint64>(0));
    447 
    448   // Verify IO thread is not responding for ping messages.
    449   io_watcher_->WaitForCheckResponse(
    450       kUnresponsiveTime + TimeDelta::FromMinutes(1), FAILED);
    451   EXPECT_EQ(io_watcher_->success_response_, static_cast<uint64>(0));
    452   EXPECT_GT(io_watcher_->failed_response_, static_cast<uint64>(0));
    453 
    454   // DeActivate thread watching for shutdown.
    455   WatchDogThread::PostTask(
    456       FROM_HERE,
    457       NewRunnableMethod(io_watcher_, &ThreadWatcher::DeActivateThreadWatching));
    458   WatchDogThread::PostTask(
    459       FROM_HERE,
    460       NewRunnableMethod(
    461           webkit_watcher_, &ThreadWatcher::DeActivateThreadWatching));
    462 
    463   // Wait for the io_watcher_'s VeryLongMethod to finish.
    464   io_watcher_->WaitForWaitStateChange(kUnresponsiveTime * 10, ALL_DONE);
    465 }
    466