diff --git a/CMakeLists.txt b/CMakeLists.txt index 0ca338bd63ff81542ab4e8171b1b5de3024a5c18..50e082662b52b8826cf9374184c893db5fcbec24 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -949,6 +949,7 @@ if(WITH_TESTS) env/mock_env_test.cc file/delete_scheduler_test.cc logging/auto_roll_logger_test.cc + logging/env_logger_test.cc logging/event_logger_test.cc memory/arena_test.cc memtable/inlineskiplist_test.cc diff --git a/Makefile b/Makefile index b0b52a3736539c527cb9be6b9117d21e5e4e5da6..f1834e0ecf9f435e73d5f6b7d2063eccf719cd55 100644 --- a/Makefile +++ b/Makefile @@ -432,6 +432,7 @@ TESTS = \ inlineskiplist_test \ env_basic_test \ env_test \ + env_logger_test \ hash_test \ thread_local_test \ rate_limiter_test \ @@ -1529,6 +1530,9 @@ filelock_test: util/filelock_test.o $(LIBOBJECTS) $(TESTHARNESS) auto_roll_logger_test: logging/auto_roll_logger_test.o $(LIBOBJECTS) $(TESTHARNESS) $(AM_LINK) +env_logger_test: logging/env_logger_test.o $(LIBOBJECTS) $(TESTHARNESS) + $(AM_LINK) + memtable_list_test: db/memtable_list_test.o $(LIBOBJECTS) $(TESTHARNESS) $(AM_LINK) diff --git a/TARGETS b/TARGETS index 3935f1f740d5c31c4e7db05e1e0d027270efac56..82e1d375d96d39514c34b4090e44079467ae5b17 100644 --- a/TARGETS +++ b/TARGETS @@ -368,6 +368,11 @@ ROCKS_TESTS = [ "logging/auto_roll_logger_test.cc", "serial", ], + [ + "env_logger_test", + "logging/env_logger_test.cc", + "serial", + ], [ "autovector_test", "util/autovector_test.cc", diff --git a/env/env.cc b/env/env.cc index e5e0e99c0a0ebdaa7daa2c9f4932e38b9b7605e4..87b6b35c16c659170ad839855187e16f951da624 100644 --- a/env/env.cc +++ b/env/env.cc @@ -10,6 +10,7 @@ #include "rocksdb/env.h" #include +#include "logging/env_logger.h" #include "memory/arena.h" #include "options/db_options.h" #include "port/port.h" @@ -22,6 +23,11 @@ namespace rocksdb { Env::~Env() { } +Status Env::NewLogger(const std::string& fname, + std::shared_ptr* result) { + return NewEnvLogger(fname, this, result); +} + std::string Env::PriorityToString(Env::Priority priority) { switch (priority) { case Env::Priority::BOTTOM: @@ -422,5 +428,20 @@ EnvOptions::EnvOptions() { AssignEnvOptions(this, options); } +Status NewEnvLogger(const std::string& fname, Env* env, + std::shared_ptr* result) { + EnvOptions options; + // TODO: Tune the buffer size. + options.writable_file_max_buffer_size = 1024 * 1024; + std::unique_ptr writable_file; + const auto status = env->NewWritableFile(fname, &writable_file, options); + if (!status.ok()) { + return status; + } + + *result = std::make_shared(std::move(writable_file), fname, + options, env); + return Status::OK(); +} } // namespace rocksdb diff --git a/env/env_posix.cc b/env/env_posix.cc index c0edb00968ec0d753c337e48e32e6ec8146699c9..7f7f6b2df5b60a5a154221a5887f5b6aaf360a21 100644 --- a/env/env_posix.cc +++ b/env/env_posix.cc @@ -887,13 +887,14 @@ class PosixEnv : public Env { FILE* f; { IOSTATS_TIMER_GUARD(open_nanos); - f = fopen(fname.c_str(), "w" + f = fopen(fname.c_str(), + "w" #ifdef __GLIBC_PREREQ #if __GLIBC_PREREQ(2, 7) - "e" // glibc extension to enable O_CLOEXEC + "e" // glibc extension to enable O_CLOEXEC #endif #endif - ); + ); } if (f == nullptr) { result->reset(); diff --git a/env/io_posix.cc b/env/io_posix.cc index 304c4ffe1c7ff71d2652f5890c9af9551355fd41..293516feee84d199e9692c59cc603cb24bd65e5a 100644 --- a/env/io_posix.cc +++ b/env/io_posix.cc @@ -27,7 +27,6 @@ #include #include #endif -#include "logging/posix_logger.h" #include "monitoring/iostats_context_imp.h" #include "port/port.h" #include "rocksdb/slice.h" diff --git a/include/rocksdb/env.h b/include/rocksdb/env.h index ba8978dc810045915c49b04e3d10376afcd9706a..67464cc5c559f9a59d6c905c21aa8c9ff1ad4536 100644 --- a/include/rocksdb/env.h +++ b/include/rocksdb/env.h @@ -395,9 +395,11 @@ class Env { // same directory. virtual Status GetTestDirectory(std::string* path) = 0; - // Create and return a log file for storing informational messages. + // Create and returns a default logger (an instance of EnvLogger) for storing + // informational messages. Derived classes can overide to provide custom + // logger. virtual Status NewLogger(const std::string& fname, - std::shared_ptr* result) = 0; + std::shared_ptr* result); // Returns the number of micro-seconds since some fixed point in time. // It is often used as system time such as in GenericRateLimiter @@ -1563,4 +1565,10 @@ Status NewHdfsEnv(Env** hdfs_env, const std::string& fsname); // This is a factory method for TimedEnv defined in utilities/env_timed.cc. Env* NewTimedEnv(Env* base_env); +// Returns an instance of logger that can be used for storing informational +// messages. +// This is a factory method for EnvLogger declared in logging/env_logging.h +Status NewEnvLogger(const std::string& fname, Env* env, + std::shared_ptr* result); + } // namespace rocksdb diff --git a/logging/auto_roll_logger_test.cc b/logging/auto_roll_logger_test.cc index cce98d374ef6293cf493ad1f95d42737fcca52d9..fa668114cfb0e17c3ec902dfbdb2e611fe8e723c 100644 --- a/logging/auto_roll_logger_test.cc +++ b/logging/auto_roll_logger_test.cc @@ -22,6 +22,7 @@ #include "rocksdb/db.h" #include "test_util/sync_point.h" #include "test_util/testharness.h" +#include "test_util/testutil.h" namespace rocksdb { namespace { @@ -444,7 +445,7 @@ TEST_F(AutoRollLoggerTest, LogFlushWhileRolling) { {"AutoRollLogger::Flush:PinnedLogger", "PosixLogger::Flush:Begin2"}}); rocksdb::SyncPoint::GetInstance()->EnableProcessing(); - flush_thread = port::Thread ([&]() { auto_roll_logger->Flush(); }); + flush_thread = port::Thread([&]() { auto_roll_logger->Flush(); }); TEST_SYNC_POINT( "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit"); RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size, @@ -557,25 +558,6 @@ static std::vector GetOldFileNames(const std::string& path) { return ret; } -// Return the number of lines where a given pattern was found in the file -static size_t GetLinesCount(const std::string& fname, - const std::string& pattern) { - std::stringstream ssbuf; - std::string line; - size_t count = 0; - - std::ifstream inFile(fname.c_str()); - ssbuf << inFile.rdbuf(); - - while (getline(ssbuf, line)) { - if (line.find(pattern) != std::string::npos) { - count++; - } - } - - return count; -} - TEST_F(AutoRollLoggerTest, LogHeaderTest) { static const size_t MAX_HEADERS = 10; static const size_t LOG_MAX_SIZE = 1024 * 5; @@ -627,7 +609,7 @@ TEST_F(AutoRollLoggerTest, LogHeaderTest) { // verify that the files rolled over ASSERT_NE(oldfname, newfname); // verify that the old log contains all the header logs - ASSERT_EQ(GetLinesCount(oldfname, HEADER_STR), MAX_HEADERS); + ASSERT_EQ(test::GetLinesCount(oldfname, HEADER_STR), MAX_HEADERS); } } } diff --git a/logging/env_logger.h b/logging/env_logger.h new file mode 100644 index 0000000000000000000000000000000000000000..94cf129228ca27f0f632f25a7a08c2a3cf57e334 --- /dev/null +++ b/logging/env_logger.h @@ -0,0 +1,165 @@ +// 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). +// +// Copyright (c) 2011 The LevelDB Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. See the AUTHORS file for names of contributors. +// +// Logger implementation that uses custom Env object for logging. + +#pragma once + +#include +#include +#include "port/sys_time.h" +#include + +#include "monitoring/iostats_context_imp.h" +#include "rocksdb/env.h" +#include "rocksdb/slice.h" +#include "test_util/sync_point.h" +#include "util/file_reader_writer.h" +#include "util/mutexlock.h" + +namespace rocksdb { + +class EnvLogger : public Logger { + public: + EnvLogger(std::unique_ptr&& writable_file, + const std::string& fname, const EnvOptions& options, Env* env, + InfoLogLevel log_level = InfoLogLevel::ERROR_LEVEL) + : Logger(log_level), + file_(std::move(writable_file), fname, options, env), + last_flush_micros_(0), + env_(env), + flush_pending_(false) {} + + ~EnvLogger() { + if (!closed_) { + closed_ = true; + CloseHelper(); + } + } + + private: + void FlushLocked() { + mutex_.AssertHeld(); + if (flush_pending_) { + flush_pending_ = false; + file_.Flush(); + } + last_flush_micros_ = env_->NowMicros(); + } + + void Flush() override { + TEST_SYNC_POINT("EnvLogger::Flush:Begin1"); + TEST_SYNC_POINT("EnvLogger::Flush:Begin2"); + + MutexLock l(&mutex_); + FlushLocked(); + } + + Status CloseImpl() override { return CloseHelper(); } + + Status CloseHelper() { + mutex_.Lock(); + const auto close_status = file_.Close(); + mutex_.Unlock(); + + if (close_status.ok()) { + return close_status; + } + return Status::IOError("Close of log file failed with error:" + + (close_status.getState() + ? std::string(close_status.getState()) + : std::string())); + } + + using Logger::Logv; + void Logv(const char* format, va_list ap) override { + IOSTATS_TIMER_GUARD(logger_nanos); + + const uint64_t thread_id = env_->GetThreadID(); + + // We try twice: the first time with a fixed-size stack allocated buffer, + // and the second time with a much larger dynamically allocated buffer. + char buffer[500]; + for (int iter = 0; iter < 2; iter++) { + char* base; + int bufsize; + if (iter == 0) { + bufsize = sizeof(buffer); + base = buffer; + } else { + bufsize = 65536; + base = new char[bufsize]; + } + char* p = base; + char* limit = base + bufsize; + + struct timeval now_tv; + gettimeofday(&now_tv, nullptr); + const time_t seconds = now_tv.tv_sec; + struct tm t; + localtime_r(&seconds, &t); + p += snprintf(p, limit - p, "%04d/%02d/%02d-%02d:%02d:%02d.%06d %llx ", + t.tm_year + 1900, t.tm_mon + 1, t.tm_mday, t.tm_hour, + t.tm_min, t.tm_sec, static_cast(now_tv.tv_usec), + static_cast(thread_id)); + + // Print the message + if (p < limit) { + va_list backup_ap; + va_copy(backup_ap, ap); + p += vsnprintf(p, limit - p, format, backup_ap); + va_end(backup_ap); + } + + // Truncate to available space if necessary + if (p >= limit) { + if (iter == 0) { + continue; // Try again with larger buffer + } else { + p = limit - 1; + } + } + + // Add newline if necessary + if (p == base || p[-1] != '\n') { + *p++ = '\n'; + } + + assert(p <= limit); + mutex_.Lock(); + // We will ignore any error returned by Append(). + file_.Append(Slice(base, p - base)); + flush_pending_ = true; + const uint64_t now_micros = env_->NowMicros(); + if (now_micros - last_flush_micros_ >= flush_every_seconds_ * 1000000) { + FlushLocked(); + } + mutex_.Unlock(); + if (base != buffer) { + delete[] base; + } + break; + } + } + + size_t GetLogFileSize() const override { + MutexLock l(&mutex_); + return file_.GetFileSize(); + } + + private: + WritableFileWriter file_; + mutable port::Mutex mutex_; // Mutex to protect the shared variables below. + const static uint64_t flush_every_seconds_ = 5; + std::atomic_uint_fast64_t last_flush_micros_; + Env* env_; + std::atomic flush_pending_; +}; + +} // namespace rocksdb diff --git a/logging/env_logger_test.cc b/logging/env_logger_test.cc new file mode 100644 index 0000000000000000000000000000000000000000..316c231fad97abddfd5e5d5d715409bff8f2ccea --- /dev/null +++ b/logging/env_logger_test.cc @@ -0,0 +1,164 @@ +// 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 "env/mock_env.h" +#include "logging/env_logger.h" +#include "test_util/testharness.h" +#include "test_util/testutil.h" + +namespace rocksdb { + +namespace { +// In this test we only want to Log some simple log message with +// no format. +void LogMessage(std::shared_ptr logger, const std::string& message) { + Log(logger, "%s", message.c_str()); +} + +// Helper method to write the message num_times in the given logger. +void WriteLogs(std::shared_ptr logger, const std::string& message, + int num_times) { + for (int ii = 0; ii < num_times; ++ii) { + LogMessage(logger, message); + } +} + +} // namespace + +class EnvLoggerTest : public testing::Test { + public: + Env* env_; + + EnvLoggerTest() : env_(Env::Default()) {} + + ~EnvLoggerTest() = default; + + std::shared_ptr CreateLogger() { + std::shared_ptr result; + assert(NewEnvLogger(kLogFile, env_, &result).ok()); + assert(result); + result->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL); + return result; + } + + void DeleteLogFile() { + ASSERT_OK(env_->DeleteFile(kLogFile)); + } + + static const std::string kSampleMessage; + static const std::string kTestDir; + static const std::string kLogFile; +}; + +const std::string EnvLoggerTest::kSampleMessage = + "this is the message to be written to the log file!!"; +const std::string EnvLoggerTest::kLogFile = test::PerThreadDBPath("log_file"); + +TEST_F(EnvLoggerTest, EmptyLogFile) { + auto logger = CreateLogger(); + ASSERT_EQ(logger->Close(), Status::OK()); + + // Check the size of the log file. + uint64_t file_size; + ASSERT_EQ(env_->GetFileSize(kLogFile, &file_size), Status::OK()); + ASSERT_EQ(file_size, 0); + DeleteLogFile(); +} + +TEST_F(EnvLoggerTest, LogMultipleLines) { + auto logger = CreateLogger(); + + // Write multiple lines. + const int kNumIter = 10; + WriteLogs(logger, kSampleMessage, kNumIter); + + // Flush the logs. + logger->Flush(); + ASSERT_EQ(logger->Close(), Status::OK()); + + // Validate whether the log file has 'kNumIter' number of lines. + ASSERT_EQ(test::GetLinesCount(kLogFile, kSampleMessage), kNumIter); + DeleteLogFile(); +} + +TEST_F(EnvLoggerTest, Overwrite) { + { + auto logger = CreateLogger(); + + // Write multiple lines. + const int kNumIter = 10; + WriteLogs(logger, kSampleMessage, kNumIter); + + ASSERT_EQ(logger->Close(), Status::OK()); + + // Validate whether the log file has 'kNumIter' number of lines. + ASSERT_EQ(test::GetLinesCount(kLogFile, kSampleMessage), kNumIter); + } + + // Now reopen the file again. + { + auto logger = CreateLogger(); + + // File should be empty. + uint64_t file_size; + ASSERT_EQ(env_->GetFileSize(kLogFile, &file_size), Status::OK()); + ASSERT_EQ(file_size, 0); + ASSERT_EQ(logger->GetLogFileSize(), 0); + ASSERT_EQ(logger->Close(), Status::OK()); + } + DeleteLogFile(); +} + +TEST_F(EnvLoggerTest, Close) { + auto logger = CreateLogger(); + + // Write multiple lines. + const int kNumIter = 10; + WriteLogs(logger, kSampleMessage, kNumIter); + + ASSERT_EQ(logger->Close(), Status::OK()); + + // Validate whether the log file has 'kNumIter' number of lines. + ASSERT_EQ(test::GetLinesCount(kLogFile, kSampleMessage), kNumIter); + DeleteLogFile(); +} + +TEST_F(EnvLoggerTest, ConcurrentLogging) { + auto logger = CreateLogger(); + + const int kNumIter = 20; + std::function cb = [&]() { + WriteLogs(logger, kSampleMessage, kNumIter); + logger->Flush(); + }; + + // Write to the logs from multiple threads. + std::vector threads; + const int kNumThreads = 5; + // Create threads. + for (int ii = 0; ii < kNumThreads; ++ii) { + threads.push_back(port::Thread(cb)); + } + + // Wait for them to complete. + for (auto& th : threads) { + th.join(); + } + + ASSERT_EQ(logger->Close(), Status::OK()); + + // Verfiy the log file. + ASSERT_EQ(test::GetLinesCount(kLogFile, kSampleMessage), + kNumIter * kNumThreads); + DeleteLogFile(); +} + +} // namespace rocksdb + +int main(int argc, char** argv) { + ::testing::InitGoogleTest(&argc, argv); + return RUN_ALL_TESTS(); +} diff --git a/src.mk b/src.mk index 7c35ee67589eeb637e7fcf10471bc0393a87c5ce..8b0122dbe225862f01b7406da9b8d7f368bc42f2 100644 --- a/src.mk +++ b/src.mk @@ -345,6 +345,7 @@ MAIN_SOURCES = \ env/env_test.cc \ env/mock_env_test.cc \ logging/auto_roll_logger_test.cc \ + logging/env_logger_test.cc \ logging/event_logger_test.cc \ memory/arena_test.cc \ memtable/inlineskiplist_test.cc \ diff --git a/test_util/testutil.cc b/test_util/testutil.cc index 61a49d88a17d48d8dbeea17731dcde862a55afa4..46f878f8ce5c0969e99be4400f1d51b9f2871c56 100644 --- a/test_util/testutil.cc +++ b/test_util/testutil.cc @@ -11,6 +11,7 @@ #include #include +#include #include #include "db/memtable_list.h" @@ -426,5 +427,22 @@ bool IsDirectIOSupported(Env* env, const std::string& dir) { return s.ok(); } +size_t GetLinesCount(const std::string& fname, const std::string& pattern) { + std::stringstream ssbuf; + std::string line; + size_t count = 0; + + std::ifstream inFile(fname.c_str()); + ssbuf << inFile.rdbuf(); + + while (getline(ssbuf, line)) { + if (line.find(pattern) != std::string::npos) { + count++; + } + } + + return count; +} + } // namespace test } // namespace rocksdb diff --git a/test_util/testutil.h b/test_util/testutil.h index bc0b2b07d5fc591a643f300b3773e95a3504b588..bb732ff3a5a3a7456a67d6f784b9124366c5a7c9 100644 --- a/test_util/testutil.h +++ b/test_util/testutil.h @@ -750,5 +750,8 @@ Status DestroyDir(Env* env, const std::string& dir); bool IsDirectIOSupported(Env* env, const std::string& dir); +// Return the number of lines where a given pattern was found in a file. +size_t GetLinesCount(const std::string& fname, const std::string& pattern); + } // namespace test } // namespace rocksdb diff --git a/util/file_reader_writer.h b/util/file_reader_writer.h index 0a7e5032d2fbdd6ad7cd42cb8e7f4e081c8cfa75..0c5089d0758d2057dd58ac1471ba3524f651f8bc 100644 --- a/util/file_reader_writer.h +++ b/util/file_reader_writer.h @@ -282,7 +282,7 @@ class WritableFileWriter { // returns NotSupported status. Status SyncWithoutFlush(bool use_fsync); - uint64_t GetFileSize() { return filesize_; } + uint64_t GetFileSize() const { return filesize_; } Status InvalidateCache(size_t offset, size_t length) { return writable_file_->InvalidateCache(offset, length);