rgw/multisite: expose lock latency as perf counter for data sync

Add a "lock_latency" perf counter to the per-zone data sync counter.
This tracks the latency of RADOS lock/unlock operations in
RGWContinuousLeaseCR, giving operators visibility into the values
driving the LatencyConcurrencyControl.

The new perf counter can be queried via the admin socket:
  ceph daemon <asok> perf dump data-sync-from-<zone>
and reset independently:
  ceph daemon <asok> perf reset data-sync-from-<zone>

This would allow us to distinguish a poisoned average from ongoing
OSD latency issues without restarting the RGW process.

Signed-off-by: Oguzhan Ozmen <oozmen@bloomberg.net>
(cherry picked from commit eb42801b6f0c34d06419ad4e44631eaefdb209d1)

diff --git a/src/rgw/driver/rados/rgw_cr_rados.cc b/src/rgw/driver/rados/rgw_cr_rados.cc
index 69465ccd9b7a37bdede79a4701a62b764ff903e6..12bcb75401fc18840ebb6e5880cb106c80313f16 100644 (file)
--- a/src/rgw/driver/rados/rgw_cr_rados.cc
+++ b/src/rgw/driver/rados/rgw_cr_rados.cc
@@ -1031,7 +1031,11 @@ int RGWContinuousLeaseCR::operate(const DoutPrefixProvider *dpp)
       current_time = ceph::coarse_mono_clock::now();
       yield call(new RGWSimpleRadosLockCR(async_rados, store, obj, lock_name, cookie, interval));
       if (latency) {
-             latency->add_latency(ceph::coarse_mono_clock::now() - current_time);
+             auto elapsed = ceph::coarse_mono_clock::now() - current_time;
+             latency->add_latency(elapsed);
+             if (counters) {
+               counters->tinc(sync_counters::l_lock, elapsed);
+             }
       }
       current_time = ceph::coarse_mono_clock::now();
       if (current_time - last_renew_try_time > interval_tolerance) {
@@ -1055,7 +1059,11 @@ int RGWContinuousLeaseCR::operate(const DoutPrefixProvider *dpp)
     current_time = ceph::coarse_mono_clock::now();
     yield call(new RGWSimpleRadosUnlockCR(async_rados, store, obj, lock_name, cookie));
     if (latency) {
-      latency->add_latency(ceph::coarse_mono_clock::now() - current_time);
+      auto elapsed = ceph::coarse_mono_clock::now() - current_time;
+      latency->add_latency(elapsed);
+      if (counters) {
+        counters->tinc(sync_counters::l_lock, elapsed);
+      }
     }
     return set_state(RGWCoroutine_Done);
   }

diff --git a/src/rgw/driver/rados/rgw_cr_rados.h b/src/rgw/driver/rados/rgw_cr_rados.h
index b3b0218222945827bbba77cf2a4ee1eef617ee90..cfd7226614f6041add87b2f1652ac9da7b5a0915 100644 (file)
--- a/src/rgw/driver/rados/rgw_cr_rados.h
+++ b/src/rgw/driver/rados/rgw_cr_rados.h
@@ -17,6 +17,7 @@
 
 #include "services/svc_sys_obj.h"
 #include "services/svc_bucket.h"
+#include "include/common_fwd.h"
 
 struct rgw_http_param_pair;
 class RGWRESTConn;
@@ -1548,17 +1549,20 @@ class RGWContinuousLeaseCR : public RGWCoroutine {
   ceph::coarse_mono_time current_time;
 
   LatencyMonitor* latency;
+  PerfCounters* counters;
 
 public:
   RGWContinuousLeaseCR(RGWAsyncRadosProcessor* async_rados,
                        rgw::sal::RadosStore* _store,
                        rgw_raw_obj obj, std::string lock_name,
                        int interval, RGWCoroutine* caller,
-                      LatencyMonitor* const latency)
+                       LatencyMonitor* const latency,
+                       PerfCounters* counters = nullptr)
     : RGWCoroutine(_store->ctx()), async_rados(async_rados), store(_store),
       obj(std::move(obj)), lock_name(std::move(lock_name)),
       interval(interval), interval_tolerance(ceph::make_timespan(9*interval/10)),
-      ts_interval(ceph::make_timespan(interval)), caller(caller), latency(latency)
+      ts_interval(ceph::make_timespan(interval)), caller(caller), latency(latency),
+      counters(counters)
   {}
 
   virtual ~RGWContinuousLeaseCR() override;

diff --git a/src/rgw/driver/rados/rgw_data_sync.cc b/src/rgw/driver/rados/rgw_data_sync.cc
index d090891d7333e7facf8c80dee4bb17da65305111..edae2cebc768292798905e0364aeaf5b64dfdc31 100644 (file)
--- a/src/rgw/driver/rados/rgw_data_sync.cc
+++ b/src/rgw/driver/rados/rgw_data_sync.cc
@@ -595,7 +595,7 @@ public:
       sc->env->async_rados, sc->env->driver,
       { sc->env->svc->zone->get_zone_params().log_pool,
        RGWDataSyncStatusManager::sync_status_oid(sc->source_zone) },
-      string(lock_name), lock_duration, caller, &sc->lcc);
+      string(lock_name), lock_duration, caller, &sc->lcc, sc->env->counters);
   }
 
   int operate(const DoutPrefixProvider *dpp) override {
@@ -2335,7 +2335,7 @@ public:
     lease_cr.reset(new RGWContinuousLeaseCR(sync_env->async_rados, driver,
                                             rgw_raw_obj(pool, status_oid),
                                             lock_name, lock_duration, this,
-                                           &sc->lcc));
+                                           &sc->lcc, sync_env->counters));
     lease_stack.reset(spawn(lease_cr.get(), false));
   }
 };
@@ -5844,7 +5844,7 @@ int RGWSyncBucketCR::operate(const DoutPrefixProvider *dpp)
 
         if (!bucket_lease_cr) {
           bucket_lease_cr.reset(new RGWContinuousLeaseCR(env->async_rados, env->driver, status_obj,
-                lock_name, lock_duration, this, &sc->lcc));
+                lock_name, lock_duration, this, &sc->lcc, env->counters));
           yield spawn(bucket_lease_cr.get(), false);
           while (!bucket_lease_cr->is_locked()) {
             if (bucket_lease_cr->is_done()) {
@@ -5912,7 +5912,7 @@ int RGWSyncBucketCR::operate(const DoutPrefixProvider *dpp)
         // different shards from duplicating the init and full sync
         if (!bucket_lease_cr) {
           bucket_lease_cr.reset(new RGWContinuousLeaseCR(env->async_rados, env->driver, status_obj,
-                                                        lock_name, lock_duration, this, &sc->lcc));
+                                                        lock_name, lock_duration, this, &sc->lcc, env->counters));
           yield spawn(bucket_lease_cr.get(), false);
           while (!bucket_lease_cr->is_locked()) {
             if (bucket_lease_cr->is_done()) {

diff --git a/src/rgw/driver/rados/rgw_sync_counters.cc b/src/rgw/driver/rados/rgw_sync_counters.cc
index b95fa8fc4fed826da8e0ef2a063a39f5a351573e..0b7f6e3c3b46fa9fa2b31086579378fe00c4162e 100644 (file)
--- a/src/rgw/driver/rados/rgw_sync_counters.cc
+++ b/src/rgw/driver/rados/rgw_sync_counters.cc
@@ -21,6 +21,8 @@ PerfCountersRef build(CephContext *cct, const std::string& name)
   b.add_time_avg(l_poll, "poll_latency", "Average latency of replication log requests");
   b.add_u64_counter(l_poll_err, "poll_errors", "Number of replication log request errors");
 
+  b.add_time_avg(l_lock, "lock_latency", "Average latency of sync lock operations");
+
   auto logger = PerfCountersRef{ b.create_perf_counters(), cct };
   cct->get_perfcounters_collection()->add(logger.get());
   return logger;

diff --git a/src/rgw/driver/rados/rgw_sync_counters.h b/src/rgw/driver/rados/rgw_sync_counters.h
index 5120df3517a36c8ad1a7200eee05b06ff0a1dad2..0db227e600ae3ef8bbe7520149b88628f66607ee 100644 (file)
--- a/src/rgw/driver/rados/rgw_sync_counters.h
+++ b/src/rgw/driver/rados/rgw_sync_counters.h
@@ -17,6 +17,8 @@ enum {
   l_poll,
   l_poll_err,
 
+  l_lock,
+
   l_last,
 };