perfcounters: fl -> time, use u64 nsec instead of double

(Almost) all current float users are actually time values, so switch to
a utime_t-based interface and internally using nsec in a u64.  This avoids
using floating point in librbd, which is problematic for windows VMs that
leave the FPU in an unfriendly state.

There are two non-time users in the mds and osd that log the CPU load.
Just multiply those values by 100 and report as ints instead.

Fixes: #3521
Signed-off-by: Sage Weil <sage@inktank.com>

diff --git a/src/client/Client.cc b/src/client/Client.cc
index 641aba170d7a87d4e6e2ac7ca0550f96aa44e8db..35cba96d3c607a09de6e9af9ea558745af16c04e 100644 (file)
--- a/src/client/Client.cc
+++ b/src/client/Client.cc
@@ -360,11 +360,11 @@ int Client::init()
 
   // logger
   PerfCountersBuilder plb(cct, "client", l_c_first, l_c_last);
-  plb.add_fl_avg(l_c_reply, "reply");
-  plb.add_fl_avg(l_c_lat, "lat");
-  plb.add_fl_avg(l_c_wrlat, "wrlat");
-  plb.add_fl_avg(l_c_owrlat, "owrlat");
-  plb.add_fl_avg(l_c_ordlat, "ordlat");
+  plb.add_time_avg(l_c_reply, "reply");
+  plb.add_time_avg(l_c_lat, "lat");
+  plb.add_time_avg(l_c_wrlat, "wrlat");
+  plb.add_time_avg(l_c_owrlat, "owrlat");
+  plb.add_time_avg(l_c_ordlat, "ordlat");
   logger = plb.create_perf_counters();
   cct->get_perfcounters_collection()->add(logger);
 
@@ -1258,8 +1258,8 @@ int Client::make_request(MetaRequest *request,
   utime_t lat = ceph_clock_now(cct);
   lat -= request->sent_stamp;
   ldout(cct, 20) << "lat " << lat << dendl;
-  logger->finc(l_c_lat,(double)lat);
-  logger->finc(l_c_reply,(double)lat);
+  logger->tinc(l_c_lat, lat);
+  logger->tinc(l_c_reply, lat);
 
   request->put();
 
@@ -5746,7 +5746,7 @@ int Client::_write(Fh *f, int64_t offset, uint64_t size, const char *buf)
   // time
   utime_t lat = ceph_clock_now(cct);
   lat -= start;
-  logger->finc(l_c_wrlat,(double)lat);
+  logger->tinc(l_c_wrlat, lat);
     
   // assume success for now.  FIXME.
   uint64_t totalwritten = size;

diff --git a/src/client/SyntheticClient.cc b/src/client/SyntheticClient.cc
index f285f3379dc4773d8c3186baf62ecf8cce221c15..f081244de32cc1fd6d4958eb67cdd9b3fb85020e 100644 (file)
--- a/src/client/SyntheticClient.cc
+++ b/src/client/SyntheticClient.cc
@@ -2356,9 +2356,9 @@ int SyntheticClient::object_rw(int nobj, int osize, int wrpc,
     lat -= start;
     if (client->logger) {
       if (write) 
-       client->logger->fset(l_c_owrlat, lat);
+       client->logger->tset(l_c_owrlat, lat);
       else 
-       client->logger->fset(l_c_ordlat, lat);
+       client->logger->tset(l_c_ordlat, lat);
     }
   }
 

diff --git a/src/common/Finisher.h b/src/common/Finisher.h
index eb2ac243c9933b4b6c9d9207cfd62ca959d6c8ec..173b924d7adcb2800c1b0ea508d80d6784de53f3 100644 (file)
--- a/src/common/Finisher.h
+++ b/src/common/Finisher.h
@@ -95,7 +95,7 @@ class Finisher {
     finisher_thread(this) {
     PerfCountersBuilder b(cct, string("finisher-") + name,
                          l_finisher_first, l_finisher_last);
-    b.add_fl_avg(l_finisher_queue_len, "queue_len");
+    b.add_time_avg(l_finisher_queue_len, "queue_len");
     logger = b.create_perf_counters();
     cct->get_perfcounters_collection()->add(logger);
     logger->set(l_finisher_queue_len, 0);

diff --git a/src/common/Mutex.cc b/src/common/Mutex.cc
index 2dc035a9479d5781c5091c2a9c656c597dad26a8..235086470a70da9e6dffced371b46776fa087c5c 100644 (file)
--- a/src/common/Mutex.cc
+++ b/src/common/Mutex.cc
@@ -30,7 +30,7 @@ Mutex::Mutex(const char *n, bool r, bool ld,
   if (cct) {
     PerfCountersBuilder b(cct, string("mutex-") + name,
                          l_mutex_first, l_mutex_last);
-    b.add_fl_avg(l_mutex_wait, "wait");
+    b.add_time_avg(l_mutex_wait, "wait");
     logger = b.create_perf_counters();
     cct->get_perfcounters_collection()->add(logger);
     logger->set(l_mutex_wait, 0);
@@ -89,7 +89,7 @@ void Mutex::Lock(bool no_lockdep) {
     start = ceph_clock_now(cct);
   int r = pthread_mutex_lock(&_m);
   if (logger && cct && cct->_conf->mutex_perf_counter)
-    logger->finc(l_mutex_wait,
+    logger->tinc(l_mutex_wait,
                 ceph_clock_now(cct) - start);
   assert(r == 0);
   if (lockdep && g_lockdep) _locked();

diff --git a/src/common/Throttle.cc b/src/common/Throttle.cc
index da863c5ebb2fc20c08655b28023247feea0e37f9..844263aa111d2519b395535716b4172f7b42ccdb 100644 (file)
--- a/src/common/Throttle.cc
+++ b/src/common/Throttle.cc
@@ -43,7 +43,7 @@ Throttle::Throttle(CephContext *cct, std::string n, int64_t m)
   b.add_u64_counter(l_throttle_take_sum, "take_sum");
   b.add_u64_counter(l_throttle_put, "put");
   b.add_u64_counter(l_throttle_put_sum, "put_sum");
-  b.add_fl_avg(l_throttle_wait, "wait");
+  b.add_time_avg(l_throttle_wait, "wait");
 
   logger = b.create_perf_counters();
   cct->get_perfcounters_collection()->add(logger);
@@ -90,7 +90,7 @@ bool Throttle::_wait(int64_t c)
     if (waited) {
       ldout(cct, 3) << "_wait finished waiting" << dendl;
       utime_t dur = ceph_clock_now(cct) - start;
-      logger->finc(l_throttle_wait, dur);
+      logger->tinc(l_throttle_wait, dur);
     }
 
     delete cv;

diff --git a/src/common/perf_counters.cc b/src/common/perf_counters.cc
index 144ea3c4d3bfbc05242ec54da887663525e8c3dc..67a777497b38af2812b9f1997bf129be75b6e97f 100644 (file)
--- a/src/common/perf_counters.cc
+++ b/src/common/perf_counters.cc
@@ -106,7 +106,7 @@ void PerfCounters::inc(int idx, uint64_t amt)
   perf_counter_data_any_d& data(m_data[idx - m_lower_bound - 1]);
   if (!(data.type & PERFCOUNTER_U64))
     return;
-  data.u.u64 += amt;
+  data.u64 += amt;
   if (data.type & PERFCOUNTER_LONGRUNAVG)
     data.avgcount++;
 }
@@ -123,8 +123,8 @@ void PerfCounters::dec(int idx, uint64_t amt)
   assert(!(data.type & PERFCOUNTER_LONGRUNAVG));
   if (!(data.type & PERFCOUNTER_U64))
     return;
-  assert(data.u.u64 >= amt);
-  data.u.u64 -= amt;
+  assert(data.u64 >= amt);
+  data.u64 -= amt;
 }
 
 void PerfCounters::set(int idx, uint64_t amt)
@@ -138,7 +138,7 @@ void PerfCounters::set(int idx, uint64_t amt)
   perf_counter_data_any_d& data(m_data[idx - m_lower_bound - 1]);
   if (!(data.type & PERFCOUNTER_U64))
     return;
-  data.u.u64 = amt;
+  data.u64 = amt;
   if (data.type & PERFCOUNTER_LONGRUNAVG)
     data.avgcount++;
 }
@@ -154,10 +154,10 @@ uint64_t PerfCounters::get(int idx) const
   const perf_counter_data_any_d& data(m_data[idx - m_lower_bound - 1]);
   if (!(data.type & PERFCOUNTER_U64))
     return 0;
-  return data.u.u64;
+  return data.u64;
 }
 
-void PerfCounters::finc(int idx, double amt)
+void PerfCounters::tinc(int idx, utime_t amt)
 {
   if (!m_cct->_conf->perf)
     return;
@@ -166,14 +166,14 @@ void PerfCounters::finc(int idx, double amt)
   assert(idx > m_lower_bound);
   assert(idx < m_upper_bound);
   perf_counter_data_any_d& data(m_data[idx - m_lower_bound - 1]);
-  if (!(data.type & PERFCOUNTER_FLOAT))
+  if (!(data.type & PERFCOUNTER_TIME))
     return;
-  data.u.dbl += amt;
+  data.u64 += amt.to_nsec();
   if (data.type & PERFCOUNTER_LONGRUNAVG)
     data.avgcount++;
 }
 
-void PerfCounters::fset(int idx, double amt)
+void PerfCounters::tset(int idx, utime_t amt)
 {
   if (!m_cct->_conf->perf)
     return;
@@ -182,25 +182,25 @@ void PerfCounters::fset(int idx, double amt)
   assert(idx > m_lower_bound);
   assert(idx < m_upper_bound);
   perf_counter_data_any_d& data(m_data[idx - m_lower_bound - 1]);
-  if (!(data.type & PERFCOUNTER_FLOAT))
+  if (!(data.type & PERFCOUNTER_TIME))
     return;
-  data.u.dbl = amt;
+  data.u64 = amt.to_nsec();
   if (data.type & PERFCOUNTER_LONGRUNAVG)
     assert(0);
 }
 
-double PerfCounters::fget(int idx) const
+utime_t PerfCounters::tget(int idx) const
 {
   if (!m_cct->_conf->perf)
-    return 0.0;
+    return utime_t();
 
   Mutex::Locker lck(m_lock);
   assert(idx > m_lower_bound);
   assert(idx < m_upper_bound);
   const perf_counter_data_any_d& data(m_data[idx - m_lower_bound - 1]);
-  if (!(data.type & PERFCOUNTER_FLOAT))
-    return 0.0;
-  return data.u.dbl;
+  if (!(data.type & PERFCOUNTER_TIME))
+    return utime_t();
+  return utime_t(data.u64 / 1000000000ull, data.u64 % 1000000000ull);
 }
 
 void PerfCounters::write_json_to_buf(bufferlist& bl, bool schema)
@@ -253,9 +253,9 @@ PerfCounters::PerfCounters(CephContext *cct, const std::string &name,
 PerfCounters::perf_counter_data_any_d::perf_counter_data_any_d()
   : name(NULL),
     type(PERFCOUNTER_NONE),
+    u64(0),
     avgcount(0)
 {
-  memset(&u, 0, sizeof(u));
 }
 
 void  PerfCounters::perf_counter_data_any_d::write_schema_json(char *buf, size_t buf_sz) const
@@ -269,12 +269,12 @@ void  PerfCounters::perf_counter_data_any_d::write_json(char *buf, size_t buf_sz
     if (type & PERFCOUNTER_U64) {
       snprintf(buf, buf_sz, "\"%s\":{\"avgcount\":%" PRId64 ","
              "\"sum\":%" PRId64 "}", 
-             name, avgcount, u.u64);
+             name, avgcount, u64);
     }
-    else if (type & PERFCOUNTER_FLOAT) {
+    else if (type & PERFCOUNTER_TIME) {
       snprintf(buf, buf_sz, "\"%s\":{\"avgcount\":%" PRId64 ","
-             "\"sum\":%g}",
-             name, avgcount, u.dbl);
+             "\"sum\":%llu.%09llu}",
+              name, avgcount, u64 / 1000000000ull, u64 % 1000000000ull);
     }
     else {
       assert(0);
@@ -283,10 +283,10 @@ void  PerfCounters::perf_counter_data_any_d::write_json(char *buf, size_t buf_sz
   else {
     if (type & PERFCOUNTER_U64) {
       snprintf(buf, buf_sz, "\"%s\":%" PRId64,
-              name, u.u64);
+              name, u64);
     }
-    else if (type & PERFCOUNTER_FLOAT) {
-      snprintf(buf, buf_sz, "\"%s\":%g", name, u.dbl);
+    else if (type & PERFCOUNTER_TIME) {
+      snprintf(buf, buf_sz, "\"%s\":%llu.%09llu", name, u64 / 1000000000ull, u64 % 1000000000ull);
     }
     else {
       assert(0);
@@ -322,14 +322,14 @@ void PerfCountersBuilder::add_u64_avg(int idx, const char *name)
   add_impl(idx, name, PERFCOUNTER_U64 | PERFCOUNTER_LONGRUNAVG);
 }
 
-void PerfCountersBuilder::add_fl(int idx, const char *name)
+void PerfCountersBuilder::add_time(int idx, const char *name)
 {
-  add_impl(idx, name, PERFCOUNTER_FLOAT);
+  add_impl(idx, name, PERFCOUNTER_TIME);
 }
 
-void PerfCountersBuilder::add_fl_avg(int idx, const char *name)
+void PerfCountersBuilder::add_time_avg(int idx, const char *name)
 {
-  add_impl(idx, name, PERFCOUNTER_FLOAT | PERFCOUNTER_LONGRUNAVG);
+  add_impl(idx, name, PERFCOUNTER_TIME | PERFCOUNTER_LONGRUNAVG);
 }
 
 void PerfCountersBuilder::add_impl(int idx, const char *name, int ty)

diff --git a/src/common/perf_counters.h b/src/common/perf_counters.h
index d36736218526dfa5eb2111dfc2796c71ae19d306..269a32f2c46f8e2821d9eff5d9d23bcfc11641b7 100644 (file)
--- a/src/common/perf_counters.h
+++ b/src/common/perf_counters.h
@@ -19,6 +19,7 @@
 #include "common/config_obs.h"
 #include "common/Mutex.h"
 #include "include/buffer.h"
+#include "include/utime.h"
 
 #include <stdint.h>
 #include <string>
@@ -31,7 +32,7 @@ class PerfCountersCollectionTest;
 enum perfcounter_type_d
 {
   PERFCOUNTER_NONE = 0,
-  PERFCOUNTER_FLOAT = 0x1,
+  PERFCOUNTER_TIME = 0x1,
   PERFCOUNTER_U64 = 0x2,
   PERFCOUNTER_LONGRUNAVG = 0x4,
   PERFCOUNTER_COUNTER = 0x8,
@@ -51,15 +52,15 @@ enum perfcounter_type_d
  * and accessed. For a counter, use the inc(counter, amount) function (note
  * that amount defaults to 1 if you don't set it). For a value, use the
  * set(index, value) function.
- * (For floats, use the finc and fset variants.)
+ * (For time, use the tinc and tset variants.)
  *
  * If for some reason you would like to reset your counters, you can do so using
  * the set functions even if they are counters, and you can also
  * increment your values if for some reason you wish to.
  *
- * For the floating-point average, it returns the current value and
+ * For the time average, it returns the current value and
  * the "avgcount" member when read off. avgcount is incremented when you call
- * finc. Calling fset on an average is an error and will assert out.
+ * tinc. Calling tset on an average is an error and will assert out.
  */
 class PerfCounters
 {
@@ -71,9 +72,9 @@ public:
   void set(int idx, uint64_t v);
   uint64_t get(int idx) const;
 
-  void fset(int idx, double v);
-  void finc(int idx, double v);
-  double fget(int idx) const;
+  void tset(int idx, utime_t v);
+  void tinc(int idx, utime_t v);
+  utime_t tget(int idx) const;
 
   void write_json_to_buf(ceph::bufferlist& bl, bool schema);
 
@@ -96,10 +97,7 @@ private:
 
     const char *name;
     enum perfcounter_type_d type;
-    union {
-      uint64_t u64;
-      double dbl;
-    } u;
+    uint64_t u64;
     uint64_t avgcount;
   };
   typedef std::vector<perf_counter_data_any_d> perf_counter_data_vec_t;
@@ -167,8 +165,8 @@ public:
   void add_u64(int key, const char *name);
   void add_u64_counter(int key, const char *name);
   void add_u64_avg(int key, const char *name);
-  void add_fl(int key, const char *name);
-  void add_fl_avg(int key, const char *name);
+  void add_time(int key, const char *name);
+  void add_time_avg(int key, const char *name);
   PerfCounters* create_perf_counters();
 private:
   PerfCountersBuilder(const PerfCountersBuilder &rhs);

diff --git a/src/include/utime.h b/src/include/utime.h
index 5344f04ffc80140fa001c0987ed844ac1dd092d2..8e7891f1594b91dc3511336155a3d21f41b30560 100644 (file)
--- a/src/include/utime.h
+++ b/src/include/utime.h
@@ -72,6 +72,10 @@ public:
   __u32&         sec_ref()  { return tv.tv_sec; }
   __u32&         nsec_ref() { return tv.tv_nsec; }
 
+  uint64_t to_nsec() const {
+    return (uint64_t)tv.tv_nsec + (uint64_t)tv.tv_sec * 1000000000ull;
+  }
+
   void copy_to_timeval(struct timeval *v) const {
     v->tv_sec = tv.tv_sec;
     v->tv_usec = tv.tv_nsec/1000;

diff --git a/src/librbd/AioCompletion.h b/src/librbd/AioCompletion.h
index 7d3f33666434f2fa0e7920c5aa1bd868e6727722..361d425531f24015a5aea06a89c8189feaa99f2a 100644 (file)
--- a/src/librbd/AioCompletion.h
+++ b/src/librbd/AioCompletion.h
@@ -105,11 +105,11 @@ namespace librbd {
       }
       switch (aio_type) {
       case AIO_TYPE_READ: 
-       ictx->perfcounter->finc(l_librbd_aio_rd_latency, elapsed); break;
+       ictx->perfcounter->tinc(l_librbd_aio_rd_latency, elapsed); break;
       case AIO_TYPE_WRITE:
-       ictx->perfcounter->finc(l_librbd_aio_wr_latency, elapsed); break;
+       ictx->perfcounter->tinc(l_librbd_aio_wr_latency, elapsed); break;
       case AIO_TYPE_DISCARD:
-       ictx->perfcounter->finc(l_librbd_aio_discard_latency, elapsed); break;
+       ictx->perfcounter->tinc(l_librbd_aio_discard_latency, elapsed); break;
       default:
        lderr(ictx->cct) << "completed invalid aio_type: " << aio_type << dendl;
        break;

diff --git a/src/librbd/ImageCtx.cc b/src/librbd/ImageCtx.cc
index b29a2caaab7ffd6278970e698d919f4563d636bf..06dcc6619dd596d981685dfd6f9752e08ca272d1 100644 (file)
--- a/src/librbd/ImageCtx.cc
+++ b/src/librbd/ImageCtx.cc
@@ -189,23 +189,23 @@ namespace librbd {
 
     plb.add_u64_counter(l_librbd_rd, "rd");
     plb.add_u64_counter(l_librbd_rd_bytes, "rd_bytes");
-    plb.add_fl_avg(l_librbd_rd_latency, "rd_latency");
+    plb.add_time_avg(l_librbd_rd_latency, "rd_latency");
     plb.add_u64_counter(l_librbd_wr, "wr");
     plb.add_u64_counter(l_librbd_wr_bytes, "wr_bytes");
-    plb.add_fl_avg(l_librbd_wr_latency, "wr_latency");
+    plb.add_time_avg(l_librbd_wr_latency, "wr_latency");
     plb.add_u64_counter(l_librbd_discard, "discard");
     plb.add_u64_counter(l_librbd_discard_bytes, "discard_bytes");
-    plb.add_fl_avg(l_librbd_discard_latency, "discard_latency");
+    plb.add_time_avg(l_librbd_discard_latency, "discard_latency");
     plb.add_u64_counter(l_librbd_flush, "flush");
     plb.add_u64_counter(l_librbd_aio_rd, "aio_rd");
     plb.add_u64_counter(l_librbd_aio_rd_bytes, "aio_rd_bytes");
-    plb.add_fl_avg(l_librbd_aio_rd_latency, "aio_rd_latency");
+    plb.add_time_avg(l_librbd_aio_rd_latency, "aio_rd_latency");
     plb.add_u64_counter(l_librbd_aio_wr, "aio_wr");
     plb.add_u64_counter(l_librbd_aio_wr_bytes, "aio_wr_bytes");
-    plb.add_fl_avg(l_librbd_aio_wr_latency, "aio_wr_latency");
+    plb.add_time_avg(l_librbd_aio_wr_latency, "aio_wr_latency");
     plb.add_u64_counter(l_librbd_aio_discard, "aio_discard");
     plb.add_u64_counter(l_librbd_aio_discard_bytes, "aio_discard_bytes");
-    plb.add_fl_avg(l_librbd_aio_discard_latency, "aio_discard_latency");
+    plb.add_time_avg(l_librbd_aio_discard_latency, "aio_discard_latency");
     plb.add_u64_counter(l_librbd_snap_create, "snap_create");
     plb.add_u64_counter(l_librbd_snap_remove, "snap_remove");
     plb.add_u64_counter(l_librbd_snap_rollback, "snap_rollback");

diff --git a/src/librbd/internal.cc b/src/librbd/internal.cc
index 501a63d55727d7e1ee08a569403d480c40041010..2be4f2d70399b74142e91938a9c812197a226d5f 100644 (file)
--- a/src/librbd/internal.cc
+++ b/src/librbd/internal.cc
@@ -2152,7 +2152,7 @@ reprotect_and_return_err:
     }
 
     elapsed = ceph_clock_now(ictx->cct) - start_time;
-    ictx->perfcounter->finc(l_librbd_rd_latency, elapsed);
+    ictx->perfcounter->tinc(l_librbd_rd_latency, elapsed);
     ictx->perfcounter->inc(l_librbd_rd);
     ictx->perfcounter->inc(l_librbd_rd_bytes, mylen);
     return total_read;
@@ -2235,7 +2235,7 @@ reprotect_and_return_err:
       return ret;
 
     elapsed = ceph_clock_now(ictx->cct) - start_time;
-    ictx->perfcounter->finc(l_librbd_wr_latency, elapsed);
+    ictx->perfcounter->tinc(l_librbd_wr_latency, elapsed);
     ictx->perfcounter->inc(l_librbd_wr);
     ictx->perfcounter->inc(l_librbd_wr_bytes, mylen);
     return mylen;

diff --git a/src/mds/MDS.cc b/src/mds/MDS.cc
index fde5ff11ff00cf10b9b22d1f625e188edbb1187d..9b2417bdfde8eaf19a9a0c99d97a27917f569b60 100644 (file)
--- a/src/mds/MDS.cc
+++ b/src/mds/MDS.cc
@@ -200,7 +200,7 @@ void MDS::create_logger()
 
     mds_plb.add_u64_counter(l_mds_req, "req"); // FIXME: nobody is actually setting this
     mds_plb.add_u64_counter(l_mds_reply, "reply");
-    mds_plb.add_fl_avg(l_mds_replyl, "replyl");
+    mds_plb.add_time_avg(l_mds_replyl, "replyl");
     mds_plb.add_u64_counter(l_mds_fw, "fw");
     
     mds_plb.add_u64_counter(l_mds_dir_f, "dir_f");
@@ -243,7 +243,7 @@ void MDS::create_logger()
     mds_plb.add_u64_counter(l_mds_trino, "trino");
     mds_plb.add_u64_counter(l_mds_tlock, "tlock");
     
-    mds_plb.add_fl(l_mds_l, "l");
+    mds_plb.add_u64(l_mds_l, "l");
     mds_plb.add_u64(l_mds_q, "q");
     mds_plb.add_u64(l_mds_popanyd, "popanyd"); // FIXME: unused
     mds_plb.add_u64(l_mds_popnest, "popnest");
@@ -561,7 +561,7 @@ void MDS::tick()
   if (logger) {
     req_rate = logger->get(l_mds_req);
     
-    logger->fset(l_mds_l, (int)load.mds_load());
+    logger->set(l_mds_l, 100 * load.mds_load());
     logger->set(l_mds_q, messenger->get_dispatch_queue_len());
     logger->set(l_mds_sm, mdcache->num_subtrees());
 

diff --git a/src/mds/Server.cc b/src/mds/Server.cc
index b0fd9ec0c15e68413da59e707cb86cb6f8f258c9..fbb0289c283587889a00efd6e8ac1882c465b7fd 100644 (file)
--- a/src/mds/Server.cc
+++ b/src/mds/Server.cc
@@ -832,8 +832,8 @@ void Server::early_reply(MDRequest *mdr, CInode *tracei, CDentry *tracedn)
   mdr->did_early_reply = true;
 
   mds->logger->inc(l_mds_reply);
-  double lat = ceph_clock_now(g_ceph_context) - mdr->client_request->get_recv_stamp();
-  mds->logger->finc(l_mds_replyl, lat);
+  utime_t lat = ceph_clock_now(g_ceph_context) - mdr->client_request->get_recv_stamp();
+  mds->logger->tinc(l_mds_replyl, lat);
   dout(20) << "lat " << lat << dendl;
 }
 
@@ -874,8 +874,8 @@ void Server::reply_request(MDRequest *mdr, MClientReply *reply, CInode *tracei,
   if (!did_early_reply && !is_replay) {
 
     mds->logger->inc(l_mds_reply);
-    double lat = ceph_clock_now(g_ceph_context) - mdr->client_request->get_recv_stamp();
-    mds->logger->finc(l_mds_replyl, lat);
+    utime_t lat = ceph_clock_now(g_ceph_context) - mdr->client_request->get_recv_stamp();
+    mds->logger->tinc(l_mds_replyl, lat);
     dout(20) << "lat " << lat << dendl;
     
     if (tracei)

diff --git a/src/os/FileJournal.cc b/src/os/FileJournal.cc
index 702323ea4cb98f6e26f4bbd42d422c20bbcb19f0..5f31406db409e0e2db845ae1f761604e4f54592d 100644 (file)
--- a/src/os/FileJournal.cc
+++ b/src/os/FileJournal.cc
@@ -840,7 +840,7 @@ void FileJournal::queue_completions_thru(uint64_t seq)
             << " " << next.finish
             << " lat " << lat << dendl;
     if (logger) {
-      logger->finc(l_os_j_lat, lat);
+      logger->tinc(l_os_j_lat, lat);
     }
     if (next.finish)
       finisher->queue(next.finish);

diff --git a/src/os/FileStore.cc b/src/os/FileStore.cc
index 70eef5ae13f68aed71f972ceeacbed8e50bfae31..3feb92924a9b85e5500714abb969c51ac220bb5c 100644 (file)
--- a/src/os/FileStore.cc
+++ b/src/os/FileStore.cc
@@ -442,7 +442,7 @@ FileStore::FileStore(const std::string &base, const std::string &jdev, const cha
   plb.add_u64(l_os_jq_max_bytes, "journal_queue_max_bytes");
   plb.add_u64(l_os_jq_bytes, "journal_queue_bytes");
   plb.add_u64_counter(l_os_j_bytes, "journal_bytes");
-  plb.add_fl_avg(l_os_j_lat, "journal_latency");
+  plb.add_time_avg(l_os_j_lat, "journal_latency");
   plb.add_u64_counter(l_os_j_wr, "journal_wr");
   plb.add_u64_avg(l_os_j_wr_bytes, "journal_wr_bytes");
   plb.add_u64(l_os_oq_max_ops, "op_queue_max_ops");
@@ -451,12 +451,12 @@ FileStore::FileStore(const std::string &base, const std::string &jdev, const cha
   plb.add_u64(l_os_oq_max_bytes, "op_queue_max_bytes");
   plb.add_u64(l_os_oq_bytes, "op_queue_bytes");
   plb.add_u64_counter(l_os_bytes, "bytes");
-  plb.add_fl_avg(l_os_apply_lat, "apply_latency");
+  plb.add_time_avg(l_os_apply_lat, "apply_latency");
   plb.add_u64(l_os_committing, "committing");
 
   plb.add_u64_counter(l_os_commit, "commitcycle");
-  plb.add_fl_avg(l_os_commit_len, "commitcycle_interval");
-  plb.add_fl_avg(l_os_commit_lat, "commitcycle_latency");
+  plb.add_time_avg(l_os_commit_len, "commitcycle_interval");
+  plb.add_time_avg(l_os_commit_lat, "commitcycle_latency");
   plb.add_u64_counter(l_os_j_full, "journal_full");
 
   logger = plb.create_perf_counters();
@@ -1977,7 +1977,7 @@ void FileStore::_finish_op(OpSequencer *osr)
 
   utime_t lat = ceph_clock_now(g_ceph_context);
   lat -= o->start;
-  logger->finc(l_os_apply_lat, lat);
+  logger->tinc(l_os_apply_lat, lat);
 
   if (o->onreadable_sync) {
     o->onreadable_sync->finish(0);
@@ -3420,8 +3420,8 @@ void FileStore::sync_entry()
       dout(10) << "sync_entry commit took " << lat << ", interval was " << dur << dendl;
 
       logger->inc(l_os_commit);
-      logger->finc(l_os_commit_lat, lat);
-      logger->finc(l_os_commit_len, dur);
+      logger->tinc(l_os_commit_lat, lat);
+      logger->tinc(l_os_commit_len, dur);
 
       apply_manager.commit_finish();
 

diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc
index 3dfae663ba2c73b9d4757ba144a874763491e585..cb2e4d7fcebab7d8006bcc3976676a663391359c 100644 (file)
--- a/src/osd/OSD.cc
+++ b/src/osd/OSD.cc
@@ -958,33 +958,33 @@ void OSD::create_logger()
   osd_plb.add_u64_counter(l_osd_op,       "op");           // client ops
   osd_plb.add_u64_counter(l_osd_op_inb,   "op_in_bytes");       // client op in bytes (writes)
   osd_plb.add_u64_counter(l_osd_op_outb,  "op_out_bytes");      // client op out bytes (reads)
-  osd_plb.add_fl_avg(l_osd_op_lat,   "op_latency");       // client op latency
+  osd_plb.add_time_avg(l_osd_op_lat,   "op_latency");       // client op latency
 
   osd_plb.add_u64_counter(l_osd_op_r,      "op_r");        // client reads
   osd_plb.add_u64_counter(l_osd_op_r_outb, "op_r_out_bytes");   // client read out bytes
-  osd_plb.add_fl_avg(l_osd_op_r_lat,  "op_r_latency");    // client read latency
+  osd_plb.add_time_avg(l_osd_op_r_lat,  "op_r_latency");    // client read latency
   osd_plb.add_u64_counter(l_osd_op_w,      "op_w");        // client writes
   osd_plb.add_u64_counter(l_osd_op_w_inb,  "op_w_in_bytes");    // client write in bytes
-  osd_plb.add_fl_avg(l_osd_op_w_rlat, "op_w_rlat");   // client write readable/applied latency
-  osd_plb.add_fl_avg(l_osd_op_w_lat,  "op_w_latency");    // client write latency
+  osd_plb.add_time_avg(l_osd_op_w_rlat, "op_w_rlat");   // client write readable/applied latency
+  osd_plb.add_time_avg(l_osd_op_w_lat,  "op_w_latency");    // client write latency
   osd_plb.add_u64_counter(l_osd_op_rw,     "op_rw");       // client rmw
   osd_plb.add_u64_counter(l_osd_op_rw_inb, "op_rw_in_bytes");   // client rmw in bytes
   osd_plb.add_u64_counter(l_osd_op_rw_outb,"op_rw_out_bytes");  // client rmw out bytes
-  osd_plb.add_fl_avg(l_osd_op_rw_rlat,"op_rw_rlat");  // client rmw readable/applied latency
-  osd_plb.add_fl_avg(l_osd_op_rw_lat, "op_rw_latency");   // client rmw latency
+  osd_plb.add_time_avg(l_osd_op_rw_rlat,"op_rw_rlat");  // client rmw readable/applied latency
+  osd_plb.add_time_avg(l_osd_op_rw_lat, "op_rw_latency");   // client rmw latency
 
   osd_plb.add_u64_counter(l_osd_sop,       "subop");         // subops
   osd_plb.add_u64_counter(l_osd_sop_inb,   "subop_in_bytes");     // subop in bytes
-  osd_plb.add_fl_avg(l_osd_sop_lat,   "subop_latency");     // subop latency
+  osd_plb.add_time_avg(l_osd_sop_lat,   "subop_latency");     // subop latency
 
   osd_plb.add_u64_counter(l_osd_sop_w,     "subop_w");          // replicated (client) writes
   osd_plb.add_u64_counter(l_osd_sop_w_inb, "subop_w_in_bytes");      // replicated write in bytes
-  osd_plb.add_fl_avg(l_osd_sop_w_lat, "subop_w_latency");      // replicated write latency
+  osd_plb.add_time_avg(l_osd_sop_w_lat, "subop_w_latency");      // replicated write latency
   osd_plb.add_u64_counter(l_osd_sop_pull,     "subop_pull");       // pull request
-  osd_plb.add_fl_avg(l_osd_sop_pull_lat, "subop_pull_latency");
+  osd_plb.add_time_avg(l_osd_sop_pull_lat, "subop_pull_latency");
   osd_plb.add_u64_counter(l_osd_sop_push,     "subop_push");       // push (write)
   osd_plb.add_u64_counter(l_osd_sop_push_inb, "subop_push_in_bytes");
-  osd_plb.add_fl_avg(l_osd_sop_push_lat, "subop_push_latency");
+  osd_plb.add_time_avg(l_osd_sop_push_lat, "subop_push_latency");
 
   osd_plb.add_u64_counter(l_osd_pull,      "pull");       // pull requests sent
   osd_plb.add_u64_counter(l_osd_push,      "push");       // push messages
@@ -995,7 +995,7 @@ void OSD::create_logger()
 
   osd_plb.add_u64_counter(l_osd_rop, "recovery_ops");       // recovery ops (started)
 
-  osd_plb.add_fl(l_osd_loadavg, "loadavg");
+  osd_plb.add_u64(l_osd_loadavg, "loadavg");
   osd_plb.add_u64(l_osd_buf, "buffer_bytes");       // total ceph::buffer bytes
 
   osd_plb.add_u64(l_osd_pg, "numpg");   // num pgs
@@ -2014,7 +2014,7 @@ void OSD::heartbeat()
   // get CPU load avg
   double loadavgs[1];
   if (getloadavg(loadavgs, 1) == 1)
-    logger->fset(l_osd_loadavg, loadavgs[0]);
+    logger->set(l_osd_loadavg, 100 * loadavgs[0]);
 
   dout(30) << "heartbeat checking stats" << dendl;
 

diff --git a/src/osd/ReplicatedPG.cc b/src/osd/ReplicatedPG.cc
index 3dd5e9566d62694465a4d906ce7121caa3a28ddd..e11e3a364d060468eada6f36b0b6e574c022d00a 100644 (file)
--- a/src/osd/ReplicatedPG.cc
+++ b/src/osd/ReplicatedPG.cc
@@ -1033,23 +1033,23 @@ void ReplicatedPG::log_op_stats(OpContext *ctx)
 
   osd->logger->inc(l_osd_op_outb, outb);
   osd->logger->inc(l_osd_op_inb, inb);
-  osd->logger->finc(l_osd_op_lat, latency);
+  osd->logger->tinc(l_osd_op_lat, latency);
 
   if (m->may_read() && m->may_write()) {
     osd->logger->inc(l_osd_op_rw);
     osd->logger->inc(l_osd_op_rw_inb, inb);
     osd->logger->inc(l_osd_op_rw_outb, outb);
-    osd->logger->finc(l_osd_op_rw_rlat, rlatency);
-    osd->logger->finc(l_osd_op_rw_lat, latency);
+    osd->logger->tinc(l_osd_op_rw_rlat, rlatency);
+    osd->logger->tinc(l_osd_op_rw_lat, latency);
   } else if (m->may_read()) {
     osd->logger->inc(l_osd_op_r);
     osd->logger->inc(l_osd_op_r_outb, outb);
-    osd->logger->finc(l_osd_op_r_lat, latency);
+    osd->logger->tinc(l_osd_op_r_lat, latency);
   } else if (m->may_write()) {
     osd->logger->inc(l_osd_op_w);
     osd->logger->inc(l_osd_op_w_inb, inb);
-    osd->logger->finc(l_osd_op_w_rlat, rlatency);
-    osd->logger->finc(l_osd_op_w_lat, latency);
+    osd->logger->tinc(l_osd_op_w_rlat, rlatency);
+    osd->logger->tinc(l_osd_op_w_lat, latency);
   } else
     assert(0);
 
@@ -1071,11 +1071,11 @@ void ReplicatedPG::log_subop_stats(OpRequestRef op, int tag_inb, int tag_lat)
   osd->logger->inc(l_osd_sop);
 
   osd->logger->inc(l_osd_sop_inb, inb);
-  osd->logger->finc(l_osd_sop_lat, latency);
+  osd->logger->tinc(l_osd_sop_lat, latency);
 
   if (tag_inb)
     osd->logger->inc(tag_inb, inb);
-  osd->logger->finc(tag_lat, latency);
+  osd->logger->tinc(tag_lat, latency);
 
   dout(15) << "log_subop_stats " << *op->request << " inb " << inb << " latency " << latency << dendl;
 }

diff --git a/src/osdc/Journaler.cc b/src/osdc/Journaler.cc
index 0345bc15dd303b60eb4dd1f4dad55e37cfc47151..544ac8c49c43d060f25aeb810f38fa59a6167844 100644 (file)
--- a/src/osdc/Journaler.cc
+++ b/src/osdc/Journaler.cc
@@ -405,7 +405,7 @@ void Journaler::_finish_flush(int r, uint64_t start, utime_t stamp)
   if (logger) {
     utime_t lat = ceph_clock_now(cct);
     lat -= stamp;
-    logger->finc(logger_key_lat, lat);
+    logger->tinc(logger_key_lat, lat);
   }
 
   // adjust safe_pos

diff --git a/src/osdc/ObjectCacher.cc b/src/osdc/ObjectCacher.cc
index c933bad164a2f659e391468fb9303131197c0382..e98beb45d897f2a10e4b5940910a3346a7c0cdc8 100644 (file)
--- a/src/osdc/ObjectCacher.cc
+++ b/src/osdc/ObjectCacher.cc
@@ -537,7 +537,7 @@ void ObjectCacher::perf_start()
                       "data_overwritten_while_flushing");
   plb.add_u64_counter(l_objectcacher_write_ops_blocked, "write_ops_blocked");
   plb.add_u64_counter(l_objectcacher_write_bytes_blocked, "write_bytes_blocked");
-  plb.add_fl(l_objectcacher_write_time_blocked, "write_time_blocked");
+  plb.add_time(l_objectcacher_write_time_blocked, "write_time_blocked");
 
   perfcounter = plb.create_perf_counters();
   cct->get_perfcounters_collection()->add(perfcounter);
@@ -1318,7 +1318,7 @@ int ObjectCacher::_wait_for_write(OSDWrite *wr, uint64_t len, ObjectSet *oset, M
     perfcounter->inc(l_objectcacher_write_ops_blocked);
     perfcounter->inc(l_objectcacher_write_bytes_blocked, len);
     utime_t blocked = ceph_clock_now(cct) - start;
-    perfcounter->finc(l_objectcacher_write_time_blocked, (double) blocked);
+    perfcounter->tinc(l_objectcacher_write_time_blocked, blocked);
   }
   return ret;
 }

diff --git a/src/rgw/rgw_common.cc b/src/rgw/rgw_common.cc
index 35b31be60c07faa441da03fb2c60a81857f1956e..8564fdd985a5ee9c2f2d543c64db61b9ceadb32a 100644 (file)
--- a/src/rgw/rgw_common.cc
+++ b/src/rgw/rgw_common.cc
@@ -28,10 +28,10 @@ int rgw_perf_start(CephContext *cct)
 
   plb.add_u64_counter(l_rgw_get, "get");
   plb.add_u64_counter(l_rgw_get_b, "get_b");
-  plb.add_fl_avg(l_rgw_get_lat, "get_initial_lat");
+  plb.add_time_avg(l_rgw_get_lat, "get_initial_lat");
   plb.add_u64_counter(l_rgw_put, "put");
   plb.add_u64_counter(l_rgw_put_b, "put_b");
-  plb.add_fl_avg(l_rgw_put_lat, "put_initial_lat");
+  plb.add_time_avg(l_rgw_put_lat, "put_initial_lat");
 
   plb.add_u64(l_rgw_qlen, "qlen");
   plb.add_u64(l_rgw_qactive, "qactive");

diff --git a/src/rgw/rgw_op.cc b/src/rgw/rgw_op.cc
index 49863c3046d9437b5fe5243d66e19a17f3a07dc2..4bbe8e6f36e781b4e9007b79ab8d9d96b328550f 100644 (file)
--- a/src/rgw/rgw_op.cc
+++ b/src/rgw/rgw_op.cc
@@ -388,7 +388,7 @@ int RGWGetObj::read_user_manifest_part(rgw_bucket& bucket, RGWObjEnt& ent, RGWAc
     cur_ofs += len;
     ofs += len;
     ret = 0;
-    perfcounter->finc(l_rgw_get_lat,
+    perfcounter->tinc(l_rgw_get_lat,
                       (ceph_clock_now(s->cct) - start_time));
     send_response_data(bl);
 
@@ -449,7 +449,7 @@ int RGWGetObj::iterate_user_manifest_parts(rgw_bucket& bucket, string& obj_prefi
        found_end = true;
       }
 
-      perfcounter->finc(l_rgw_get_lat,
+      perfcounter->tinc(l_rgw_get_lat,
                        (ceph_clock_now(s->cct) - start_time));
 
       if (found_start) {
@@ -588,7 +588,7 @@ void RGWGetObj::execute()
     ofs += len;
     ret = 0;
 
-    perfcounter->finc(l_rgw_get_lat,
+    perfcounter->tinc(l_rgw_get_lat,
                      (ceph_clock_now(s->cct) - start_time));
     ret = send_response_data(bl);
     bl.clear();
@@ -1369,7 +1369,7 @@ void RGWPutObj::execute()
   ret = processor->complete(etag, attrs);
 done:
   dispose_processor(processor);
-  perfcounter->finc(l_rgw_put_lat,
+  perfcounter->tinc(l_rgw_put_lat,
                    (ceph_clock_now(s->cct) - s->time));
 }
 

diff --git a/src/test/perf_counters.cc b/src/test/perf_counters.cc
index 8ac408bb41490499926c4a83a2fc8248f606f016..e5090d2c5b09e9ad412e9a473782d377c516ba61 100644 (file)
--- a/src/test/perf_counters.cc
+++ b/src/test/perf_counters.cc
@@ -91,8 +91,8 @@ static PerfCounters* setup_test_perfcounters1(CephContext *cct)
   PerfCountersBuilder bld(cct, "test_perfcounter_1",
          TEST_PERFCOUNTERS1_ELEMENT_FIRST, TEST_PERFCOUNTERS1_ELEMENT_LAST);
   bld.add_u64(TEST_PERFCOUNTERS1_ELEMENT_1, "element1");
-  bld.add_fl(TEST_PERFCOUNTERS1_ELEMENT_2, "element2");
-  bld.add_fl_avg(TEST_PERFCOUNTERS1_ELEMENT_3, "element3");
+  bld.add_time(TEST_PERFCOUNTERS1_ELEMENT_2, "element2");
+  bld.add_time_avg(TEST_PERFCOUNTERS1_ELEMENT_3, "element3");
   return bld.create_perf_counters();
 }
 
@@ -104,18 +104,18 @@ TEST(PerfCounters, SinglePerfCounters) {
   std::string msg;
   ASSERT_EQ("", client.do_request("perfcounters_dump", &msg));
   ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':0,"
-           "'element2':0,'element3':{'avgcount':0,'sum':0}}}"), msg);
+           "'element2':0.000000000,'element3':{'avgcount':0,'sum':0.000000000}}}"), msg);
   fake_pf->inc(TEST_PERFCOUNTERS1_ELEMENT_1);
-  fake_pf->fset(TEST_PERFCOUNTERS1_ELEMENT_2, 0.5);
-  fake_pf->finc(TEST_PERFCOUNTERS1_ELEMENT_3, 100.0);
+  fake_pf->tset(TEST_PERFCOUNTERS1_ELEMENT_2, utime_t(0, 500000000));
+  fake_pf->tinc(TEST_PERFCOUNTERS1_ELEMENT_3, utime_t(100, 0));
   ASSERT_EQ("", client.do_request("perfcounters_dump", &msg));
   ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':1,"
-           "'element2':0.5,'element3':{'avgcount':1,'sum':100}}}"), msg);
-  fake_pf->finc(TEST_PERFCOUNTERS1_ELEMENT_3, 0.0);
-  fake_pf->finc(TEST_PERFCOUNTERS1_ELEMENT_3, 25.0);
+           "'element2':0.500000000,'element3':{'avgcount':1,'sum':100.000000000}}}"), msg);
+  fake_pf->tinc(TEST_PERFCOUNTERS1_ELEMENT_3, utime_t());
+  fake_pf->tinc(TEST_PERFCOUNTERS1_ELEMENT_3, utime_t(25,0));
   ASSERT_EQ("", client.do_request("perfcounters_dump", &msg));
-  ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':1,'element2':0.5,"
-           "'element3':{'avgcount':3,'sum':125}}}"), msg);
+  ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':1,'element2':0.500000000,"
+           "'element3':{'avgcount':3,'sum':125.000000000}}}"), msg);
 }
 
 enum {
@@ -130,7 +130,7 @@ static PerfCounters* setup_test_perfcounter2(CephContext *cct)
   PerfCountersBuilder bld(cct, "test_perfcounter_2",
          TEST_PERFCOUNTERS2_ELEMENT_FIRST, TEST_PERFCOUNTERS2_ELEMENT_LAST);
   bld.add_u64(TEST_PERFCOUNTERS2_ELEMENT_FOO, "foo");
-  bld.add_fl(TEST_PERFCOUNTERS2_ELEMENT_BAR, "bar");
+  bld.add_time(TEST_PERFCOUNTERS2_ELEMENT_BAR, "bar");
   return bld.create_perf_counters();
 }
 
@@ -145,19 +145,19 @@ TEST(PerfCounters, MultiplePerfCounters) {
   std::string msg;
 
   ASSERT_EQ("", client.do_request("perfcounters_dump", &msg));
-  ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':0,'element2':0,'element3':"
-           "{'avgcount':0,'sum':0}},'test_perfcounter_2':{'foo':0,'bar':0}}"), msg);
+  ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':0,'element2':0.000000000,'element3':"
+           "{'avgcount':0,'sum':0.000000000}},'test_perfcounter_2':{'foo':0,'bar':0.000000000}}"), msg);
 
   fake_pf1->inc(TEST_PERFCOUNTERS1_ELEMENT_1);
   fake_pf1->inc(TEST_PERFCOUNTERS1_ELEMENT_1, 5);
   ASSERT_EQ("", client.do_request("perfcounters_dump", &msg));
-  ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':6,'element2':0,'element3':"
-           "{'avgcount':0,'sum':0}},'test_perfcounter_2':{'foo':0,'bar':0}}"), msg);
+  ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':6,'element2':0.000000000,'element3':"
+           "{'avgcount':0,'sum':0.000000000}},'test_perfcounter_2':{'foo':0,'bar':0.000000000}}"), msg);
 
   coll->remove(fake_pf2);
   ASSERT_EQ("", client.do_request("perfcounters_dump", &msg));
-  ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':6,'element2':0,"
-           "'element3':{'avgcount':0,'sum':0}}}"), msg);
+  ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':6,'element2':0.000000000,"
+           "'element3':{'avgcount':0,'sum':0.000000000}}}"), msg);
   ASSERT_EQ("", client.do_request("perfcounters_schema", &msg));
   ASSERT_EQ(sd("{'test_perfcounter_1':{'element1':{'type':2},"
               "'element2':{'type':1},'element3':{'type':5}}}"), msg);