Delay logging: Add cf names, and convert to MB units

db/column_family.cc

@@ -905,6 +905,7 @@ namespace {
 const int kMemtablePenalty = 5;
 const int kNumPendingSteps = 100;
 const double kGoalMbs = 3 * 1048576.0;
+const int kBytesInMB = 1048576;
 }  // namespace
 
 double ColumnFamilyData::TEST_CalculateWriteDelayDivider(
@@ -1108,14 +1109,15 @@ ColumnFamilyData::CalculateWriteDelayDividerAndMaybeUpdateWriteStallCause(
   return biggest_divider;
 }
 
-void ColumnFamilyData::SetL0BaseCompactionSpeed(uint64_t size) {
+void ColumnFamilyData::SetL0BaseCompactionSpeed(uint64_t l0_bytes_compacted) {
   if (started_l0_timer_ == true) {
     assert(l0_start_clearance_time_ > 0);
-    float l0_clearance_dur =
+    double l0_clearance_dur =
         ioptions_.clock->NowMicros() - l0_start_clearance_time_;
     assert(l0_clearance_dur > 0);
     const int micros_in_sec = 1000000;
-    uint64_t cur_speed = (size / l0_clearance_dur) * micros_in_sec;
+    uint64_t cur_speed =
+        (l0_bytes_compacted / l0_clearance_dur) * micros_in_sec;
     if (first_l0_comp_) {
       first_l0_comp_ = false;
       // Since first compaction is more prone to variability in speed we'd
@@ -1129,11 +1131,12 @@ void ColumnFamilyData::SetL0BaseCompactionSpeed(uint64_t size) {
     started_l0_timer_ = false;
     l0_start_clearance_time_ = 0;
     ROCKS_LOG_INFO(ioptions_.logger,
-                   "L0L1 compaction ended. duration: %f"
-                   ", amount cleared: %" PRIu64 ", current rate: %" PRIu64
-                   ", avg rate: %" PRIu64,
-                   l0_clearance_dur, size, cur_speed,
-                   lo_base_compaction_speed_);
+                   "[%s] L0L1 compaction ended. Duration: %.1f secs"
+                   ", amount cleared: %" PRIu64 " MB, current rate: %" PRIu64
+                   ", avg rate: %" PRIu64 " MB/s",
+                   name_.c_str(), l0_clearance_dur / micros_in_sec,
+                   l0_bytes_compacted / kBytesInMB, cur_speed / kBytesInMB,
+                   lo_base_compaction_speed_ / kBytesInMB);
   }
 }
 
@@ -1143,10 +1146,11 @@ void ColumnFamilyData::MaybeStartL0L1Timer() {
   if (!started_l0_timer_ && vstorage->IsL0ScoreAbove1()) {
     started_l0_timer_ = true;
     l0_start_clearance_time_ = ioptions_.clock->NowMicros();
-    ROCKS_LOG_INFO(
-        ioptions_.logger,
-        "Auto tune: Started timer. time: %" PRIu64 " Num L0 files: %d",
-        l0_start_clearance_time_, vstorage->l0_delay_trigger_count());
+    ROCKS_LOG_INFO(ioptions_.logger,
+                   "[%s] Auto tune: Started timer. time: %" PRIu64
+                   " Num L0 files: %d",
+                   name_.c_str(), l0_start_clearance_time_,
+                   vstorage->l0_delay_trigger_count());
   }
 }
 
@@ -1237,10 +1241,10 @@ WriteStallCondition ColumnFamilyData::RecalculateWriteStallConditions(
           ioptions_.logger,
           "[%s] Stalling writes because we have %d immutable memtables "
           "(waiting for flush), max_write_buffer_number is set to %d. "
-          "delayed write rate: %" PRIu64,
+          "delayed write rate: %" PRIu64 " MB/s",
           name_.c_str(), imm()->NumNotFlushed(),
           mutable_cf_options.max_write_buffer_number,
-          write_controller->delayed_write_rate());
+          write_controller->delayed_write_rate() / kBytesInMB);
     } else if (write_stall_condition == WriteStallCondition::kDelayed &&
                write_stall_cause == WriteStallCause::kL0FileCountLimit) {
       if (!dynamic_delay) {
@@ -1261,10 +1265,10 @@ WriteStallCondition ColumnFamilyData::RecalculateWriteStallConditions(
       ROCKS_LOG_WARN(ioptions_.logger,
                      "[%s] Stalling writes because we have %d level-0 files, "
                      "%d running flushes "
-                     "delayed write rate %" PRIu64,
+                     "delayed write rate %" PRIu64 " MB/s",
                      name_.c_str(), vstorage->l0_delay_trigger_count(),
                      running_flushes_.load(),
-                     write_controller->delayed_write_rate());
+                     write_controller->delayed_write_rate() / kBytesInMB);
     } else if (write_stall_condition == WriteStallCondition::kDelayed &&
                write_stall_cause == WriteStallCause::kPendingCompactionBytes) {
       // If the distance to hard limit is less than 1/4 of the gap between soft
@@ -1290,9 +1294,9 @@ WriteStallCondition ColumnFamilyData::RecalculateWriteStallConditions(
       ROCKS_LOG_WARN(
           ioptions_.logger,
           "[%s] Stalling writes because of estimated pending compaction "
-          "bytes %" PRIu64 ". delayed write rate: %" PRIu64,
+          "bytes %" PRIu64 ". delayed write rate: %" PRIu64 " MB/s",
           name_.c_str(), vstorage->estimated_compaction_needed_bytes(),
-          write_controller->delayed_write_rate());
+          write_controller->delayed_write_rate() / kBytesInMB);
     } else {
       assert(write_stall_condition == WriteStallCondition::kNormal);
       if (vstorage->l0_delay_trigger_count() >=