Stop printing per-level stall times.

Summary:
Per-level stall times are the suggested stall time, not the actual stall time so this change stops printing them
both in the per-level output lines and in the summary. Also changed output for total stall time to include units
in all cases. The new output looks like:
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(cnt)    RecordIn   RecordDrop
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  L0     4/1          7   0.8      0.0     0.0      0.0       0.6      0.6       0.0   0.0      0.0     12.9        50       352    0.141        882            0            0
  L1     5/0          9   0.9      0.0     0.0      0.0       0.0      0.0       0.6   0.0      0.0      0.0         0         0    0.000          0            0            0
  L2    54/0         99   1.0      0.0     0.0      0.0       0.0      0.0       0.6   0.0      0.0      0.0         0         0    0.000          0            0            0
  L3   289/0        527   0.5      0.0     0.0      0.0       0.0      0.0       0.5   0.0      0.0      0.0         0         0    0.000          0            0            0
 Sum   352/1        642   0.0      0.0     0.0      0.0       0.6      0.6       1.7   1.0      0.0     12.9        50       352    0.141        882            0            0
 Int     0/0          0   0.0      0.0     0.0      0.0       0.0      0.0       0.0   1.0      0.0     15.5         0         3    0.118          7            0            0
Flush(GB): accumulative 0.627, interval 0.005
Stalls(count): 0 level0_slowdown, 0 level0_numfiles, 882 memtable_compaction, 0 leveln_slowdown_soft, 0 leveln_slowdown_hard

Task ID: #6493861

Blame Rev:

Test Plan:
run db_bench, look at output

Revert Plan:

Database Impact:

Memcache Impact:

Other Notes:

EImportant:

- begin *PUBLIC* platform impact section -
Bugzilla: #
- end platform impact -

Reviewers: igor

Reviewed By: igor

Subscribers: dhruba

Differential Revision: https://reviews.facebook.net/D35085

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)",

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<double>(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;
 }
 

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<CompactionStats> comp_stats_;
   // These count the number of microseconds for which MakeRoomForWrite stalls.
-  std::vector<uint64_t> stall_leveln_slowdown_hard_;
   std::vector<uint64_t> stall_leveln_slowdown_count_hard_;
-  std::vector<uint64_t> stall_leveln_slowdown_soft_;
   std::vector<uint64_t> 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_;
 

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<double>(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<double>(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<double>(micros % 60000000) / 1000000);