rocksdb/util/stop_watch.h
Hui Xiao dcc6fc99f9 Fix StopWatch bug; Remove setting record_read_stats (#11474)
Summary:
**Context/Summary:**
- StopWatch enable stats even when `StatsLevel::kExceptTimers` is set. It's a harmless bug though since `reportTimeToHistogram()` will not report it anyway according to https://github.com/facebook/rocksdb/blob/main/include/rocksdb/statistics.h#L705
-  https://github.com/facebook/rocksdb/pull/11288 should have removed logics of setting `record_read_stats = !for_compaction` as we don't differentiate `RandomAccessFileReader`'s stats behavior based on compaction or not (instead we now report stats of different IO activities including compaction to different stats). Fixing this should report more compaction related file read micros that aren't reported previously due to `for_compaction==true`

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

Test Plan:
- DB bench pre vs post fix with small max_open_files

Setup command
`./db_ bench  -db=/dev/shm/testdb/ -statistics=true -benchmarks=fillseq -key_size=32 -value_size=512 -num=5000 -write_buffer_size=655 -target_file_size_base=655 -disable_auto_compactions=true -compression_type=none -bloom_bits=3`

Run command
`./db_bench --open_files=1 -use_existing_db=true -db=/dev/shm/testdb2/ -statistics=true -benchmarks=compactall -key_size=32 -value_size=512 -num=5000 -write_buffer_size=655 -target_file_size_base=655 -disable_auto_compactions=true -compression_type=none -bloom_bits=3`

Pre-fix
```
rocksdb.sst.read.micros P50 : 2.056175 P95 : 4.647739 P99 : 8.948475 P100 : 25.000000 COUNT : 4451 SUM : 12827
rocksdb.file.read.flush.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
rocksdb.file.read.compaction.micros P50 : 2.057397 P95 : 4.625253 P99 : 8.749474 P100 : 25.000000 COUNT : 4382 SUM : 12608
rocksdb.file.read.db.open.micros P50 : 1.985294 P95 : 9.100000 P99 : 13.000000 P100 : 13.000000 COUNT : 69 SUM : 219
```

Post-fix (with a higher `rocksdb.file.read.compaction.micros` count)
```
rocksdb.sst.read.micros P50 : 1.858968 P95 : 3.653086 P99 : 5.968000 P100 : 21.000000 COUNT : 3548 SUM : 9119
rocksdb.file.read.flush.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
rocksdb.file.read.compaction.micros P50 : 1.857027 P95 : 3.627614 P99 : 5.738621 P100 : 21.000000 COUNT : 3479 SUM : 8904
rocksdb.file.read.db.open.micros P50 : 2.000000 P95 : 6.733333 P99 : 11.000000 P100 : 11.000000 COUNT : 69 SUM : 215
```
- CI

Reviewed By: ajkr

Differential Revision: D46137221

Pulled By: hx235

fbshipit-source-id: e5b4ee7001af26f2ee0377bc6334f43b2a527388
2023-05-25 10:16:58 -07:00

137 lines
4.4 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 "monitoring/statistics_impl.h"
#include "rocksdb/system_clock.h"
namespace ROCKSDB_NAMESPACE {
// Auto-scoped.
// When statistics is not nullptr, records the measured time into any enabled
// histograms supplied to the constructor. A histogram argument may be omitted
// by setting it to Histograms::HISTOGRAM_ENUM_MAX. It is also saved into
// *elapsed if the pointer is not nullptr and overwrite is true, it will be
// added to *elapsed if overwrite is false.
class StopWatch {
public:
StopWatch(SystemClock* clock, Statistics* statistics,
const uint32_t hist_type_1,
const uint32_t hist_type_2 = Histograms::HISTOGRAM_ENUM_MAX,
uint64_t* elapsed = nullptr, bool overwrite = true,
bool delay_enabled = false)
: clock_(clock),
statistics_(statistics),
hist_type_1_(statistics && statistics->HistEnabledForType(hist_type_1)
? hist_type_1
: Histograms::HISTOGRAM_ENUM_MAX),
hist_type_2_(statistics && statistics->HistEnabledForType(hist_type_2)
? hist_type_2
: Histograms::HISTOGRAM_ENUM_MAX),
elapsed_(elapsed),
overwrite_(overwrite),
stats_enabled_(statistics &&
statistics->get_stats_level() >
StatsLevel::kExceptTimers &&
(hist_type_1_ != Histograms::HISTOGRAM_ENUM_MAX ||
hist_type_2_ != Histograms::HISTOGRAM_ENUM_MAX)),
delay_enabled_(delay_enabled),
total_delay_(0),
delay_start_time_(0),
start_time_((stats_enabled_ || elapsed != nullptr) ? clock->NowMicros()
: 0) {}
~StopWatch() {
if (elapsed_) {
if (overwrite_) {
*elapsed_ = clock_->NowMicros() - start_time_;
} else {
*elapsed_ += clock_->NowMicros() - start_time_;
}
}
if (elapsed_ && delay_enabled_) {
*elapsed_ -= total_delay_;
}
if (stats_enabled_) {
const auto time = (elapsed_ != nullptr)
? *elapsed_
: (clock_->NowMicros() - start_time_);
if (hist_type_1_ != Histograms::HISTOGRAM_ENUM_MAX) {
statistics_->reportTimeToHistogram(hist_type_1_, time);
}
if (hist_type_2_ != Histograms::HISTOGRAM_ENUM_MAX) {
statistics_->reportTimeToHistogram(hist_type_2_, time);
}
}
}
void DelayStart() {
// if delay_start_time_ is not 0, it means we are already tracking delay,
// so delay_start_time_ should not be overwritten
if (elapsed_ && delay_enabled_ && delay_start_time_ == 0) {
delay_start_time_ = clock_->NowMicros();
}
}
void DelayStop() {
if (elapsed_ && delay_enabled_ && delay_start_time_ != 0) {
total_delay_ += clock_->NowMicros() - delay_start_time_;
}
// reset to 0 means currently no delay is being tracked, so two consecutive
// calls to DelayStop will not increase total_delay_
delay_start_time_ = 0;
}
uint64_t GetDelay() const { return delay_enabled_ ? total_delay_ : 0; }
uint64_t start_time() const { return start_time_; }
private:
SystemClock* clock_;
Statistics* statistics_;
const uint32_t hist_type_1_;
const uint32_t hist_type_2_;
uint64_t* elapsed_;
bool overwrite_;
bool stats_enabled_;
bool delay_enabled_;
uint64_t total_delay_;
uint64_t delay_start_time_;
const uint64_t start_time_;
};
// a nano second precision stopwatch
class StopWatchNano {
public:
explicit StopWatchNano(SystemClock* clock, bool auto_start = false)
: clock_(clock), start_(0) {
if (auto_start) {
Start();
}
}
void Start() { start_ = clock_->NowNanos(); }
uint64_t ElapsedNanos(bool reset = false) {
auto now = clock_->NowNanos();
auto elapsed = now - start_;
if (reset) {
start_ = now;
}
return elapsed;
}
uint64_t ElapsedNanosSafe(bool reset = false) {
return (clock_ != nullptr) ? ElapsedNanos(reset) : 0U;
}
bool IsStarted() { return start_ != 0; }
private:
SystemClock* clock_;
uint64_t start_;
};
} // namespace ROCKSDB_NAMESPACE