From: Yin Congmin Date: Fri, 30 Jul 2021 05:55:28 +0000 (+0800) Subject: librbd/cache/pwl/rwl: fix buf_persist and add writeback_lat perf counters X-Git-Tag: v16.2.7~50^2~36 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=89182b581a377c86ec8d1903d9d1350c27ffe517;p=ceph.git librbd/cache/pwl/rwl: fix buf_persist and add writeback_lat perf counters 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 (cherry picked from commit 8ed3080078ad5eaa51145a9481c7c2223ad38765) --- diff --git a/src/librbd/cache/pwl/AbstractWriteLog.cc b/src/librbd/cache/pwl/AbstractWriteLog.cc index 67a3f845067b6..f78c4ca9cf72b 100644 --- a/src/librbd/cache/pwl/AbstractWriteLog.cc +++ b/src/librbd/cache/pwl/AbstractWriteLog.cc @@ -158,13 +158,13 @@ void AbstractWriteLog::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::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"); @@ -580,7 +581,10 @@ template void AbstractWriteLog::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); @@ -1303,16 +1307,16 @@ void AbstractWriteLog::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 { @@ -1640,8 +1644,12 @@ Context* AbstractWriteLog::construct_flush_entry(std::shared_ptrram_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) { @@ -1966,7 +1974,7 @@ void AbstractWriteLog::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); } } diff --git a/src/librbd/cache/pwl/LogOperation.cc b/src/librbd/cache/pwl/LogOperation.cc index 2c5a5ef78d638..54da5a2e002d6 100644 --- a/src/librbd/cache/pwl/LogOperation.cc +++ b/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; } @@ -227,12 +227,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 sync_point, diff --git a/src/librbd/cache/pwl/LogOperation.h b/src/librbd/cache/pwl/LogOperation.h index 52f8591b6a656..15befe05f255d 100644 --- a/src/librbd/cache/pwl/LogOperation.h +++ b/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; diff --git a/src/librbd/cache/pwl/Types.h b/src/librbd/cache/pwl/Types.h index a646e971acbe1..d73eb19cea36b 100644 --- a/src/librbd/cache/pwl/Types.h +++ b/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, diff --git a/src/librbd/cache/pwl/rwl/WriteLog.cc b/src/librbd/cache/pwl/rwl/WriteLog.cc index 20b5e342b0af3..5e12e6f1ba5ef 100644 --- a/src/librbd/cache/pwl/rwl/WriteLog.cc +++ b/src/librbd/cache/pwl/rwl/WriteLog.cc @@ -162,7 +162,7 @@ int WriteLog::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 << " " @@ -824,6 +824,16 @@ template template void WriteLog::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(operation->get_log_entry()); @@ -834,12 +844,13 @@ void WriteLog::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; } } } diff --git a/src/librbd/cache/pwl/ssd/WriteLog.cc b/src/librbd/cache/pwl/ssd/WriteLog.cc index 977586295dbeb..6aeb08ad18cef 100644 --- a/src/librbd/cache/pwl/ssd/WriteLog.cc +++ b/src/librbd/cache/pwl/ssd/WriteLog.cc @@ -765,7 +765,7 @@ void WriteLog::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 ||