librbd/cache/pwl/rwl: fix buf_persist and add writeback_lat perf coun…

…ters

initialize buf_persist_time, then change name buf_persist_time to
buf_persist_start_time, change flush to internal_flush. add
writeback_lat perf conters. update some print formats for perf.

Fixes: https://tracker.ceph.com/issues/52090
Signed-off-by: Yin Congmin <[email protected]>

src/librbd/cache/pwl/AbstractWriteLog.cc

@@ -158,13 +158,13 @@ void AbstractWriteLog<I>::perf_start(std::string name) {
     "Histogram of syncpoint's logentry numbers vs bytes number");
 
   plb.add_u64_counter(l_librbd_pwl_wr_req, "wr", "Writes");
+  plb.add_u64_counter(l_librbd_pwl_wr_bytes, "wr_bytes", "Data size in writes");
   plb.add_u64_counter(l_librbd_pwl_wr_req_def, "wr_def", "Writes deferred for resources");
   plb.add_u64_counter(l_librbd_pwl_wr_req_def_lanes, "wr_def_lanes", "Writes deferred for lanes");
   plb.add_u64_counter(l_librbd_pwl_wr_req_def_log, "wr_def_log", "Writes deferred for log entries");
   plb.add_u64_counter(l_librbd_pwl_wr_req_def_buf, "wr_def_buf", "Writes deferred for buffers");
   plb.add_u64_counter(l_librbd_pwl_wr_req_overlap, "wr_overlap", "Writes overlapping with prior in-progress writes");
   plb.add_u64_counter(l_librbd_pwl_wr_req_queued, "wr_q_barrier", "Writes queued for prior barriers (aio_flush)");
-  plb.add_u64_counter(l_librbd_pwl_wr_bytes, "wr_bytes", "Data size in writes");
 
   plb.add_u64_counter(l_librbd_pwl_log_ops, "log_ops", "Log appends");
   plb.add_u64_avg(l_librbd_pwl_log_op_bytes, "log_op_bytes", "Average log append bytes");
@@ -258,7 +258,8 @@ void AbstractWriteLog<I>::perf_start(std::string name) {
   plb.add_time_avg(l_librbd_pwl_cmp_latency, "cmp_lat", "Compare and Write latecy");
   plb.add_u64_counter(l_librbd_pwl_cmp_fails, "cmp_fails", "Compare and Write compare fails");
 
-  plb.add_u64_counter(l_librbd_pwl_flush, "flush", "Flush (flush RWL)");
+  plb.add_u64_counter(l_librbd_pwl_internal_flush, "internal_flush", "Flush RWL (write back to OSD)");
+  plb.add_time_avg(l_librbd_pwl_writeback_latency, "writeback_lat", "write back to OSD latency");
   plb.add_u64_counter(l_librbd_pwl_invalidate_cache, "invalidate", "Invalidate RWL");
   plb.add_u64_counter(l_librbd_pwl_invalidate_discard_cache, "discard", "Discard and invalidate RWL");
 
@@ -579,7 +580,10 @@ template <typename I>
 void AbstractWriteLog<I>::init(Context *on_finish) {
   CephContext *cct = m_image_ctx.cct;
   ldout(cct, 20) << dendl;
-  perf_start(m_image_ctx.id);
+  auto pname = std::string("librbd-pwl-") + m_image_ctx.id +
+      std::string("-") + m_image_ctx.md_ctx.get_pool_name() +
+      std::string("-") + m_image_ctx.name;
+  perf_start(pname);
 
   ceph_assert(!m_initialized);
 
@@ -1302,16 +1306,16 @@ void AbstractWriteLog<I>::complete_op_log_entries(GenericLogOperations &&ops,
     }
     op->complete(result);
     m_perfcounter->tinc(l_librbd_pwl_log_op_dis_to_app_t,
-                        op->log_append_time - op->dispatch_time);
+                        op->log_append_start_time - op->dispatch_time);
     m_perfcounter->tinc(l_librbd_pwl_log_op_dis_to_cmp_t, now - op->dispatch_time);
     m_perfcounter->hinc(l_librbd_pwl_log_op_dis_to_cmp_t_hist,
                         utime_t(now - op->dispatch_time).to_nsec(),
                         log_entry->ram_entry.write_bytes);
-    utime_t app_lat = op->log_append_comp_time - op->log_append_time;
+    utime_t app_lat = op->log_append_comp_time - op->log_append_start_time;
     m_perfcounter->tinc(l_librbd_pwl_log_op_app_to_appc_t, app_lat);
     m_perfcounter->hinc(l_librbd_pwl_log_op_app_to_appc_t_hist, app_lat.to_nsec(),
                       log_entry->ram_entry.write_bytes);
-    m_perfcounter->tinc(l_librbd_pwl_log_op_app_to_cmp_t, now - op->log_append_time);
+    m_perfcounter->tinc(l_librbd_pwl_log_op_app_to_cmp_t, now - op->log_append_start_time);
   }
   // New entries may be flushable
   {
@@ -1639,8 +1643,12 @@ Context* AbstractWriteLog<I>::construct_flush_entry(std::shared_ptr<GenericLogEn
   m_flush_bytes_in_flight += log_entry->ram_entry.write_bytes;
 
   /* Flush write completion action */
+  utime_t writeback_start_time = ceph_clock_now();
   Context *ctx = new LambdaContext(
-    [this, log_entry, invalidating](int r) {
+    [this, log_entry, writeback_start_time, invalidating](int r) {
+      utime_t writeback_comp_time = ceph_clock_now();
+      m_perfcounter->tinc(l_librbd_pwl_writeback_latency,
+                          writeback_comp_time - writeback_start_time);
       {
         std::lock_guard locker(m_lock);
         if (r < 0) {
@@ -1965,7 +1973,7 @@ void AbstractWriteLog<I>::internal_flush(bool invalidate, Context *on_finish) {
     if (invalidate) {
       m_perfcounter->inc(l_librbd_pwl_invalidate_cache, 1);
     } else {
-      m_perfcounter->inc(l_librbd_pwl_flush, 1);
+      m_perfcounter->inc(l_librbd_pwl_internal_flush, 1);
     }
   }
 

src/librbd/cache/pwl/LogOperation.cc

@@ -21,9 +21,9 @@ GenericLogOperation::GenericLogOperation(utime_t dispatch_time,
 
 std::ostream& GenericLogOperation::format(std::ostream &os) const {
   os << "dispatch_time=[" << dispatch_time << "], "
-     << "buf_persist_time=[" << buf_persist_time << "], "
+     << "buf_persist_start_time=[" << buf_persist_start_time << "], "
      << "buf_persist_comp_time=[" << buf_persist_comp_time << "], "
-     << "log_append_time=[" << log_append_time << "], "
+     << "log_append_start_time=[" << log_append_start_time << "], "
      << "log_append_comp_time=[" << log_append_comp_time << "], ";
   return os;
 }
@@ -226,12 +226,15 @@ std::ostream &operator<<(std::ostream &os,
 
 void WriteLogOperation::complete(int result) {
   GenericWriteLogOperation::complete(result);
-  m_perfcounter->tinc(l_librbd_pwl_log_op_dis_to_buf_t, buf_persist_time - dispatch_time);
-  utime_t buf_lat = buf_persist_comp_time - buf_persist_time;
-  m_perfcounter->tinc(l_librbd_pwl_log_op_buf_to_bufc_t, buf_lat);
-  m_perfcounter->hinc(l_librbd_pwl_log_op_buf_to_bufc_t_hist, buf_lat.to_nsec(),
+  m_perfcounter->tinc(l_librbd_pwl_log_op_dis_to_buf_t,
+                      buf_persist_start_time - dispatch_time);
+  utime_t buf_persist_lat = buf_persist_comp_time - buf_persist_start_time;
+  m_perfcounter->tinc(l_librbd_pwl_log_op_buf_to_bufc_t, buf_persist_lat);
+  m_perfcounter->hinc(l_librbd_pwl_log_op_buf_to_bufc_t_hist,
+                      buf_persist_lat.to_nsec(),
                       log_entry->ram_entry.write_bytes);
-  m_perfcounter->tinc(l_librbd_pwl_log_op_buf_to_app_t, log_append_time - buf_persist_time);
+  m_perfcounter->tinc(l_librbd_pwl_log_op_buf_to_app_t,
+                      log_append_start_time - buf_persist_start_time);
 }
 
 WriteLogOperationSet::WriteLogOperationSet(utime_t dispatched, PerfCounters *perfcounter, std::shared_ptr<SyncPoint> sync_point,

src/librbd/cache/pwl/LogOperation.h

@@ -35,11 +35,11 @@ class GenericLogOperation {
 protected:
   PerfCounters *m_perfcounter = nullptr;
 public:
-  utime_t dispatch_time;         // When op created
-  utime_t buf_persist_time;      // When buffer persist begins
-  utime_t buf_persist_comp_time; // When buffer persist completes
-  utime_t log_append_time;       // When log append begins
-  utime_t log_append_comp_time;  // When log append completes
+  utime_t dispatch_time;          // When op created
+  utime_t buf_persist_start_time; // When buffer persist begins
+  utime_t buf_persist_comp_time;  // When buffer persist completes
+  utime_t log_append_start_time;  // When log append begins
+  utime_t log_append_comp_time;   // When log append completes
   GenericLogOperation(utime_t dispatch_time, PerfCounters *perfcounter);
   virtual ~GenericLogOperation() { };
   GenericLogOperation(const GenericLogOperation&) = delete;

src/librbd/cache/pwl/Types.h

@@ -41,13 +41,13 @@ enum {
 
   // All write requests
   l_librbd_pwl_wr_req,             // write requests
+  l_librbd_pwl_wr_bytes,           // bytes written
   l_librbd_pwl_wr_req_def,         // write requests deferred for resources
   l_librbd_pwl_wr_req_def_lanes,   // write requests deferred for lanes
   l_librbd_pwl_wr_req_def_log,     // write requests deferred for log entries
   l_librbd_pwl_wr_req_def_buf,     // write requests deferred for buffer space
   l_librbd_pwl_wr_req_overlap,     // write requests detained for overlap
   l_librbd_pwl_wr_req_queued,      // write requests queued for prior barrier
-  l_librbd_pwl_wr_bytes,           // bytes written
 
   // Write log operations (1 .. n per request that appends to the log)
   l_librbd_pwl_log_ops,            // log append ops
@@ -137,7 +137,8 @@ enum {
   l_librbd_pwl_cmp_latency,
   l_librbd_pwl_cmp_fails,
 
-  l_librbd_pwl_flush,
+  l_librbd_pwl_internal_flush,
+  l_librbd_pwl_writeback_latency,
   l_librbd_pwl_invalidate_cache,
   l_librbd_pwl_invalidate_discard_cache,
 

src/librbd/cache/pwl/rwl/WriteLog.cc

@@ -162,7 +162,7 @@ int WriteLog<I>::append_op_log_entries(GenericLogOperations &ops)
     ldout(m_image_ctx.cct, 05) << "APPENDING: index="
                                << operation->get_log_entry()->log_entry_index << " "
                                << "operation=[" << *operation << "]" << dendl;
-    operation->log_append_time = now;
+    operation->log_append_start_time = now;
     *operation->get_log_entry()->cache_entry = operation->get_log_entry()->ram_entry;
     ldout(m_image_ctx.cct, 20) << "APPENDING: index="
                                << operation->get_log_entry()->log_entry_index << " "
@@ -825,6 +825,16 @@ template <typename I>
 template <typename V>
 void WriteLog<I>::flush_pmem_buffer(V& ops)
 {
+  utime_t now = ceph_clock_now();
+  for (auto &operation : ops) {
+    if (operation->reserved_allocated()) {
+      operation->buf_persist_start_time = now;
+    } else {
+      ldout(m_image_ctx.cct, 20) << "skipping non-write op: "
+                                 << *operation << dendl;
+    }
+  }
+
   for (auto &operation : ops) {
     if(operation->is_writing_op()) {
       auto log_entry = static_pointer_cast<WriteLogEntry>(operation->get_log_entry());
@@ -835,12 +845,13 @@ void WriteLog<I>::flush_pmem_buffer(V& ops)
   /* Drain once for all */
   pmemobj_drain(m_log_pool);
 
-  utime_t now = ceph_clock_now();
+  now = ceph_clock_now();
   for (auto &operation : ops) {
     if (operation->reserved_allocated()) {
       operation->buf_persist_comp_time = now;
     } else {
-      ldout(m_image_ctx.cct, 20) << "skipping non-write op: " << *operation << dendl;
+      ldout(m_image_ctx.cct, 20) << "skipping non-write op: "
+                                 << *operation << dendl;
     }
   }
 }

src/librbd/cache/pwl/ssd/WriteLog.cc

@@ -729,7 +729,7 @@ void WriteLog<I>::append_ops(GenericLogOperations &ops, Context *ctx,
 
   utime_t now = ceph_clock_now();
   for (auto &operation : ops) {
-    operation->log_append_time = now;
+    operation->log_append_start_time = now;
     auto log_entry = operation->get_log_entry();
 
     if (log_entries.size() == CONTROL_BLOCK_MAX_LOG_ENTRIES ||