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