From 694988b62793343c54d5620f7207c8d94e7d7f6e Mon Sep 17 00:00:00 2001 From: Yueh-Hsuan Chiang Date: Tue, 3 Mar 2015 12:48:12 -0800 Subject: [PATCH] Fix a bug in stall time counter. Improve its output format. Summary: Fix a bug in stall time counter. Improve its output format. Test Plan: export ROCKSDB_TESTS=Timeout ./db_test ./db_bench --benchmarks=fillrandom --stats_interval=10000 --statistics=true --stats_per_interval=1 --num=1000000 --threads=4 --level0_stop_writes_trigger=3 --level0_slowdown_writes_trigger=2 sample output: Uptime(secs): 35.8 total, 0.0 interval Cumulative writes: 359590 writes, 359589 keys, 183047 batches, 2.0 writes per batch, 0.04 GB user ingest, stall seconds: 1786.008 ms Cumulative WAL: 359591 writes, 183046 syncs, 1.96 writes per sync, 0.04 GB written Interval writes: 253 writes, 253 keys, 128 batches, 2.0 writes per batch, 0.0 MB user ingest, stall time: 0 us Interval WAL: 253 writes, 128 syncs, 1.96 writes per sync, 0.00 MB written Reviewers: MarkCallaghan, igor, sdong Reviewed By: sdong Subscribers: dhruba, leveldb Differential Revision: https://reviews.facebook.net/D34275 --- db/db_impl.cc | 8 +++++++- db/internal_stats.cc | 15 +++++++++++---- util/logging.cc | 14 ++++++++++++++ util/logging.h | 3 +++ 4 files changed, 35 insertions(+), 5 deletions(-) diff --git a/db/db_impl.cc b/db/db_impl.cc index 75229a67f..423d12dba 100644 --- a/db/db_impl.cc +++ b/db/db_impl.cc @@ -3233,6 +3233,7 @@ Status DBImpl::Write(const WriteOptions& write_options, WriteBatch* my_batch) { Status DBImpl::DelayWrite(uint64_t expiration_time) { uint64_t time_delayed = 0; bool delayed = false; + bool timed_out = false; { StopWatch sw(env_, stats_, WRITE_STALL, &time_delayed); bool has_timeout = (expiration_time > 0); @@ -3250,7 +3251,8 @@ Status DBImpl::DelayWrite(uint64_t expiration_time) { if (has_timeout) { bg_cv_.TimedWait(expiration_time); if (env_->NowMicros() > expiration_time) { - return Status::TimedOut(); + timed_out = true; + break; } } else { bg_cv_.Wait(); @@ -3263,6 +3265,10 @@ Status DBImpl::DelayWrite(uint64_t expiration_time) { RecordTick(stats_, STALL_MICROS, time_delayed); } + if (timed_out) { + return Status::TimedOut(); + } + return bg_error_; } diff --git a/db/internal_stats.cc b/db/internal_stats.cc index 6d7cd72bd..0c3ad56dc 100644 --- a/db/internal_stats.cc +++ b/db/internal_stats.cc @@ -312,6 +312,9 @@ void InternalStats::DumpDBStats(std::string* value) { uint64_t wal_synced = db_stats_[InternalStats::WAL_FILE_SYNCED]; uint64_t write_with_wal = db_stats_[InternalStats::WRITE_WITH_WAL]; uint64_t write_stall_micros = db_stats_[InternalStats::WRITE_STALL_MICROS]; + const int kHumanMicrosLen = 32; + char human_micros[kHumanMicrosLen]; + // Data // writes: total number of write requests. // keys: total number of key updates issued by all the write requests @@ -321,13 +324,14 @@ void InternalStats::DumpDBStats(std::string* value) { // writes/batches is the average group commit size. // // The format is the same for interval stats. + AppendHumanMicros(write_stall_micros, human_micros, kHumanMicrosLen); snprintf(buf, sizeof(buf), "Cumulative writes: %" PRIu64 " writes, %" PRIu64 " keys, %" PRIu64 " batches, %.1f writes per batch, %.2f GB user ingest, " - "stall micros: %" PRIu64 "\n", + "stall time: %s\n", write_other + write_self, num_keys_written, write_self, (write_other + write_self) / static_cast(write_self + 1), - user_bytes_written / kGB, write_stall_micros); + user_bytes_written / kGB, human_micros); value->append(buf); // WAL snprintf(buf, sizeof(buf), @@ -343,16 +347,19 @@ void InternalStats::DumpDBStats(std::string* value) { uint64_t interval_write_self = write_self - db_stats_snapshot_.write_self; uint64_t interval_num_keys_written = num_keys_written - db_stats_snapshot_.num_keys_written; + AppendHumanMicros( + write_stall_micros - db_stats_snapshot_.write_stall_micros, + human_micros, kHumanMicrosLen); snprintf(buf, sizeof(buf), "Interval writes: %" PRIu64 " writes, %" PRIu64 " keys, %" PRIu64 " batches, %.1f writes per batch, %.1f MB user ingest, " - "stall micros: %" PRIu64 "\n", + "stall time: %s\n", interval_write_other + interval_write_self, interval_num_keys_written, interval_write_self, static_cast(interval_write_other + interval_write_self) / (interval_write_self + 1), (user_bytes_written - db_stats_snapshot_.ingest_bytes) / kMB, - write_stall_micros - db_stats_snapshot_.write_stall_micros); + human_micros); value->append(buf); uint64_t interval_write_with_wal = diff --git a/util/logging.cc b/util/logging.cc index 98d96b82b..664258333 100644 --- a/util/logging.cc +++ b/util/logging.cc @@ -23,6 +23,20 @@ namespace rocksdb { +// for micros < 10ms, print "XX us". +// for micros < 10sec, print "XX ms". +// for micros >= 10 sec, print "XX sec". +int AppendHumanMicros(uint64_t micros, char* output, int len) { + if (micros < 10000) { + return snprintf(output, len, "%" PRIu64 " us", micros); + } else if (micros < 10000000) { + return snprintf(output, len, "%.3lf ms", + static_cast(micros) / 1000); + } else { + return snprintf(output, len, "%.3lf sec", + static_cast(micros) / 1000000); + } +} // for sizes >=10TB, print "XXTB" // for sizes >=10GB, print "XXGB" diff --git a/util/logging.h b/util/logging.h index 7ca8ae0a3..64d7c22ca 100644 --- a/util/logging.h +++ b/util/logging.h @@ -20,6 +20,9 @@ namespace rocksdb { class Slice; +// Append a human-readable time in micros. +int AppendHumanMicros(uint64_t micros, char* output, int len); + // Append a human-readable size in bytes int AppendHumanBytes(uint64_t bytes, char* output, int len); -- GitLab