rocksdb/util/timer_test.cc
Peter Dillinger 6ac1d25fd0 Fix+clean up handling of mock sleeps (#7101)
Summary:
We have a number of tests hanging on MacOS and windows due to
mishandling of code for mock sleeps. In addition, the code was in
terrible shape because the same variable (addon_time_) would sometimes
refer to microseconds and sometimes to seconds. One test even assumed it
was nanoseconds but was written to pass anyway.

This has been cleaned up so that DB tests generally use a SpecialEnv
function to mock sleep, for either some number of microseconds or seconds
depending on the function called. But to call one of these, the test must first
call SetMockSleep (precondition enforced with assertion), which also turns
sleeps in RocksDB into mock sleeps. To also removes accounting for actual
clock time, call SetTimeElapseOnlySleepOnReopen, which implies
SetMockSleep (on DB re-open). This latter setting only works by applying
on DB re-open, otherwise havoc can ensue if Env goes back in time with
DB open.

More specifics:

Removed some unused test classes, and updated comments on the general
problem.

Fixed DBSSTTest.GetTotalSstFilesSize using a sync point callback instead
of mock time. For this we have the only modification to production code,
inserting a sync point callback in flush_job.cc, which is not a change to
production behavior.

Removed unnecessary resetting of mock times to 0 in many tests. RocksDB
deals in relative time. Any behaviors relying on absolute date/time are likely
a bug. (The above test DBSSTTest.GetTotalSstFilesSize was the only one
clearly injecting a specific absolute time for actual testing convenience.) Just
in case I misunderstood some test, I put this note in each replacement:
// NOTE: Presumed unnecessary and removed: resetting mock time in env

Strengthened some tests like MergeTestTime, MergeCompactionTimeTest, and
FilterCompactionTimeTest in db_test.cc

stats_history_test and blob_db_test are each their own beast, rather deeply
dependent on MockTimeEnv. Each gets its own variant of a work-around for
TimedWait in a mock time environment. (Reduces redundancy and
inconsistency in stats_history_test.)

Intended follow-up:

Remove TimedWait from the public API of InstrumentedCondVar, and only
make that accessible through Env by passing in an InstrumentedCondVar and
a deadline. Then the Env implementations mocking time can fix this problem
without using sync points. (Test infrastructure using sync points interferes
with individual tests' control over sync points.)

With that change, we can simplify/consolidate the scattered work-arounds.

Pull Request resolved: https://github.com/facebook/rocksdb/pull/7101

Test Plan: make check on Linux and MacOS

Reviewed By: zhichao-cao

Differential Revision: D23032815

Pulled By: pdillinger

fbshipit-source-id: 7f33967ada8b83011fb54e8279365c008bd6610b
2020-08-11 12:41:30 -07:00

293 lines
7.2 KiB
C++

// Copyright (c) 2011-present, Facebook, Inc. All rights reserved.
// This source code is licensed under both the GPLv2 (found in the
// COPYING file in the root directory) and Apache 2.0 License
// (found in the LICENSE.Apache file in the root directory).
#include "util/timer.h"
#include "db/db_test_util.h"
namespace ROCKSDB_NAMESPACE {
class TimerTest : public testing::Test {
public:
TimerTest() : mock_env_(new MockTimeEnv(Env::Default())) {}
protected:
std::unique_ptr<MockTimeEnv> mock_env_;
#if defined(OS_MACOSX) && !defined(NDEBUG)
// On some platforms (MacOS) pthread_cond_timedwait does not appear
// to release the lock for other threads to operate if the deadline time
// is already passed. This is a problem for tests in general because
// TimedWait calls are a bad abstraction: the deadline parameter is
// usually computed from Env time, but is interpreted in real clock time.
// Since this test doesn't even pretend to use clock times, we have
// to mock TimedWait to ensure it yields.
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<uint64_t*>(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 int kIterations = 1;
uint64_t time_counter = 0;
mock_env_->set_current_time(0);
InstrumentedMutex mutex;
InstrumentedCondVar test_cv(&mutex);
Timer timer(mock_env_.get());
int count = 0;
timer.Add(
[&] {
InstrumentedMutexLock l(&mutex);
count++;
if (count >= kIterations) {
test_cv.SignalAll();
}
},
"fn_sch_test", 1 * kSecond, 0);
ASSERT_TRUE(timer.Start());
// Wait for execution to finish
{
InstrumentedMutexLock l(&mutex);
while(count < kIterations) {
time_counter += kSecond;
mock_env_->set_current_time(time_counter);
test_cv.TimedWait(time_counter);
}
}
ASSERT_TRUE(timer.Shutdown());
ASSERT_EQ(1, count);
}
TEST_F(TimerTest, MultipleScheduleOnceTest) {
const int kIterations = 1;
uint64_t time_counter = 0;
mock_env_->set_current_time(0);
InstrumentedMutex mutex1;
InstrumentedCondVar test_cv1(&mutex1);
Timer timer(mock_env_.get());
int count1 = 0;
timer.Add(
[&] {
InstrumentedMutexLock l(&mutex1);
count1++;
if (count1 >= kIterations) {
test_cv1.SignalAll();
}
},
"fn_sch_test1", 1 * kSecond, 0);
InstrumentedMutex mutex2;
InstrumentedCondVar test_cv2(&mutex2);
int count2 = 0;
timer.Add(
[&] {
InstrumentedMutexLock l(&mutex2);
count2 += 5;
if (count2 >= kIterations) {
test_cv2.SignalAll();
}
},
"fn_sch_test2", 3 * kSecond, 0);
ASSERT_TRUE(timer.Start());
// Wait for execution to finish
{
InstrumentedMutexLock l(&mutex1);
while (count1 < kIterations) {
time_counter += kSecond;
mock_env_->set_current_time(time_counter);
test_cv1.TimedWait(time_counter);
}
}
// Wait for execution to finish
{
InstrumentedMutexLock l(&mutex2);
while(count2 < kIterations) {
time_counter += kSecond;
mock_env_->set_current_time(time_counter);
test_cv2.TimedWait(time_counter);
}
}
ASSERT_TRUE(timer.Shutdown());
ASSERT_EQ(1, count1);
ASSERT_EQ(5, count2);
}
TEST_F(TimerTest, SingleScheduleRepeatedlyTest) {
const int kIterations = 5;
uint64_t time_counter = 0;
mock_env_->set_current_time(0);
InstrumentedMutex mutex;
InstrumentedCondVar test_cv(&mutex);
Timer timer(mock_env_.get());
int count = 0;
timer.Add(
[&] {
InstrumentedMutexLock l(&mutex);
count++;
if (count >= kIterations) {
test_cv.SignalAll();
}
},
"fn_sch_test", 1 * kSecond, 1 * kSecond);
ASSERT_TRUE(timer.Start());
// Wait for execution to finish
{
InstrumentedMutexLock l(&mutex);
while(count < kIterations) {
time_counter += kSecond;
mock_env_->set_current_time(time_counter);
test_cv.TimedWait(time_counter);
}
}
ASSERT_TRUE(timer.Shutdown());
ASSERT_EQ(5, count);
}
TEST_F(TimerTest, MultipleScheduleRepeatedlyTest) {
uint64_t time_counter = 0;
mock_env_->set_current_time(0);
Timer timer(mock_env_.get());
InstrumentedMutex mutex1;
InstrumentedCondVar test_cv1(&mutex1);
const int kIterations1 = 5;
int count1 = 0;
timer.Add(
[&] {
InstrumentedMutexLock l(&mutex1);
count1++;
if (count1 >= kIterations1) {
test_cv1.SignalAll();
}
},
"fn_sch_test1", 0, 2 * kSecond);
InstrumentedMutex mutex2;
InstrumentedCondVar test_cv2(&mutex2);
const int kIterations2 = 5;
int count2 = 0;
timer.Add(
[&] {
InstrumentedMutexLock l(&mutex2);
count2++;
if (count2 >= kIterations2) {
test_cv2.SignalAll();
}
},
"fn_sch_test2", 1 * kSecond, 2 * kSecond);
ASSERT_TRUE(timer.Start());
// Wait for execution to finish
{
InstrumentedMutexLock l(&mutex1);
while(count1 < kIterations1) {
time_counter += kSecond;
mock_env_->set_current_time(time_counter);
test_cv1.TimedWait(time_counter);
}
}
timer.Cancel("fn_sch_test1");
// Wait for execution to finish
{
InstrumentedMutexLock l(&mutex2);
while(count2 < kIterations2) {
time_counter += kSecond;
mock_env_->set_current_time(time_counter);
test_cv2.TimedWait(time_counter);
}
}
timer.Cancel("fn_sch_test2");
ASSERT_TRUE(timer.Shutdown());
ASSERT_EQ(count1, 5);
ASSERT_EQ(count2, 5);
}
TEST_F(TimerTest, AddAfterStartTest) {
const int kIterations = 5;
InstrumentedMutex mutex;
InstrumentedCondVar test_cv(&mutex);
// wait timer to run and then add a new job
SyncPoint::GetInstance()->LoadDependency(
{{"Timer::Run::Waiting", "TimerTest:AddAfterStartTest:1"}});
SyncPoint::GetInstance()->EnableProcessing();
mock_env_->set_current_time(0);
Timer timer(mock_env_.get());
ASSERT_TRUE(timer.Start());
TEST_SYNC_POINT("TimerTest:AddAfterStartTest:1");
int count = 0;
timer.Add(
[&] {
InstrumentedMutexLock l(&mutex);
count++;
if (count >= kIterations) {
test_cv.SignalAll();
}
},
"fn_sch_test", 1 * kSecond, 1 * kSecond);
// Wait for execution to finish
uint64_t time_counter = 0;
{
InstrumentedMutexLock l(&mutex);
while (count < kIterations) {
time_counter += kSecond;
mock_env_->set_current_time(time_counter);
test_cv.TimedWait(time_counter);
}
}
ASSERT_TRUE(timer.Shutdown());
ASSERT_EQ(kIterations, count);
}
} // namespace ROCKSDB_NAMESPACE
int main(int argc, char** argv) {
::testing::InitGoogleTest(&argc, argv);
return RUN_ALL_TESTS();
}