rocksdb/logging/env_logger.h
mrambacher 3dff28cf9b Use SystemClock* instead of std::shared_ptr<SystemClock> in lower level routines (#8033)
Summary:
For performance purposes, the lower level routines were changed to use a SystemClock* instead of a std::shared_ptr<SystemClock>.  The shared ptr has some performance degradation on certain hardware classes.

For most of the system, there is no risk of the pointer being deleted/invalid because the shared_ptr will be stored elsewhere.  For example, the ImmutableDBOptions stores the Env which has a std::shared_ptr<SystemClock> in it.  The SystemClock* within the ImmutableDBOptions is essentially a "short cut" to gain access to this constant resource.

There were a few classes (PeriodicWorkScheduler?) where the "short cut" property did not hold.  In those cases, the shared pointer was preserved.

Using db_bench readrandom perf_level=3 on my EC2 box, this change performed as well or better than 6.17:

6.17: readrandom   :      28.046 micros/op 854902 ops/sec;   61.3 MB/s (355999 of 355999 found)
6.18: readrandom   :      32.615 micros/op 735306 ops/sec;   52.7 MB/s (290999 of 290999 found)
PR: readrandom   :      27.500 micros/op 871909 ops/sec;   62.5 MB/s (367999 of 367999 found)

(Note that the times for 6.18 are prior to revert of the SystemClock).

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

Reviewed By: pdillinger

Differential Revision: D27014563

Pulled By: mrambacher

fbshipit-source-id: ad0459eba03182e454391b5926bf5cdd45657b67
2021-03-15 04:34:11 -07:00

168 lines
4.7 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).
//
// 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 <time.h>
#include <atomic>
#include <memory>
#include "port/sys_time.h"
#include "file/writable_file_writer.h"
#include "monitoring/iostats_context_imp.h"
#include "rocksdb/env.h"
#include "rocksdb/slice.h"
#include "test_util/sync_point.h"
#include "util/mutexlock.h"
namespace ROCKSDB_NAMESPACE {
class EnvLogger : public Logger {
public:
EnvLogger(std::unique_ptr<FSWritableFile>&& writable_file,
const std::string& fname, const EnvOptions& options, Env* env,
InfoLogLevel log_level = InfoLogLevel::ERROR_LEVEL)
: Logger(log_level),
env_(env),
clock_(env_->GetSystemClock().get()),
file_(std::move(writable_file), fname, options, clock_),
last_flush_micros_(0),
flush_pending_(false) {}
~EnvLogger() {
if (!closed_) {
closed_ = true;
CloseHelper().PermitUncheckedError();
}
}
private:
void FlushLocked() {
mutex_.AssertHeld();
if (flush_pending_) {
flush_pending_ = false;
file_.Flush().PermitUncheckedError();
}
last_flush_micros_ = clock_->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<int>(now_tv.tv_usec),
static_cast<long long unsigned int>(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)).PermitUncheckedError();
flush_pending_ = true;
const uint64_t now_micros = clock_->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:
Env* env_;
SystemClock* clock_;
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_;
std::atomic<bool> flush_pending_;
};
} // namespace ROCKSDB_NAMESPACE