os/bluestore: add perfcount for bluestore/bluefs allocator

Allocator performance is the performance limiting factor
on performance storage. This performance count can help
us intuitively observe the reasons for changes in bluestore
performance.

Signed-off-by: Yite Gu <yitegu0@gamil.com>

diff --git a/src/os/bluestore/BlueFS.cc b/src/os/bluestore/BlueFS.cc
index 54d0bbc38e5710134241cf324ff7216124de9b87..f9e8dae1282d3ebbd3353374ac8f67d7becc88fe 100644 (file)
--- a/src/os/bluestore/BlueFS.cc
+++ b/src/os/bluestore/BlueFS.cc
@@ -285,9 +285,9 @@ void BlueFS::_init_logger()
                    "mxwb",
                    PerfCountersBuilder::PRIO_INTERESTING,
                    unit_t(UNIT_BYTES));
-  b.add_u64_counter(l_bluefs_main_alloc_unit, "alloc_unit_main",
+  b.add_u64_counter(l_bluefs_slow_alloc_unit, "alloc_unit_slow",
                    "Allocation unit size (in bytes) for primary/shared device",
-                   "aumb",
+                   "ausb",
                    PerfCountersBuilder::PRIO_CRITICAL,
                    unit_t(UNIT_BYTES));
   b.add_u64_counter(l_bluefs_db_alloc_unit, "alloc_unit_db",
@@ -427,6 +427,30 @@ void BlueFS::_init_logger()
            "How many times bluefs read found page with all 0s");
   b.add_u64(l_bluefs_read_zeros_errors, "read_zeros_errors",
            "How many times bluefs read found transient page with all 0s");
+  b.add_time_avg(l_bluefs_wal_alloc_lat, "wal_alloc_lat",
+                "Average bluefs wal allocate latency",
+                "bwal",
+                PerfCountersBuilder::PRIO_USEFUL);
+  b.add_time_avg(l_bluefs_db_alloc_lat, "db_alloc_lat",
+                "Average bluefs db allocate latency",
+                "bdal",
+                PerfCountersBuilder::PRIO_USEFUL);
+  b.add_time_avg(l_bluefs_slow_alloc_lat, "slow_alloc_lat",
+                "Average allocation latency for primary/shared device",
+                "bsal",
+                PerfCountersBuilder::PRIO_USEFUL);
+  b.add_time(l_bluefs_wal_alloc_max_lat, "alloc_wal_max_lat",
+             "Max allocation latency for wal device",
+             "awxt",
+             PerfCountersBuilder::PRIO_INTERESTING);
+  b.add_time(l_bluefs_db_alloc_max_lat, "alloc_db_max_lat",
+             "Max allocation latency for db device",
+             "adxt",
+             PerfCountersBuilder::PRIO_INTERESTING);
+  b.add_time(l_bluefs_slow_alloc_max_lat, "alloc_slow_max_lat",
+             "Max allocation latency for primary/shared device",
+             "asxt",
+             PerfCountersBuilder::PRIO_INTERESTING);
 
   logger = b.create_perf_counters();
   cct->get_perfcounters_collection()->add(logger);
@@ -712,7 +736,7 @@ void BlueFS::_init_alloc()
     alloc_size[BDEV_SLOW] = 0;
   }
   logger->set(l_bluefs_db_alloc_unit, alloc_size[BDEV_DB]);
-  logger->set(l_bluefs_main_alloc_unit, alloc_size[BDEV_SLOW]);
+  logger->set(l_bluefs_slow_alloc_unit, alloc_size[BDEV_SLOW]);
   // new wal and db devices are never shared
   if (bdev[BDEV_NEWWAL]) {
     alloc_size[BDEV_NEWWAL] = cct->_conf->bluefs_alloc_size;
@@ -3814,6 +3838,33 @@ const char* BlueFS::get_device_name(unsigned id)
   return names[id];
 }
 
+void BlueFS::_update_allocate_stats(uint8_t id, const ceph::timespan& d)
+{
+  switch(id) {
+    case BDEV_SLOW:
+      logger->tinc(l_bluefs_slow_alloc_lat, d);
+      if (d > max_alloc_lat[id]) {
+        logger->tset(l_bluefs_slow_alloc_max_lat, utime_t(d));
+        max_alloc_lat[id] = d;
+      }
+      break;
+    case BDEV_DB:
+      logger->tinc(l_bluefs_db_alloc_lat, d);
+      if (d > max_alloc_lat[id]) {
+        logger->tset(l_bluefs_db_alloc_max_lat, utime_t(d));
+        max_alloc_lat[id] = d;
+      }
+      break;
+    case BDEV_WAL:
+      logger->tinc(l_bluefs_wal_alloc_lat, d);
+      if (d > max_alloc_lat[id]) {
+        logger->tset(l_bluefs_wal_alloc_max_lat, utime_t(d));
+        max_alloc_lat[id] = d;
+      }
+      break;
+  }
+}
+
 int BlueFS::_allocate(uint8_t id, uint64_t len,
                      uint64_t alloc_unit,
                      bluefs_fnode_t* node,
@@ -3859,7 +3910,9 @@ int BlueFS::_allocate(uint8_t id, uint64_t len,
     }   
     ++alloc_attempts;
     extents.reserve(4);  // 4 should be (more than) enough for most allocations
+    auto t0 = mono_clock::now();
     alloc_len = alloc[id]->allocate(need, alloc_unit, hint, &extents);
+    _update_allocate_stats(id, mono_clock::now() - t0);
   }
   if (alloc_len < 0 || alloc_len < need) {
     if (alloc[id]) {

diff --git a/src/os/bluestore/BlueFS.h b/src/os/bluestore/BlueFS.h
index 759e71fdf05ef3c0982528fc3e1a6a285c1dc30c..86fb3cc882e1e4c2c5cd9d98d0d98e246734ea7a 100644 (file)
--- a/src/os/bluestore/BlueFS.h
+++ b/src/os/bluestore/BlueFS.h
@@ -43,7 +43,7 @@ enum {
   l_bluefs_max_bytes_wal,
   l_bluefs_max_bytes_db,
   l_bluefs_max_bytes_slow,
-  l_bluefs_main_alloc_unit,
+  l_bluefs_slow_alloc_unit,
   l_bluefs_db_alloc_unit,
   l_bluefs_wal_alloc_unit,
   l_bluefs_read_random_lat,
@@ -79,6 +79,12 @@ enum {
   l_bluefs_alloc_shared_size_fallbacks,
   l_bluefs_read_zeros_candidate,
   l_bluefs_read_zeros_errors,
+  l_bluefs_wal_alloc_lat,
+  l_bluefs_db_alloc_lat,
+  l_bluefs_slow_alloc_lat,
+  l_bluefs_wal_alloc_max_lat,
+  l_bluefs_db_alloc_max_lat,
+  l_bluefs_slow_alloc_max_lat,
   l_bluefs_last,
 };
 
@@ -440,6 +446,8 @@ private:
     l_bluefs_max_bytes_db,
   };
 
+  ceph::timespan max_alloc_lat[MAX_BDEV] = {ceph::make_timespan(0)};
+
   // cache
   struct {
     ceph::mutex lock = ceph::make_mutex("BlueFS::nodes.lock");
@@ -528,6 +536,7 @@ private:
   const char* get_device_name(unsigned id);
 
   typedef std::function<void(const bluefs_extent_t)> update_fn_t;
+  void _update_allocate_stats(uint8_t id, const ceph::timespan& d);
   int _allocate(uint8_t bdev, uint64_t len,
                 uint64_t alloc_unit,
                bluefs_fnode_t* node,

diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index d2cc85300215f8edc929652070429aef55fad7a8..b2feb54c0ae3d91bcd4aa6fcfc7a80b206226fa1 100644 (file)
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -6456,6 +6456,10 @@ void BlueStore::_init_logger()
     l_bluestore_allocate_hist, "allocate_histogram",
     alloc_hist_x_axis_config, alloc_hist_y_axis_config,
     "Histogram of requested block allocations vs. given ones");
+  b.add_time_avg(l_bluestore_allocator_lat, "allocator_lat",
+    "Average bluestore allocator latency",
+    "bsal",
+    PerfCountersBuilder::PRIO_USEFUL);
 
   logger = b.create_perf_counters();
   cct->get_perfcounters_collection()->add(logger);
@@ -16799,9 +16803,14 @@ int BlueStore::_do_alloc_write(
   PExtentVector prealloc;
   prealloc.reserve(2 * wctx->writes.size());
   int64_t prealloc_left = 0;
+  auto start = mono_clock::now();
   prealloc_left = alloc->allocate(
     need, min_alloc_size, need,
     0, &prealloc);
+  log_latency("allocator@_do_alloc_write",
+    l_bluestore_allocator_lat,
+    mono_clock::now() - start,
+    cct->_conf->bluestore_log_op_age);
   if (prealloc_left < 0 || prealloc_left < (int64_t)need) {
     derr << __func__ << " failed to allocate 0x" << std::hex << need
          << " allocated 0x " << (prealloc_left < 0 ? 0 : prealloc_left)

diff --git a/src/os/bluestore/BlueStore.h b/src/os/bluestore/BlueStore.h
index beac82f163a71c2a45aa05700392cfe2c4ce415b..f6c85b1d2190a5abe3ec4c7eea288909f4a07c2d 100644 (file)
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -211,6 +211,7 @@ enum {
   // allocation stats
   //****************************************
   l_bluestore_allocate_hist,
+  l_bluestore_allocator_lat,
   //****************************************
 
   // slow op counter