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
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
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.
49class 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
226DISABLE_RUNNABLE_METHOD_REFCOUNT(CustomThreadWatcher);
227
228class 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.
277const TimeDelta ThreadWatcherTest::kSleepTime =
278    TimeDelta::FromMilliseconds(50);
279const TimeDelta ThreadWatcherTest::kUnresponsiveTime =
280    TimeDelta::FromMilliseconds(500);
281const BrowserThread::ID ThreadWatcherTest::io_thread_id = BrowserThread::IO;
282const std::string ThreadWatcherTest::io_thread_name = "IO";
283const BrowserThread::ID ThreadWatcherTest::webkit_thread_id =
284    BrowserThread::WEBKIT;
285const 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.
289TEST_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.
313TEST_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).
346TEST_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.
378TEST_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.
420TEST_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