diff --git a/db/column_family.cc b/db/column_family.cc index 72888136c..627dedcd4 100644 --- a/db/column_family.cc +++ b/db/column_family.cc @@ -451,8 +451,7 @@ void ColumnFamilyData::RecalculateWriteStallConditions( uint64_t kHardLimitSlowdown = 1000; write_controller_token_ = write_controller->GetDelayToken(kHardLimitSlowdown); - internal_stats_->RecordLevelNSlowdown(max_level, kHardLimitSlowdown, - false); + internal_stats_->RecordLevelNSlowdown(max_level, false); Log(InfoLogLevel::WARN_LEVEL, ioptions_.info_log, "[%s] Stalling writes because we hit hard limit on level %d. " "(%" PRIu64 "us)", @@ -463,7 +462,7 @@ void ColumnFamilyData::RecalculateWriteStallConditions( mutable_cf_options.soft_rate_limit, mutable_cf_options.hard_rate_limit); write_controller_token_ = write_controller->GetDelayToken(slowdown); - internal_stats_->RecordLevelNSlowdown(max_level, slowdown, true); + internal_stats_->RecordLevelNSlowdown(max_level, true); Log(InfoLogLevel::WARN_LEVEL, ioptions_.info_log, "[%s] Stalling writes because we hit soft limit on level %d (%" PRIu64 "us)", diff --git a/db/internal_stats.cc b/db/internal_stats.cc index 4ed637553..94252a24a 100644 --- a/db/internal_stats.cc +++ b/db/internal_stats.cc @@ -33,16 +33,16 @@ void PrintLevelStatsHeader(char* buf, size_t len, const std::string& cf_name) { "Level Files Size(MB) Score Read(GB) Rn(GB) Rnp1(GB) " "Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) " "Comp(sec) Comp(cnt) Avg(sec) " - "Stall(sec) Stall(cnt) Avg(ms) RecordIn RecordDrop\n" + "Stall(cnt) RecordIn RecordDrop\n" "--------------------------------------------------------------------" "--------------------------------------------------------------------" - "----------------------------------------------------------\n", + "--------------------------------------\n", cf_name.c_str()); } void PrintLevelStats(char* buf, size_t len, const std::string& name, int num_files, int being_compacted, double total_file_size, double score, - double w_amp, double stall_us, uint64_t stalls, + double w_amp, uint64_t stalls, const InternalStats::CompactionStats& stats) { uint64_t bytes_read = stats.bytes_readn + stats.bytes_readnp1; int64_t bytes_new = stats.bytes_written - stats.bytes_readnp1; @@ -62,10 +62,8 @@ void PrintLevelStats(char* buf, size_t len, const std::string& name, "%9.0f " /* Comp(sec) */ "%9d " /* Comp(cnt) */ "%8.3f " /* Avg(sec) */ - "%10.2f " /* Stall(sec) */ "%10" PRIu64 " " /* Stall(cnt) */ - "%7.2f " /* Avg(ms) */ "%12" PRIu64 " " /* input entries */ "%12" PRIu64 "\n" /* number of records reduced */, @@ -77,8 +75,7 @@ void PrintLevelStats(char* buf, size_t len, const std::string& name, stats.bytes_written / kMB / elapsed, stats.micros / 1000000.0, stats.count, stats.count == 0 ? 0 : stats.micros / 1000000.0 / stats.count, - stall_us / 1000000.0, stalls, - stalls == 0 ? 0 : stall_us / 1000.0 / stalls, + stalls, stats.num_input_records, stats.num_dropped_records); } @@ -423,12 +420,9 @@ void InternalStats::DumpCFStats(std::string* value) { int total_files = 0; int total_files_being_compacted = 0; double total_file_size = 0; - uint64_t total_slowdown_soft = 0; uint64_t total_slowdown_count_soft = 0; - uint64_t total_slowdown_hard = 0; uint64_t total_slowdown_count_hard = 0; uint64_t total_stall_count = 0; - double total_stall_us = 0; for (int level = 0; level < number_levels_; level++) { int files = vstorage->NumLevelFiles(level); total_files += files; @@ -441,20 +435,10 @@ void InternalStats::DumpCFStats(std::string* value) { : (stall_leveln_slowdown_count_soft_[level] + stall_leveln_slowdown_count_hard_[level]); - double stall_us = level == 0 ? - (cf_stats_value_[LEVEL0_SLOWDOWN] + - cf_stats_value_[LEVEL0_NUM_FILES] + - cf_stats_value_[MEMTABLE_COMPACTION]) - : (stall_leveln_slowdown_soft_[level] + - stall_leveln_slowdown_hard_[level]); - stats_sum.Add(comp_stats_[level]); total_file_size += vstorage->NumLevelBytes(level); - total_stall_us += stall_us; total_stall_count += stalls; - total_slowdown_soft += stall_leveln_slowdown_soft_[level]; total_slowdown_count_soft += stall_leveln_slowdown_count_soft_[level]; - total_slowdown_hard += stall_leveln_slowdown_hard_[level]; total_slowdown_count_hard += stall_leveln_slowdown_count_hard_[level]; double w_amp = (comp_stats_[level].bytes_readn == 0) ? 0.0 : comp_stats_[level].bytes_written / @@ -462,7 +446,7 @@ void InternalStats::DumpCFStats(std::string* value) { PrintLevelStats(buf, sizeof(buf), "L" + ToString(level), files, files_being_compacted[level], vstorage->NumLevelBytes(level), compaction_score[level], - w_amp, stall_us, stalls, comp_stats_[level]); + w_amp, stalls, comp_stats_[level]); value->append(buf); } } @@ -472,7 +456,7 @@ void InternalStats::DumpCFStats(std::string* value) { // Stats summary across levels PrintLevelStats(buf, sizeof(buf), "Sum", total_files, total_files_being_compacted, total_file_size, 0, w_amp, - total_stall_us, total_stall_count, stats_sum); + total_stall_count, stats_sum); value->append(buf); // Interval summary uint64_t interval_ingest = @@ -481,24 +465,14 @@ void InternalStats::DumpCFStats(std::string* value) { interval_stats.Subtract(cf_stats_snapshot_.comp_stats); w_amp = interval_stats.bytes_written / static_cast(interval_ingest); PrintLevelStats(buf, sizeof(buf), "Int", 0, 0, 0, 0, - w_amp, total_stall_us - cf_stats_snapshot_.stall_us, - total_stall_count - cf_stats_snapshot_.stall_count, interval_stats); + w_amp, total_stall_count - cf_stats_snapshot_.stall_count, + interval_stats); value->append(buf); snprintf(buf, sizeof(buf), "Flush(GB): accumulative %.3f, interval %.3f\n", curr_ingest / kGB, interval_ingest / kGB); value->append(buf); - snprintf(buf, sizeof(buf), - "Stalls(secs): %.3f level0_slowdown, %.3f level0_numfiles, " - "%.3f memtable_compaction, %.3f leveln_slowdown_soft, " - "%.3f leveln_slowdown_hard\n", - cf_stats_value_[LEVEL0_SLOWDOWN] / 1000000.0, - cf_stats_value_[LEVEL0_NUM_FILES] / 1000000.0, - cf_stats_value_[MEMTABLE_COMPACTION] / 1000000.0, - total_slowdown_soft / 1000000.0, - total_slowdown_hard / 1000000.0); - value->append(buf); snprintf(buf, sizeof(buf), "Stalls(count): %" PRIu64 " level0_slowdown, " @@ -513,7 +487,6 @@ void InternalStats::DumpCFStats(std::string* value) { cf_stats_snapshot_.ingest_bytes = curr_ingest; cf_stats_snapshot_.comp_stats = stats_sum; - cf_stats_snapshot_.stall_us = total_stall_us; cf_stats_snapshot_.stall_count = total_stall_count; } diff --git a/db/internal_stats.h b/db/internal_stats.h index 9d2b7788c..e72fc75bc 100644 --- a/db/internal_stats.h +++ b/db/internal_stats.h @@ -88,9 +88,7 @@ class InternalStats { cf_stats_value_(INTERNAL_CF_STATS_ENUM_MAX), cf_stats_count_(INTERNAL_CF_STATS_ENUM_MAX), comp_stats_(num_levels), - stall_leveln_slowdown_hard_(num_levels), stall_leveln_slowdown_count_hard_(num_levels), - stall_leveln_slowdown_soft_(num_levels), stall_leveln_slowdown_count_soft_(num_levels), bg_error_count_(0), number_levels_(num_levels), @@ -105,9 +103,7 @@ class InternalStats { cf_stats_count_[i] = 0; } for (int i = 0; i < num_levels; ++i) { - stall_leveln_slowdown_hard_[i] = 0; stall_leveln_slowdown_count_hard_[i] = 0; - stall_leveln_slowdown_soft_[i] = 0; stall_leveln_slowdown_count_soft_[i] = 0; } } @@ -211,12 +207,10 @@ class InternalStats { comp_stats_[level].bytes_moved += amount; } - void RecordLevelNSlowdown(int level, uint64_t micros, bool soft) { + void RecordLevelNSlowdown(int level, bool soft) { if (soft) { - stall_leveln_slowdown_soft_[level] += micros; ++stall_leveln_slowdown_count_soft_[level]; } else { - stall_leveln_slowdown_hard_[level] += micros; ++stall_leveln_slowdown_count_hard_[level]; } } @@ -255,9 +249,7 @@ class InternalStats { // Per-ColumnFamily/level compaction stats std::vector comp_stats_; // These count the number of microseconds for which MakeRoomForWrite stalls. - std::vector stall_leveln_slowdown_hard_; std::vector stall_leveln_slowdown_count_hard_; - std::vector stall_leveln_slowdown_soft_; std::vector stall_leveln_slowdown_count_soft_; // Used to compute per-interval statistics @@ -265,13 +257,11 @@ class InternalStats { // ColumnFamily-level stats CompactionStats comp_stats; uint64_t ingest_bytes; // Bytes written to L0 - uint64_t stall_us; // Stall time in micro-seconds uint64_t stall_count; // Stall count CFStatsSnapshot() : comp_stats(0), ingest_bytes(0), - stall_us(0), stall_count(0) {} } cf_stats_snapshot_; diff --git a/util/logging.cc b/util/logging.cc index 802965948..3972981dc 100644 --- a/util/logging.cc +++ b/util/logging.cc @@ -26,6 +26,8 @@ namespace rocksdb { // for micros < 10ms, print "XX us". // for micros < 10sec, print "XX ms". // for micros >= 10 sec, print "XX sec". +// for micros <= 1 hour, print Y:X M:S". +// for micros > 1 hour, print Z:Y:X H:M:S". int AppendHumanMicros(uint64_t micros, char* output, int len) { if (micros < 10000) { return snprintf(output, len, "%" PRIu64 " us", micros); @@ -36,11 +38,12 @@ int AppendHumanMicros(uint64_t micros, char* output, int len) { return snprintf(output, len, "%.3lf sec", static_cast(micros) / 1000000); } else if (micros < 1000000l * 60 * 60) { - return snprintf(output, len, "%02" PRIu64 ":%05.3f", + return snprintf(output, len, "%02" PRIu64 ":%05.3f M:S", micros / 1000000 / 60, static_cast(micros % 60000000) / 1000000); } else { - return snprintf(output, len, "%02" PRIu64 ":%02" PRIu64 ":%05.3f", + return snprintf(output, len, + "%02" PRIu64 ":%02" PRIu64 ":%05.3f H:M:S", micros / 1000000 / 3600, (micros / 1000000 / 60) % 60, static_cast(micros % 60000000) / 1000000);