mirror of
https://github.com/facebook/rocksdb.git
synced 2026-10-23 08:09:02 +03:00
Summary: Pull Request resolved: https://github.com/facebook/rocksdb/pull/15436 ## Why Long-held global mutexes can stall foreground and background work. Existing mutex statistics measure acquisition waits, not continuous ownership. This adds opt-in logging to identify the mutex, owning thread, operation and release site. ## Enable for an investigation Provide an INFO logger and shared `Statistics` object when opening the DB, then: - Set the shared statistics level to `StatsLevel::kAll`. - Set `mutex_hold_log_threshold_us` through `DB::SetDBOptions`; `100000` means 100 ms. - Restore threshold 0 and the previous statistics level afterward. The threshold defaults to **0 (disabled)**. `kAll` alone does not enable these hold probes; threshold 0 leaves existing statistics timers unchanged. ## Output Illustrative records, not production observations: ``` SLOW_GLOBAL_MUTEX mutex=DBImpl::mutex_ mutex_addr=0x12340000 owner_thread_id=12345 thread_operation=Compaction hold_us=200000 threshold_us=100000 observed_end_us=1792205400000000 buffer_dropped_records=0 unlock=db_impl_compaction_flush.cc:4660 BackgroundCallCompaction() SLOW_GLOBAL_MUTEX mutex=DBImpl::wal_write_mutex_ mutex_addr=0x12340100 owner_thread_id=12346 thread_operation= hold_us=35000 threshold_us=25000 observed_end_us=1792205401000000 buffer_dropped_records=0 scope_exit=db_impl_write.cc:2250 PreprocessWrite() ``` The first proves a completed 200 ms DB-mutex ownership interval on a thread tagged `Compaction`. The second uses a 25 ms threshold; an empty operation tag means none was available. Neither record reports acquisition wait or proves the cause of a stall. Release attribution uses compiler-embedded strings available in optimized, stripped builds, with a GCC/Clang fallback where standard source locations are unavailable. Direct unlock and condition wait identify their call sites; scope exit and temporary unlock identify guard declarations, not closing braces. No stack unwinding or symbol lookup. ## Scope and safety - Track six selected mutexes: DB, WAL, point-lock wait graph, two prepare-log bookkeeping mutexes and transaction name map. This is not comprehensive synchronization tracing. - Acquisition waits and condition-variable release gaps are excluded from hold duration. Configuration is pre-first-use; repeated setup retains the first valid context. - Sample at most once per mutex per second, with eight deferred records per thread. `buffer_dropped_records` counts capacity overflow only; rate limiting, pause and emission contention can omit samples. - Emit after covered outer lock scopes release. Emission is nonblocking best-effort; shutdown drains/pauses emission and stops diagnostics before the owned logger closes. Closing from that logger's own callback is unsupported. - No data-file format change. The mutable option is persisted in OPTIONS and wired into bench/stress tools. Typed C binding is deferred; string DB-option APIs are available. Disabled bookkeeping still has a cost. Release A/B measurements found about 3 ns added per selected mutex pair at level 1, and about 70 ns for hold timing over `kAll`/0. Get and reused-iterator Seek showed no resolved small probe effect; fresh iterator+Seek at 16 threads showed +8.7% CPU/query and -9.4% QPS. No logs were emitted in those benchmarks; logging cost and broader workload qualification remain open. Reviewed By: xingbowang Differential Revision: D125790955 fbshipit-source-id: 1096163f3bd25ffee585dc6ec8ebfd7f1759851a
401 lines
13 KiB
C++
401 lines
13 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).
|
|
|
|
#pragma once
|
|
|
|
#include <atomic>
|
|
#include <cstdint>
|
|
#include <memory>
|
|
#include <mutex>
|
|
#include <utility>
|
|
#include <version>
|
|
|
|
#if defined(__cpp_lib_source_location) && __has_include(<source_location>)
|
|
#include <source_location>
|
|
#endif
|
|
|
|
#include "monitoring/statistics_impl.h"
|
|
#include "port/port.h"
|
|
#include "rocksdb/env.h"
|
|
#include "rocksdb/statistics.h"
|
|
#include "rocksdb/system_clock.h"
|
|
#include "rocksdb/thread_status.h"
|
|
#include "test_util/sync_point.h"
|
|
#include "util/stop_watch.h"
|
|
|
|
namespace ROCKSDB_NAMESPACE {
|
|
class InstrumentedCondVar;
|
|
|
|
#if defined(__cpp_lib_source_location) && __has_include(<source_location>) && \
|
|
!defined(ROCKSDB_TEST_MUTEX_LOCATION_FALLBACK)
|
|
using MutexSourceLocation = std::source_location;
|
|
#else
|
|
// Older libc++ lacks source_location; compiler builtins preserve caller sites.
|
|
class MutexSourceLocation {
|
|
public:
|
|
#if defined(__GNUC__) || defined(__clang__)
|
|
static constexpr MutexSourceLocation current(
|
|
const char* file = __builtin_FILE(), uint32_t line = __builtin_LINE(),
|
|
const char* function = __builtin_FUNCTION()) noexcept {
|
|
return MutexSourceLocation(file, line, function);
|
|
}
|
|
#else
|
|
static constexpr MutexSourceLocation current() noexcept { return {}; }
|
|
#endif
|
|
constexpr MutexSourceLocation() noexcept = default;
|
|
constexpr const char* file_name() const noexcept { return file_; }
|
|
constexpr uint32_t line() const noexcept { return line_; }
|
|
constexpr const char* function_name() const noexcept { return function_; }
|
|
|
|
private:
|
|
constexpr MutexSourceLocation(const char* file, uint32_t line,
|
|
const char* function) noexcept
|
|
: file_(file), function_(function), line_(line) {}
|
|
const char* file_ = "";
|
|
const char* function_ = "";
|
|
uint32_t line_ = 0;
|
|
};
|
|
#endif
|
|
|
|
struct SlowMutexLoggingContext {
|
|
SlowMutexLoggingContext(Statistics* s, SystemClock* c, Env* e,
|
|
std::shared_ptr<Logger> l,
|
|
const std::atomic<uint64_t>* threshold)
|
|
: stats(s),
|
|
clock(c),
|
|
env(e),
|
|
logger(std::move(l)),
|
|
threshold_us(threshold) {}
|
|
|
|
Statistics* stats;
|
|
SystemClock* clock;
|
|
Env* env;
|
|
std::shared_ptr<Logger> logger;
|
|
const std::atomic<uint64_t>* threshold_us;
|
|
std::atomic<bool> paused{false};
|
|
std::atomic<bool> stopped{false};
|
|
std::mutex emission_mutex;
|
|
};
|
|
|
|
// Enter before taking DB closing locks, not from the context's own Logv().
|
|
// Failed close attempts resume probes unless the logger was closed.
|
|
class SlowMutexLoggingPause {
|
|
public:
|
|
explicit SlowMutexLoggingPause(
|
|
std::shared_ptr<SlowMutexLoggingContext> context)
|
|
: context_(std::move(context)) {
|
|
if (context_) {
|
|
lock_ = std::unique_lock<std::mutex>(context_->emission_mutex);
|
|
context_->paused.store(true, std::memory_order_relaxed);
|
|
}
|
|
}
|
|
SlowMutexLoggingPause(const SlowMutexLoggingPause&) = delete;
|
|
SlowMutexLoggingPause& operator=(const SlowMutexLoggingPause&) = delete;
|
|
SlowMutexLoggingPause(SlowMutexLoggingPause&&) = delete;
|
|
SlowMutexLoggingPause& operator=(SlowMutexLoggingPause&&) = delete;
|
|
~SlowMutexLoggingPause() {
|
|
if (context_) {
|
|
context_->paused.store(false, std::memory_order_relaxed);
|
|
}
|
|
}
|
|
|
|
private:
|
|
std::shared_ptr<SlowMutexLoggingContext> context_;
|
|
std::unique_lock<std::mutex> lock_;
|
|
};
|
|
|
|
// Configured only for explicitly selected DB-wide mutexes, before first use.
|
|
// Start/Stop require ownership; FlushLogs must run after the actual unlock.
|
|
// Stop receives compiler-backed strings; it retains only sampled release sites.
|
|
class SlowMutexTimer {
|
|
public:
|
|
SlowMutexTimer(std::shared_ptr<SlowMutexLoggingContext> context,
|
|
const char* name, const void* mutex);
|
|
SlowMutexTimer(const SlowMutexTimer&) = delete;
|
|
SlowMutexTimer& operator=(const SlowMutexTimer&) = delete;
|
|
SlowMutexTimer(SlowMutexTimer&&) = delete;
|
|
SlowMutexTimer& operator=(SlowMutexTimer&&) = delete;
|
|
~SlowMutexTimer() = default;
|
|
|
|
void Start();
|
|
void Stop(const MutexSourceLocation& location, const char* release_kind);
|
|
static void FlushLogs();
|
|
Statistics* GetStatistics() const { return context_->stats; }
|
|
|
|
private:
|
|
std::shared_ptr<SlowMutexLoggingContext> context_;
|
|
const char* name_;
|
|
const void* mutex_;
|
|
uint64_t start_ns_ = 0;
|
|
uint64_t last_log_ns_ = 0;
|
|
ThreadStatus::OperationType operation_ = ThreadStatus::OP_UNKNOWN;
|
|
bool active_ = false;
|
|
bool logged_ = false;
|
|
};
|
|
|
|
// Defers emission across callers that own other, unmeasured locks.
|
|
class SlowMutexLogScope {
|
|
public:
|
|
explicit SlowMutexLogScope(bool armed) : armed_(armed) {
|
|
if (armed_) {
|
|
Begin();
|
|
}
|
|
}
|
|
~SlowMutexLogScope() { Release(); }
|
|
void Release() {
|
|
if (armed_) {
|
|
armed_ = false;
|
|
End();
|
|
}
|
|
}
|
|
SlowMutexLogScope(const SlowMutexLogScope&) = delete;
|
|
SlowMutexLogScope& operator=(const SlowMutexLogScope&) = delete;
|
|
SlowMutexLogScope(SlowMutexLogScope&&) = delete;
|
|
SlowMutexLogScope& operator=(SlowMutexLogScope&&) = delete;
|
|
|
|
private:
|
|
static void Begin();
|
|
static void End();
|
|
bool armed_;
|
|
};
|
|
|
|
// Compiler-supplied locations are defaulted at caller-facing methods so direct
|
|
// releases need no call-site edits. Scope-exit locations identify the guard
|
|
// declaration, not a compiler-synthesized destructor or closing-brace line.
|
|
// No stack capture or symbolization is performed.
|
|
// Preserves std::mutex locking semantics while timing a selected mutex.
|
|
class SlowMutexLock {
|
|
public:
|
|
SlowMutexLock(std::mutex* mutex, SlowMutexTimer* timer,
|
|
MutexSourceLocation location = MutexSourceLocation::current())
|
|
: mutex_(mutex), timer_(timer), location_(location) {
|
|
mutex_->lock();
|
|
if (timer_) {
|
|
timer_->Start();
|
|
}
|
|
}
|
|
~SlowMutexLock() {
|
|
if (timer_) {
|
|
timer_->Stop(location_, "scope_exit");
|
|
}
|
|
mutex_->unlock();
|
|
if (timer_) {
|
|
SlowMutexTimer::FlushLogs();
|
|
}
|
|
}
|
|
SlowMutexLock(const SlowMutexLock&) = delete;
|
|
SlowMutexLock& operator=(const SlowMutexLock&) = delete;
|
|
SlowMutexLock(SlowMutexLock&&) = delete;
|
|
SlowMutexLock& operator=(SlowMutexLock&&) = delete;
|
|
|
|
private:
|
|
std::mutex* mutex_;
|
|
SlowMutexTimer* timer_;
|
|
MutexSourceLocation location_;
|
|
};
|
|
|
|
// A wrapper class for port::Mutex that provides additional layer
|
|
// for collecting stats and instrumentation.
|
|
class InstrumentedMutex {
|
|
public:
|
|
explicit InstrumentedMutex(bool adaptive = false)
|
|
: mutex_(adaptive), stats_(nullptr), clock_(nullptr), stats_code_(0) {}
|
|
|
|
explicit InstrumentedMutex(SystemClock* clock, bool adaptive = false)
|
|
: mutex_(adaptive), stats_(nullptr), clock_(clock), stats_code_(0) {}
|
|
|
|
InstrumentedMutex(Statistics* stats, SystemClock* clock, int stats_code,
|
|
bool adaptive = false)
|
|
: mutex_(adaptive),
|
|
stats_(stats),
|
|
clock_(clock),
|
|
stats_code_(stats_code) {}
|
|
|
|
#ifdef COERCE_CONTEXT_SWITCH
|
|
InstrumentedMutex(Statistics* stats, SystemClock* clock, int stats_code,
|
|
InstrumentedCondVar* bg_cv, bool adaptive = false)
|
|
: mutex_(adaptive),
|
|
stats_(stats),
|
|
clock_(clock),
|
|
stats_code_(stats_code),
|
|
bg_cv_(bg_cv) {}
|
|
#endif
|
|
|
|
InstrumentedMutex(const InstrumentedMutex&) = delete;
|
|
InstrumentedMutex& operator=(const InstrumentedMutex&) = delete;
|
|
InstrumentedMutex(InstrumentedMutex&&) = delete;
|
|
InstrumentedMutex& operator=(InstrumentedMutex&&) = delete;
|
|
~InstrumentedMutex() {
|
|
if (has_slow_timer_) {
|
|
delete slow_timer_;
|
|
}
|
|
}
|
|
|
|
void Lock();
|
|
|
|
bool TryLock() {
|
|
if (!mutex_.TryLock()) {
|
|
return false;
|
|
}
|
|
if (has_slow_timer_) {
|
|
slow_timer_->Start();
|
|
}
|
|
return true;
|
|
}
|
|
|
|
void Unlock(MutexSourceLocation location = MutexSourceLocation::current()) {
|
|
Unlock(location, "unlock");
|
|
}
|
|
|
|
void Unlock(const MutexSourceLocation& location, const char* release_kind) {
|
|
const bool tracked = has_slow_timer_;
|
|
if (tracked) {
|
|
slow_timer_->Stop(location, release_kind);
|
|
}
|
|
mutex_.Unlock();
|
|
TEST_SYNC_POINT_CALLBACK("InstrumentedMutex::Unlock:AfterUnlock", this);
|
|
if (tracked) {
|
|
SlowMutexTimer::FlushLogs();
|
|
}
|
|
}
|
|
|
|
// First valid configuration wins; call only before the mutex's first use.
|
|
void ConfigureSlowHoldLogging(
|
|
std::shared_ptr<SlowMutexLoggingContext> context, const char* name);
|
|
|
|
void AssertHeld() const { mutex_.AssertHeld(); }
|
|
|
|
private:
|
|
Statistics* GetStatistics() const {
|
|
return has_slow_timer_ ? slow_timer_->GetStatistics() : stats_;
|
|
}
|
|
void LockInternal();
|
|
friend class InstrumentedCondVar;
|
|
port::Mutex mutex_;
|
|
// The optional timer owns this slot and retains the borrowed Statistics.
|
|
// The tag fits the existing padding, keeping cache-aligned mutexes compact.
|
|
union {
|
|
Statistics* stats_;
|
|
SlowMutexTimer* slow_timer_;
|
|
};
|
|
SystemClock* clock_;
|
|
int stats_code_;
|
|
bool has_slow_timer_ = false;
|
|
#ifdef COERCE_CONTEXT_SWITCH
|
|
InstrumentedCondVar* bg_cv_ = nullptr;
|
|
#endif
|
|
};
|
|
|
|
class ALIGN_AS(CACHE_LINE_SIZE) CacheAlignedInstrumentedMutex
|
|
: public InstrumentedMutex {
|
|
using InstrumentedMutex::InstrumentedMutex;
|
|
};
|
|
static_assert(alignof(CacheAlignedInstrumentedMutex) != CACHE_LINE_SIZE ||
|
|
sizeof(CacheAlignedInstrumentedMutex) % CACHE_LINE_SIZE == 0);
|
|
|
|
// RAII wrapper for InstrumentedMutex
|
|
class InstrumentedMutexLock {
|
|
public:
|
|
explicit InstrumentedMutexLock(
|
|
InstrumentedMutex* mutex,
|
|
MutexSourceLocation location = MutexSourceLocation::current())
|
|
: mutex_(mutex), location_(location) {
|
|
mutex_->Lock();
|
|
}
|
|
|
|
~InstrumentedMutexLock() { mutex_->Unlock(location_, "scope_exit"); }
|
|
|
|
private:
|
|
InstrumentedMutex* const mutex_;
|
|
MutexSourceLocation location_;
|
|
InstrumentedMutexLock(const InstrumentedMutexLock&) = delete;
|
|
void operator=(const InstrumentedMutexLock&) = delete;
|
|
InstrumentedMutexLock(InstrumentedMutexLock&&) = delete;
|
|
void operator=(InstrumentedMutexLock&&) = delete;
|
|
};
|
|
|
|
// Release the unmeasured outer mutex before emitting nested hold records.
|
|
class DeferredInstrumentedMutexLock {
|
|
public:
|
|
DeferredInstrumentedMutexLock(
|
|
InstrumentedMutex* mutex, bool armed,
|
|
MutexSourceLocation location = MutexSourceLocation::current())
|
|
: defer_logs_(armed), mutex_(mutex), location_(location) {
|
|
mutex_->Lock();
|
|
}
|
|
~DeferredInstrumentedMutexLock() { Release(location_, "scope_exit"); }
|
|
void Unlock(MutexSourceLocation location = MutexSourceLocation::current()) {
|
|
Release(location, "unlock");
|
|
}
|
|
DeferredInstrumentedMutexLock(const DeferredInstrumentedMutexLock&) = delete;
|
|
DeferredInstrumentedMutexLock& operator=(
|
|
const DeferredInstrumentedMutexLock&) = delete;
|
|
DeferredInstrumentedMutexLock(DeferredInstrumentedMutexLock&&) = delete;
|
|
DeferredInstrumentedMutexLock& operator=(DeferredInstrumentedMutexLock&&) =
|
|
delete;
|
|
|
|
private:
|
|
void Release(const MutexSourceLocation& location, const char* release_kind) {
|
|
if (mutex_) {
|
|
mutex_->Unlock(location, release_kind);
|
|
mutex_ = nullptr;
|
|
defer_logs_.Release();
|
|
}
|
|
}
|
|
SlowMutexLogScope defer_logs_;
|
|
InstrumentedMutex* mutex_;
|
|
MutexSourceLocation location_;
|
|
};
|
|
|
|
// RAII wrapper for temporary releasing InstrumentedMutex inside
|
|
// InstrumentedMutexLock
|
|
class InstrumentedMutexUnlock {
|
|
public:
|
|
explicit InstrumentedMutexUnlock(
|
|
InstrumentedMutex* mutex,
|
|
MutexSourceLocation location = MutexSourceLocation::current())
|
|
: mutex_(mutex) {
|
|
mutex_->Unlock(location, "temporary_unlock");
|
|
}
|
|
|
|
~InstrumentedMutexUnlock() { mutex_->Lock(); }
|
|
|
|
private:
|
|
InstrumentedMutex* const mutex_;
|
|
InstrumentedMutexUnlock(const InstrumentedMutexUnlock&) = delete;
|
|
void operator=(const InstrumentedMutexUnlock&) = delete;
|
|
InstrumentedMutexUnlock(InstrumentedMutexUnlock&&) = delete;
|
|
void operator=(InstrumentedMutexUnlock&&) = delete;
|
|
};
|
|
|
|
class InstrumentedCondVar {
|
|
public:
|
|
explicit InstrumentedCondVar(InstrumentedMutex* instrumented_mutex)
|
|
: cond_(&(instrumented_mutex->mutex_)),
|
|
instrumented_mutex_(instrumented_mutex),
|
|
clock_(instrumented_mutex->clock_),
|
|
stats_code_(instrumented_mutex->stats_code_) {}
|
|
|
|
void Wait(MutexSourceLocation location = MutexSourceLocation::current());
|
|
|
|
bool TimedWait(uint64_t abs_time_us,
|
|
MutexSourceLocation location = MutexSourceLocation::current());
|
|
|
|
void Signal() { cond_.Signal(); }
|
|
|
|
void SignalAll() { cond_.SignalAll(); }
|
|
|
|
private:
|
|
void WaitInternal(const MutexSourceLocation& location);
|
|
bool TimedWaitInternal(uint64_t abs_time_us,
|
|
const MutexSourceLocation& location);
|
|
port::CondVar cond_;
|
|
InstrumentedMutex* instrumented_mutex_;
|
|
SystemClock* clock_;
|
|
int stats_code_;
|
|
};
|
|
|
|
} // namespace ROCKSDB_NAMESPACE
|