From b0469166564cb4a686ef33f8209513fdd8606be8 Mon Sep 17 00:00:00 2001 From: Andrew Kryczka Date: Mon, 22 Feb 2016 21:32:19 -0800 Subject: [PATCH] Redo SyncPoints for flush while rolling test Summary: There was a race condition in the test where the rolling thread acquired the mutex before the flush thread pinned the logger. Rather than add more complicated synchronization to fix it, I followed Siying's suggestion to use SyncPoint in the test code. Comments in the LoadDependency() invocation explain the reason for each of the sync points. Test Plan: Ran test 1000 times for tsan/asan. Will wait for all sandcastle tests to finish before committing since this is a tricky test. Reviewers: IslamAbdelRahman, sdong Reviewed By: sdong Subscribers: dhruba, leveldb Differential Revision: https://reviews.facebook.net/D54615 --- db/auto_roll_logger.cc | 2 -- db/auto_roll_logger.h | 2 +- db/auto_roll_logger_test.cc | 68 ++++++++++++++++--------------------- util/posix_logger.h | 3 +- 4 files changed, 31 insertions(+), 44 deletions(-) diff --git a/db/auto_roll_logger.cc b/db/auto_roll_logger.cc index 853637ff3..8118b2377 100644 --- a/db/auto_roll_logger.cc +++ b/db/auto_roll_logger.cc @@ -77,8 +77,6 @@ void AutoRollLogger::Logv(const char* format, va_list ap) { if ((kLogFileTimeToRoll > 0 && LogExpired()) || (kMaxLogFileSize > 0 && logger_->GetLogFileSize() >= kMaxLogFileSize)) { RollLogFile(); - TEST_SYNC_POINT_CALLBACK("AutoRollLogger::Logv:BeforeResetLogger", - logger_.get()); Status s = ResetLogger(); if (!s.ok()) { // can't really log the error if creating a new LOG file failed diff --git a/db/auto_roll_logger.h b/db/auto_roll_logger.h index 0e4974d4d..a43a98a8f 100644 --- a/db/auto_roll_logger.h +++ b/db/auto_roll_logger.h @@ -72,7 +72,7 @@ class AutoRollLogger : public Logger { // pin down the current logger_ instance before releasing the mutex. logger = logger_; } - TEST_SYNC_POINT_CALLBACK("AutoRollLogger::Flush:PinnedLogger", nullptr); + TEST_SYNC_POINT("AutoRollLogger::Flush:PinnedLogger"); if (logger) { logger->Flush(); } diff --git a/db/auto_roll_logger_test.cc b/db/auto_roll_logger_test.cc index 814a29b08..60c89a186 100644 --- a/db/auto_roll_logger_test.cc +++ b/db/auto_roll_logger_test.cc @@ -13,7 +13,6 @@ #include #include "db/auto_roll_logger.h" #include "port/port.h" -#include "util/mutexlock.h" #include "util/sync_point.h" #include "util/testharness.h" #include "rocksdb/db.h" @@ -275,51 +274,42 @@ TEST_F(AutoRollLoggerTest, LogFlushWhileRolling) { AutoRollLogger* auto_roll_logger = dynamic_cast(logger.get()); ASSERT_TRUE(auto_roll_logger); - - // The test is split into two parts, with the below callback happening between - // them: - // (1) Before ResetLogger() is reached, the log rolling test code occasionally - // invokes PosixLogger::Flush(). For this part, dependencies should not be - // enforced. - // (2) After ResetLogger() has begun, any calls to PosixLogger::Flush() will - // be from threads other than the log rolling thread. We want to only - // enforce dependencies for this part. - rocksdb::SyncPoint::GetInstance()->SetCallBack( - "AutoRollLogger::Logv:BeforeResetLogger", [&](void* arg) { - rocksdb::SyncPoint::GetInstance()->LoadDependency({ - {"PosixLogger::Flush:1", - "AutoRollLogger::ResetLogger:BeforeNewLogger"}, - {"AutoRollLogger::ResetLogger:AfterNewLogger", - "PosixLogger::Flush:2"}, - }); - }); - - port::Mutex flush_thread_mutex; - port::CondVar flush_thread_cv{&flush_thread_mutex}; std::thread flush_thread; - // Additionally, to exercise the edge case, we need to ensure the old logger - // is used. For this, we pause after pinning the logger until dependencies - // have probably been loaded. - const int kWaitForDepsSeconds = 1; + + rocksdb::SyncPoint::GetInstance()->LoadDependency({ + // Need to pin the old logger before beginning the roll, as rolling grabs + // the mutex, which would prevent us from accessing the old logger. + {"AutoRollLogger::Flush:PinnedLogger", + "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit"}, + // Need to finish the flush thread init before this callback because the + // callback accesses flush_thread.get_id() in order to apply certain sync + // points only to the flush thread. + {"AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit", + "AutoRollLoggerTest::LogFlushWhileRolling:FlushCallbackBegin"}, + // Need to reset logger at this point in Flush() to exercise a race + // condition case, which is executing the flush with the pinned (old) + // logger after the roll has cut over to a new logger. + {"AutoRollLoggerTest::LogFlushWhileRolling:FlushCallback1", + "AutoRollLogger::ResetLogger:BeforeNewLogger"}, + {"AutoRollLogger::ResetLogger:AfterNewLogger", + "AutoRollLoggerTest::LogFlushWhileRolling:FlushCallback2"}, + }); rocksdb::SyncPoint::GetInstance()->SetCallBack( - "AutoRollLogger::Flush:PinnedLogger", [&](void* arg) { - MutexLock ml{&flush_thread_mutex}; - while (flush_thread.get_id() == std::thread::id()) { - flush_thread_cv.Wait(); - } + "PosixLogger::Flush:BeginCallback", [&](void* arg) { + TEST_SYNC_POINT( + "AutoRollLoggerTest::LogFlushWhileRolling:FlushCallbackBegin"); if (std::this_thread::get_id() == flush_thread.get_id()) { - Env::Default()->SleepForMicroseconds(kWaitForDepsSeconds * 1000 * 1000); - sleep(1); + TEST_SYNC_POINT( + "AutoRollLoggerTest::LogFlushWhileRolling:FlushCallback1"); + TEST_SYNC_POINT( + "AutoRollLoggerTest::LogFlushWhileRolling:FlushCallback2"); } }); - rocksdb::SyncPoint::GetInstance()->EnableProcessing(); - { - MutexLock ml{&flush_thread_mutex}; - flush_thread = std::thread([&]() { auto_roll_logger->Flush(); }); - flush_thread_cv.Signal(); - } + flush_thread = std::thread([&]() { auto_roll_logger->Flush(); }); + TEST_SYNC_POINT( + "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit"); RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size, kSampleMessage + ":LogFlushWhileRolling"); flush_thread.join(); diff --git a/util/posix_logger.h b/util/posix_logger.h index 9fde5f046..61bb9e38a 100644 --- a/util/posix_logger.h +++ b/util/posix_logger.h @@ -57,8 +57,7 @@ class PosixLogger : public Logger { fclose(file_); } virtual void Flush() override { - TEST_SYNC_POINT("PosixLogger::Flush:1"); - TEST_SYNC_POINT("PosixLogger::Flush:2"); + TEST_SYNC_POINT_CALLBACK("PosixLogger::Flush:BeginCallback", nullptr); if (flush_pending_) { flush_pending_ = false; fflush(file_);