From 88cc81df5c2dcf9eff5e52fb9eddb46d9afc9a18 Mon Sep 17 00:00:00 2001 From: Siying Dong Date: Mon, 3 Apr 2017 11:24:39 -0700 Subject: [PATCH] auto_roll_logger_test to move away from real sleep Summary: auto_roll_logger_test relies on timing conditon that some operations finish within 1 seconds. This caused flaky tests. Move away from real timing and sleep and use fake time to verify the time-based rolling. Closes https://github.com/facebook/rocksdb/pull/2066 Differential Revision: D4810647 Pulled By: siying fbshipit-source-id: c54d994 --- db/auto_roll_logger.h | 2 + db/auto_roll_logger_test.cc | 132 +++++++++++++++++++----------------- 2 files changed, 71 insertions(+), 63 deletions(-) diff --git a/db/auto_roll_logger.h b/db/auto_roll_logger.h index df715e34d..1bcf20adf 100644 --- a/db/auto_roll_logger.h +++ b/db/auto_roll_logger.h @@ -91,6 +91,8 @@ class AutoRollLogger : public Logger { return log_fname_; } + uint64_t TEST_ctime() const { return ctime_; } + private: bool LogExpired(); Status ResetLogger(); diff --git a/db/auto_roll_logger_test.cc b/db/auto_roll_logger_test.cc index eeb5593eb..851c196e0 100644 --- a/db/auto_roll_logger_test.cc +++ b/db/auto_roll_logger_test.cc @@ -17,6 +17,7 @@ #include #include #include +#include "db/db_test_util.h" #include "port/port.h" #include "rocksdb/db.h" #include "util/logging.h" @@ -24,6 +25,22 @@ #include "util/testharness.h" namespace rocksdb { +namespace { +class NoSleepEnv : public EnvWrapper { + public: + NoSleepEnv(Env* base) : EnvWrapper(base) {} + virtual void SleepForMicroseconds(int micros) override { + fake_time_ += static_cast(micros); + } + + virtual uint64_t NowNanos() override { return fake_time_ * 1000; } + + virtual uint64_t NowMicros() override { return fake_time_; } + + private: + uint64_t fake_time_ = 6666666666; +}; +} // namespace class AutoRollLoggerTest : public testing::Test { public: @@ -44,13 +61,13 @@ class AutoRollLoggerTest : public testing::Test { void RollLogFileBySizeTest(AutoRollLogger* logger, size_t log_max_size, const std::string& log_message); - uint64_t RollLogFileByTimeTest(AutoRollLogger* logger, size_t time, - const std::string& log_message); + void RollLogFileByTimeTest(Env*, AutoRollLogger* logger, size_t time, + const std::string& log_message); static const std::string kSampleMessage; static const std::string kTestDir; static const std::string kLogFile; - static Env* env; + static Env* default_env; }; const std::string AutoRollLoggerTest::kSampleMessage( @@ -58,7 +75,7 @@ const std::string AutoRollLoggerTest::kSampleMessage( const std::string AutoRollLoggerTest::kTestDir(test::TmpDir() + "/db_log_test"); const std::string AutoRollLoggerTest::kLogFile(test::TmpDir() + "/db_log_test/LOG"); -Env* AutoRollLoggerTest::env = Env::Default(); +Env* AutoRollLoggerTest::default_env = Env::Default(); // In this test we only want to Log some simple log message with // no format. LogMessage() provides such a simple interface and @@ -75,16 +92,6 @@ void LogMessage(const InfoLogLevel log_level, Logger* logger, } } // namespace -namespace { -void GetFileCreateTime(const std::string& fname, uint64_t* file_ctime) { - struct stat s; - if (stat(fname.c_str(), &s) != 0) { - *file_ctime = (uint64_t)0; - } - *file_ctime = static_cast(s.st_ctime); -} -} // namespace - void AutoRollLoggerTest::RollLogFileBySizeTest(AutoRollLogger* logger, size_t log_max_size, const std::string& log_message) { @@ -111,45 +118,42 @@ void AutoRollLoggerTest::RollLogFileBySizeTest(AutoRollLogger* logger, ASSERT_TRUE(message_size == logger->GetLogFileSize()); } -uint64_t AutoRollLoggerTest::RollLogFileByTimeTest( - AutoRollLogger* logger, size_t time, const std::string& log_message) { - uint64_t expected_create_time; - uint64_t actual_create_time; +void AutoRollLoggerTest::RollLogFileByTimeTest(Env* env, AutoRollLogger* logger, + size_t time, + const std::string& log_message) { + uint64_t expected_ctime; + uint64_t actual_ctime; + uint64_t total_log_size; EXPECT_OK(env->GetFileSize(kLogFile, &total_log_size)); - GetFileCreateTime(kLogFile, &expected_create_time); + expected_ctime = logger->TEST_ctime(); logger->SetCallNowMicrosEveryNRecords(0); // -- Write to the log for several times, which is supposed // to be finished before time. for (int i = 0; i < 10; ++i) { - LogMessage(logger, log_message.c_str()); - EXPECT_OK(logger->GetStatus()); - // Make sure we always write to the same log file (by - // checking the create time); - GetFileCreateTime(kLogFile, &actual_create_time); - - // Also make sure the log size is increasing. - EXPECT_EQ(expected_create_time, actual_create_time); - EXPECT_GT(logger->GetLogFileSize(), total_log_size); - total_log_size = logger->GetLogFileSize(); + env->SleepForMicroseconds(50000); + LogMessage(logger, log_message.c_str()); + EXPECT_OK(logger->GetStatus()); + // Make sure we always write to the same log file (by + // checking the create time); + + actual_ctime = logger->TEST_ctime(); + + // Also make sure the log size is increasing. + EXPECT_EQ(expected_ctime, actual_ctime); + EXPECT_GT(logger->GetLogFileSize(), total_log_size); + total_log_size = logger->GetLogFileSize(); } // -- Make the log file expire -#ifdef OS_WIN - Sleep(static_cast(time) * 1000); -#else - sleep(static_cast(time)); -#endif + env->SleepForMicroseconds(static_cast(time * 1000000)); LogMessage(logger, log_message.c_str()); // At this time, the new log file should be created. - GetFileCreateTime(kLogFile, &actual_create_time); - EXPECT_GT(actual_create_time, expected_create_time); + actual_ctime = logger->TEST_ctime(); + EXPECT_LT(expected_ctime, actual_ctime); EXPECT_LT(logger->GetLogFileSize(), total_log_size); - expected_create_time = actual_create_time; - - return expected_create_time; } TEST_F(AutoRollLoggerTest, RollLogFileBySize) { @@ -163,16 +167,19 @@ TEST_F(AutoRollLoggerTest, RollLogFileBySize) { } TEST_F(AutoRollLoggerTest, RollLogFileByTime) { - size_t time = 2; - size_t log_size = 1024 * 5; + NoSleepEnv nse(Env::Default()); - InitTestDb(); - // -- Test the existence of file during the server restart. - ASSERT_EQ(Status::NotFound(), env->FileExists(kLogFile)); - AutoRollLogger logger(Env::Default(), kTestDir, "", log_size, time); - ASSERT_OK(env->FileExists(kLogFile)); + size_t time = 2; + size_t log_size = 1024 * 5; + + InitTestDb(); + // -- Test the existence of file during the server restart. + ASSERT_EQ(Status::NotFound(), default_env->FileExists(kLogFile)); + AutoRollLogger logger(&nse, kTestDir, "", log_size, time); + ASSERT_OK(default_env->FileExists(kLogFile)); - RollLogFileByTimeTest(&logger, time, kSampleMessage + ":RollLogFileByTime"); + RollLogFileByTimeTest(&nse, &logger, time, + kSampleMessage + ":RollLogFileByTime"); } TEST_F(AutoRollLoggerTest, OpenLogFilesMultipleTimesWithOptionLog_max_size) { @@ -205,16 +212,16 @@ TEST_F(AutoRollLoggerTest, CompositeRollByTimeAndSizeLogger) { InitTestDb(); - AutoRollLogger logger(Env::Default(), kTestDir, "", log_max_size, time); + NoSleepEnv nse(Env::Default()); + AutoRollLogger logger(&nse, kTestDir, "", log_max_size, time); // Test the ability to roll by size - RollLogFileBySizeTest( - &logger, log_max_size, - kSampleMessage + ":CompositeRollByTimeAndSizeLogger"); + RollLogFileBySizeTest(&logger, log_max_size, + kSampleMessage + ":CompositeRollByTimeAndSizeLogger"); // Test the ability to roll by Time - RollLogFileByTimeTest( &logger, time, - kSampleMessage + ":CompositeRollByTimeAndSizeLogger"); + RollLogFileByTimeTest(&nse, &logger, time, + kSampleMessage + ":CompositeRollByTimeAndSizeLogger"); } #ifndef OS_WIN @@ -222,6 +229,7 @@ TEST_F(AutoRollLoggerTest, CompositeRollByTimeAndSizeLogger) { // port TEST_F(AutoRollLoggerTest, CreateLoggerFromOptions) { DBOptions options; + NoSleepEnv nse(Env::Default()); shared_ptr logger; // Normal logger @@ -240,15 +248,15 @@ TEST_F(AutoRollLoggerTest, CreateLoggerFromOptions) { kSampleMessage + ":CreateLoggerFromOptions - size"); // Only roll by Time + options.env = &nse; InitTestDb(); options.max_log_file_size = 0; options.log_file_time_to_roll = 2; ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger)); auto_roll_logger = dynamic_cast(logger.get()); - RollLogFileByTimeTest( - auto_roll_logger, options.log_file_time_to_roll, - kSampleMessage + ":CreateLoggerFromOptions - time"); + RollLogFileByTimeTest(&nse, auto_roll_logger, options.log_file_time_to_roll, + kSampleMessage + ":CreateLoggerFromOptions - time"); // roll by both Time and size InitTestDb(); @@ -257,12 +265,10 @@ TEST_F(AutoRollLoggerTest, CreateLoggerFromOptions) { ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger)); auto_roll_logger = dynamic_cast(logger.get()); - RollLogFileBySizeTest( - auto_roll_logger, options.max_log_file_size, - kSampleMessage + ":CreateLoggerFromOptions - both"); - RollLogFileByTimeTest( - auto_roll_logger, options.log_file_time_to_roll, - kSampleMessage + ":CreateLoggerFromOptions - both"); + RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size, + kSampleMessage + ":CreateLoggerFromOptions - both"); + RollLogFileByTimeTest(&nse, auto_roll_logger, options.log_file_time_to_roll, + kSampleMessage + ":CreateLoggerFromOptions - both"); } TEST_F(AutoRollLoggerTest, LogFlushWhileRolling) { @@ -462,7 +468,7 @@ TEST_F(AutoRollLoggerTest, LogFileExistence) { options.max_log_file_size = 100 * 1024 * 1024; options.create_if_missing = true; ASSERT_OK(rocksdb::DB::Open(options, kTestDir, &db)); - ASSERT_OK(env->FileExists(kLogFile)); + ASSERT_OK(default_env->FileExists(kLogFile)); delete db; }