mirror of
https://github.com/facebook/rocksdb.git
synced 2026-10-23 08:09:02 +03:00
d6a7847d37
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
84 lines
2.9 KiB
C++
84 lines
2.9 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).
|
|
//
|
|
#include "db/logs_with_prep_tracker.h"
|
|
|
|
#include "port/likely.h"
|
|
|
|
namespace ROCKSDB_NAMESPACE {
|
|
void LogsWithPrepTracker::ConfigureSlowHoldLogging(
|
|
std::shared_ptr<SlowMutexLoggingContext> context) {
|
|
if (context == nullptr) {
|
|
return;
|
|
}
|
|
logs_with_prep_timer_.reset(
|
|
new SlowMutexTimer(context, "LogsWithPrepTracker::logs_with_prep_mutex_",
|
|
&logs_with_prep_mutex_));
|
|
prepared_section_completed_timer_.reset(new SlowMutexTimer(
|
|
std::move(context),
|
|
"LogsWithPrepTracker::prepared_section_completed_mutex_",
|
|
&prepared_section_completed_mutex_));
|
|
}
|
|
|
|
void LogsWithPrepTracker::MarkLogAsHavingPrepSectionFlushed(uint64_t log) {
|
|
assert(log != 0);
|
|
SlowMutexLock lock(&prepared_section_completed_mutex_,
|
|
prepared_section_completed_timer_.get());
|
|
auto it = prepared_section_completed_.find(log);
|
|
if (UNLIKELY(it == prepared_section_completed_.end())) {
|
|
prepared_section_completed_[log] = 1;
|
|
} else {
|
|
it->second += 1;
|
|
}
|
|
}
|
|
|
|
void LogsWithPrepTracker::MarkLogAsContainingPrepSection(uint64_t log) {
|
|
assert(log != 0);
|
|
SlowMutexLock lock(&logs_with_prep_mutex_, logs_with_prep_timer_.get());
|
|
|
|
auto rit = logs_with_prep_.rbegin();
|
|
bool updated = false;
|
|
// Most probably the last log is the one that is being marked for
|
|
// having a prepare section; so search from the end.
|
|
for (; rit != logs_with_prep_.rend() && rit->log >= log; ++rit) {
|
|
if (rit->log == log) {
|
|
rit->cnt++;
|
|
updated = true;
|
|
break;
|
|
}
|
|
}
|
|
if (!updated) {
|
|
// We are either at the start, or at a position with rit->log < log
|
|
logs_with_prep_.insert(rit.base(), {log, 1});
|
|
}
|
|
}
|
|
|
|
uint64_t LogsWithPrepTracker::FindMinLogContainingOutstandingPrep() {
|
|
SlowMutexLock lock(&logs_with_prep_mutex_, logs_with_prep_timer_.get());
|
|
auto it = logs_with_prep_.begin();
|
|
// start with the smallest log
|
|
for (; it != logs_with_prep_.end();) {
|
|
auto min_log = it->log;
|
|
{
|
|
SlowMutexLock lock2(&prepared_section_completed_mutex_,
|
|
prepared_section_completed_timer_.get());
|
|
auto completed_it = prepared_section_completed_.find(min_log);
|
|
if (completed_it == prepared_section_completed_.end() ||
|
|
completed_it->second < it->cnt) {
|
|
return min_log;
|
|
}
|
|
assert(completed_it != prepared_section_completed_.end() &&
|
|
completed_it->second == it->cnt);
|
|
prepared_section_completed_.erase(completed_it);
|
|
}
|
|
// erase from beginning in vector is not efficient but this function is not
|
|
// on the fast path.
|
|
it = logs_with_prep_.erase(it);
|
|
}
|
|
// no such log found
|
|
return 0;
|
|
}
|
|
} // namespace ROCKSDB_NAMESPACE
|