From f66f1fbd192e6d04009689729ca443e5d0f3eb2d Mon Sep 17 00:00:00 2001 From: Patrick Donnelly Date: Fri, 27 Oct 2017 07:05:21 -0700 Subject: [PATCH] mon: use mono clock for duration Signed-off-by: Patrick Donnelly --- src/common/ceph_time.h | 5 +++++ src/mon/Monitor.cc | 10 +++++----- src/mon/Paxos.cc | 37 ++++++++++++++++++------------------- src/osd/OSD.cc | 12 ++++++------ 4 files changed, 34 insertions(+), 30 deletions(-) diff --git a/src/common/ceph_time.h b/src/common/ceph_time.h index 49707e98c3ac1..afe8aead7cee1 100644 --- a/src/common/ceph_time.h +++ b/src/common/ceph_time.h @@ -17,6 +17,7 @@ #include +#include "include/assert.h" #include "include/encoding.h" #if defined(__APPLE__) @@ -499,6 +500,10 @@ namespace std { std::chrono::duration_cast(z) : timespan(-z.count()); } + inline timespan to_timespan(signedspan z) { + ceph_assert(z >= signedspan::zero()); + return std::chrono::duration_cast(z); + } } } // namespace std diff --git a/src/mon/Monitor.cc b/src/mon/Monitor.cc index ca737a87451e0..9203107294379 100644 --- a/src/mon/Monitor.cc +++ b/src/mon/Monitor.cc @@ -3104,13 +3104,13 @@ void Monitor::handle_command(MonOpRequestRef op) if (prefix == "compact" || prefix == "mon compact") { dout(1) << "triggering manual compaction" << dendl; - utime_t start = ceph_clock_now(); + auto start = ceph::coarse_mono_clock::now(); store->compact(); - utime_t end = ceph_clock_now(); - end -= start; - dout(1) << "finished manual compaction in " << end << " seconds" << dendl; + auto end = ceph::coarse_mono_clock::now(); + double duration = std::chrono::duration(end-start).count(); + dout(1) << "finished manual compaction in " << duration << " seconds" << dendl; ostringstream oss; - oss << "compacted " << g_conf->get_val("mon_keyvaluedb") << " in " << end << " seconds"; + oss << "compacted " << g_conf->get_val("mon_keyvaluedb") << " in " << duration << " seconds"; rs = oss.str(); r = 0; } diff --git a/src/mon/Paxos.cc b/src/mon/Paxos.cc index e92438769f088..d3c13861d60a4 100644 --- a/src/mon/Paxos.cc +++ b/src/mon/Paxos.cc @@ -266,12 +266,12 @@ void Paxos::handle_collect(MonOpRequestRef op) logger->inc(l_paxos_collect); logger->inc(l_paxos_collect_keys, t->get_keys()); logger->inc(l_paxos_collect_bytes, t->get_bytes()); - utime_t start = ceph_clock_now(); + auto start = ceph::coarse_mono_clock::now(); get_store()->apply_transaction(t); + auto end = ceph::coarse_mono_clock::now(); - utime_t end = ceph_clock_now(); - logger->tinc(l_paxos_collect_latency, end - start); + logger->tinc(l_paxos_collect_latency, to_timespan(end - start)); } else { // don't accept! dout(10) << "NOT accepting pn " << collect->pn << " from " << collect->pn_from @@ -433,12 +433,12 @@ bool Paxos::store_state(MMonPaxos *m) logger->inc(l_paxos_store_state); logger->inc(l_paxos_store_state_bytes, t->get_bytes()); logger->inc(l_paxos_store_state_keys, t->get_keys()); - utime_t start = ceph_clock_now(); + auto start = ceph::coarse_mono_clock::now(); get_store()->apply_transaction(t); + auto end = ceph::coarse_mono_clock::now(); - utime_t end = ceph_clock_now(); - logger->tinc(l_paxos_store_state_latency, end - start); + logger->tinc(l_paxos_store_state_latency, to_timespan(end-start)); // refresh first_committed; this txn may have trimmed. first_committed = get_store()->get(get_name(), "first_committed"); @@ -660,12 +660,12 @@ void Paxos::begin(bufferlist& v) logger->inc(l_paxos_begin); logger->inc(l_paxos_begin_keys, t->get_keys()); logger->inc(l_paxos_begin_bytes, t->get_bytes()); - utime_t start = ceph_clock_now(); + auto start = ceph::coarse_mono_clock::now(); get_store()->apply_transaction(t); + auto end = ceph::coarse_mono_clock::now(); - utime_t end = ceph_clock_now(); - logger->tinc(l_paxos_begin_latency, end - start); + logger->tinc(l_paxos_begin_latency, to_timespan(end - start)); assert(g_conf->paxos_kill_at != 3); @@ -744,12 +744,12 @@ void Paxos::handle_begin(MonOpRequestRef op) *_dout << dendl; logger->inc(l_paxos_begin_bytes, t->get_bytes()); - utime_t start = ceph_clock_now(); + auto start = ceph::coarse_mono_clock::now(); get_store()->apply_transaction(t); + auto end = ceph::coarse_mono_clock::now(); - utime_t end = ceph_clock_now(); - logger->tinc(l_paxos_begin_latency, end - start); + logger->tinc(l_paxos_begin_latency, to_timespan(end - start)); assert(g_conf->paxos_kill_at != 5); @@ -1040,14 +1040,13 @@ bool Paxos::do_refresh() { bool need_bootstrap = false; - utime_t start = ceph_clock_now(); - // make sure we have the latest state loaded up + auto start = ceph::coarse_mono_clock::now(); mon->refresh_from_paxos(&need_bootstrap); + auto end = ceph::coarse_mono_clock::now(); - utime_t end = ceph_clock_now(); logger->inc(l_paxos_refresh); - logger->tinc(l_paxos_refresh_latency, end - start); + logger->tinc(l_paxos_refresh_latency, to_timespan(end - start)); if (need_bootstrap) { dout(10) << " doing requested bootstrap" << dendl; @@ -1278,12 +1277,12 @@ version_t Paxos::get_new_proposal_number(version_t gt) *_dout << dendl; logger->inc(l_paxos_new_pn); - utime_t start = ceph_clock_now(); + auto start = ceph::coarse_mono_clock::now(); get_store()->apply_transaction(t); + auto end = ceph::coarse_mono_clock::now(); - utime_t end = ceph_clock_now(); - logger->tinc(l_paxos_new_pn_latency, end - start); + logger->tinc(l_paxos_new_pn_latency, to_timespan(end - start)); dout(10) << "get_new_proposal_number = " << last_pn << dendl; return last_pn; diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc index 188175ccc0653..88cfd7a1b1b36 100644 --- a/src/osd/OSD.cc +++ b/src/osd/OSD.cc @@ -2285,12 +2285,12 @@ will start to track new ops received afterwards."; auto start = ceph::coarse_mono_clock::now(); store->compact(); auto end = ceph::coarse_mono_clock::now(); - auto time_span = chrono::duration_cast>(end - start); + double duration = std::chrono::duration(end-start).count(); dout(1) << "finished manual compaction in " - << time_span.count() + << duration << " seconds" << dendl; f->open_object_section("compact_result"); - f->dump_float("elapsed_time", time_span.count()); + f->dump_float("elapsed_time", duration); f->close_section(); } else { assert(0 == "broken asok registration"); @@ -6403,11 +6403,11 @@ void OSD::do_command(Connection *con, ceph_tid_t tid, vector& cmd, buffe auto start = ceph::coarse_mono_clock::now(); store->compact(); auto end = ceph::coarse_mono_clock::now(); - auto time_span = chrono::duration_cast>(end - start); + double duration = std::chrono::duration(end-start).count(); dout(1) << "finished manual compaction in " - << time_span.count() + << duration << " seconds" << dendl; - ss << "compacted omap in " << time_span.count() << " seconds"; + ss << "compacted omap in " << duration << " seconds"; } else { -- 2.39.5