From d941b89dddb283d5c8c4e87b91c9ec512e304975 Mon Sep 17 00:00:00 2001 From: Jay Zhuang Date: Mon, 3 Aug 2020 10:15:41 -0700 Subject: [PATCH] Fix hang timer tests on macos (#7208) Summary: And re-enable disabled tests. The issue is caused by `CondVar.TimedWait()` doesn't use `MockTimeEnv`. Issue: https://github.com/facebook/rocksdb/issues/6698 Pull Request resolved: https://github.com/facebook/rocksdb/pull/7208 Test Plan: `./timer_test --gtest_repeat=1000` Reviewed By: riversand963 Differential Revision: D22857855 Pulled By: jay-zhuang fbshipit-source-id: 6d15f65f6ae58b75b76cb132815c16ad81ffd12f --- util/timer.h | 18 +++++----- util/timer_test.cc | 82 +++++++++++++++++++++++++++------------------- 2 files changed, 58 insertions(+), 42 deletions(-) diff --git a/util/timer.h b/util/timer.h index aee55816a..21ddf330a 100644 --- a/util/timer.h +++ b/util/timer.h @@ -13,7 +13,7 @@ #include #include -#include "port/port.h" +#include "monitoring/instrumented_mutex.h" #include "rocksdb/env.h" #include "util/mutexlock.h" @@ -53,13 +53,13 @@ class Timer { env_->NowMicros() + start_after_us, repeat_every_us)); - MutexLock l(&mutex_); + InstrumentedMutexLock l(&mutex_); heap_.push(fn_info.get()); map_.emplace(std::make_pair(fn_name, std::move(fn_info))); } void Cancel(const std::string& fn_name) { - MutexLock l(&mutex_); + InstrumentedMutexLock l(&mutex_); auto it = map_.find(fn_name); if (it != map_.end()) { @@ -70,13 +70,13 @@ class Timer { } void CancelAll() { - MutexLock l(&mutex_); + InstrumentedMutexLock l(&mutex_); CancelAllWithLock(); } // Start the Timer bool Start() { - MutexLock l(&mutex_); + InstrumentedMutexLock l(&mutex_); if (running_) { return false; } @@ -89,7 +89,7 @@ class Timer { // Shutdown the Timer bool Shutdown() { { - MutexLock l(&mutex_); + InstrumentedMutexLock l(&mutex_); if (!running_) { return false; } @@ -107,7 +107,7 @@ class Timer { private: void Run() { - MutexLock l(&mutex_); + InstrumentedMutexLock l(&mutex_); while (running_) { if (heap_.empty()) { @@ -204,8 +204,8 @@ class Timer { Env* const env_; // This mutex controls both the heap_ and the map_. It needs to be held for // making any changes in them. - port::Mutex mutex_; - port::CondVar cond_var_; + InstrumentedMutex mutex_; + InstrumentedCondVar cond_var_; std::unique_ptr thread_; bool running_; diff --git a/util/timer_test.cc b/util/timer_test.cc index d32dc9eb5..73fc71c42 100644 --- a/util/timer_test.cc +++ b/util/timer_test.cc @@ -15,21 +15,42 @@ class TimerTest : public testing::Test { protected: std::unique_ptr mock_env_; + +#if defined(OS_MACOSX) && !defined(NDEBUG) + // On MacOS, `CondVar.TimedWait()` doesn't use the time from MockTimeEnv, + // instead it still uses the system time. + // This is just a mitigation that always trigger the CV timeout. It is not + // perfect, only works for this test. + void SetUp() override { + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->ClearAllCallBacks(); + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->SetCallBack( + "InstrumentedCondVar::TimedWaitInternal", [&](void* arg) { + uint64_t* time_us = reinterpret_cast(arg); + if (*time_us < mock_env_->RealNowMicros()) { + *time_us = mock_env_->RealNowMicros() + 1000; + } + }); + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->EnableProcessing(); + } +#endif // OS_MACOSX && !NDEBUG + + const uint64_t kSecond = 1000000; // 1sec = 1000000us }; TEST_F(TimerTest, SingleScheduleOnceTest) { - const uint64_t kSecond = 1000000; // 1sec = 1000000us const int kIterations = 1; uint64_t time_counter = 0; mock_env_->set_current_time(0); - port::Mutex mutex; - port::CondVar test_cv(&mutex); + + InstrumentedMutex mutex; + InstrumentedCondVar test_cv(&mutex); Timer timer(mock_env_.get()); int count = 0; timer.Add( [&] { - MutexLock l(&mutex); + InstrumentedMutexLock l(&mutex); count++; if (count >= kIterations) { test_cv.SignalAll(); @@ -41,7 +62,7 @@ TEST_F(TimerTest, SingleScheduleOnceTest) { // Wait for execution to finish { - MutexLock l(&mutex); + InstrumentedMutexLock l(&mutex); while(count < kIterations) { time_counter += kSecond; mock_env_->set_current_time(time_counter); @@ -55,18 +76,17 @@ TEST_F(TimerTest, SingleScheduleOnceTest) { } TEST_F(TimerTest, MultipleScheduleOnceTest) { - const uint64_t kSecond = 1000000; // 1sec = 1000000us const int kIterations = 1; uint64_t time_counter = 0; mock_env_->set_current_time(0); - port::Mutex mutex1; - port::CondVar test_cv1(&mutex1); + InstrumentedMutex mutex1; + InstrumentedCondVar test_cv1(&mutex1); Timer timer(mock_env_.get()); int count1 = 0; timer.Add( [&] { - MutexLock l(&mutex1); + InstrumentedMutexLock l(&mutex1); count1++; if (count1 >= kIterations) { test_cv1.SignalAll(); @@ -74,12 +94,12 @@ TEST_F(TimerTest, MultipleScheduleOnceTest) { }, "fn_sch_test1", 1 * kSecond, 0); - port::Mutex mutex2; - port::CondVar test_cv2(&mutex2); + InstrumentedMutex mutex2; + InstrumentedCondVar test_cv2(&mutex2); int count2 = 0; timer.Add( [&] { - MutexLock l(&mutex2); + InstrumentedMutexLock l(&mutex2); count2 += 5; if (count2 >= kIterations) { test_cv2.SignalAll(); @@ -91,7 +111,7 @@ TEST_F(TimerTest, MultipleScheduleOnceTest) { // Wait for execution to finish { - MutexLock l(&mutex1); + InstrumentedMutexLock l(&mutex1); while (count1 < kIterations) { time_counter += kSecond; mock_env_->set_current_time(time_counter); @@ -101,7 +121,7 @@ TEST_F(TimerTest, MultipleScheduleOnceTest) { // Wait for execution to finish { - MutexLock l(&mutex2); + InstrumentedMutexLock l(&mutex2); while(count2 < kIterations) { time_counter += kSecond; mock_env_->set_current_time(time_counter); @@ -115,21 +135,20 @@ TEST_F(TimerTest, MultipleScheduleOnceTest) { ASSERT_EQ(5, count2); } -TEST_F(TimerTest, DISABLED_SingleScheduleRepeatedlyTest) { - const uint64_t kSecond = 1000000; // 1sec = 1000000us +TEST_F(TimerTest, SingleScheduleRepeatedlyTest) { const int kIterations = 5; uint64_t time_counter = 0; mock_env_->set_current_time(0); - port::Mutex mutex; - port::CondVar test_cv(&mutex); + + InstrumentedMutex mutex; + InstrumentedCondVar test_cv(&mutex); Timer timer(mock_env_.get()); int count = 0; timer.Add( [&] { - MutexLock l(&mutex); + InstrumentedMutexLock l(&mutex); count++; - fprintf(stderr, "%d\n", count); if (count >= kIterations) { test_cv.SignalAll(); } @@ -140,7 +159,7 @@ TEST_F(TimerTest, DISABLED_SingleScheduleRepeatedlyTest) { // Wait for execution to finish { - MutexLock l(&mutex); + InstrumentedMutexLock l(&mutex); while(count < kIterations) { time_counter += kSecond; mock_env_->set_current_time(time_counter); @@ -153,36 +172,33 @@ TEST_F(TimerTest, DISABLED_SingleScheduleRepeatedlyTest) { ASSERT_EQ(5, count); } -TEST_F(TimerTest, DISABLED_MultipleScheduleRepeatedlyTest) { - const uint64_t kSecond = 1000000; // 1sec = 1000000us +TEST_F(TimerTest, MultipleScheduleRepeatedlyTest) { uint64_t time_counter = 0; mock_env_->set_current_time(0); Timer timer(mock_env_.get()); - port::Mutex mutex1; - port::CondVar test_cv1(&mutex1); + InstrumentedMutex mutex1; + InstrumentedCondVar test_cv1(&mutex1); const int kIterations1 = 5; int count1 = 0; timer.Add( [&] { - MutexLock l(&mutex1); + InstrumentedMutexLock l(&mutex1); count1++; - fprintf(stderr, "hello\n"); if (count1 >= kIterations1) { test_cv1.SignalAll(); } }, "fn_sch_test1", 0, 2 * kSecond); - port::Mutex mutex2; - port::CondVar test_cv2(&mutex2); + InstrumentedMutex mutex2; + InstrumentedCondVar test_cv2(&mutex2); const int kIterations2 = 5; int count2 = 0; timer.Add( [&] { - MutexLock l(&mutex2); + InstrumentedMutexLock l(&mutex2); count2++; - fprintf(stderr, "world\n"); if (count2 >= kIterations2) { test_cv2.SignalAll(); } @@ -193,7 +209,7 @@ TEST_F(TimerTest, DISABLED_MultipleScheduleRepeatedlyTest) { // Wait for execution to finish { - MutexLock l(&mutex1); + InstrumentedMutexLock l(&mutex1); while(count1 < kIterations1) { time_counter += kSecond; mock_env_->set_current_time(time_counter); @@ -205,7 +221,7 @@ TEST_F(TimerTest, DISABLED_MultipleScheduleRepeatedlyTest) { // Wait for execution to finish { - MutexLock l(&mutex2); + InstrumentedMutexLock l(&mutex2); while(count2 < kIterations2) { time_counter += kSecond; mock_env_->set_current_time(time_counter);