os/bluestore: add more latency tracking perf counters into BlueFS

Signed-off-by: Igor Fedotov <igor.fedotov@croit.io>

diff --git a/src/os/bluestore/BlueFS.cc b/src/os/bluestore/BlueFS.cc
index 53284355132fdff4516ac719c9db0aa11bd80ce4..920739dec898878bee49e613a412a370143d6280 100644 (file)
--- a/src/os/bluestore/BlueFS.cc
+++ b/src/os/bluestore/BlueFS.cc
@@ -300,6 +300,10 @@ void BlueFS::_init_logger()
                    "auwb",
                    PerfCountersBuilder::PRIO_CRITICAL,
                    unit_t(UNIT_BYTES));
+  b.add_time_avg   (l_bluefs_read_random_lat, "read_random_lat",
+                    "Average bluefs read_random latency",
+                    "rdrt",
+                    PerfCountersBuilder::PRIO_INTERESTING);
   b.add_u64_counter(l_bluefs_read_random_count, "read_random_count",
                    "random read requests processed",
                    NULL,
@@ -338,6 +342,10 @@ void BlueFS::_init_logger()
                    "Bytes read from prefetch buffer in random read mode",
                    NULL,
                    PerfCountersBuilder::PRIO_USEFUL, unit_t(UNIT_BYTES));
+  b.add_time_avg   (l_bluefs_read_lat, "read_lat",
+                    "Average bluefs read latency",
+                    "rd_t",
+                    PerfCountersBuilder::PRIO_INTERESTING);
   b.add_u64_counter(l_bluefs_read_count, "read_count",
                    "buffered read requests processed",
                    NULL,
@@ -381,14 +389,30 @@ void BlueFS::_init_logger()
   b.add_u64_counter(l_bluefs_write_bytes, "write_bytes",
                    "Bytes written", NULL,
                    PerfCountersBuilder::PRIO_USEFUL, unit_t(UNIT_BYTES));
- b.add_time_avg     (l_bluefs_compaction_lat, "compact_lat",
+  b.add_time_avg   (l_bluefs_compaction_lat, "compact_lat",
                     "Average bluefs log compaction latency",
                     "c__t",
                     PerfCountersBuilder::PRIO_INTERESTING);
- b.add_time_avg     (l_bluefs_compaction_lock_lat, "compact_lock_lat",
+  b.add_time_avg   (l_bluefs_compaction_lock_lat, "compact_lock_lat",
                     "Average lock duration while compacting bluefs log",
                     "c_lt",
                     PerfCountersBuilder::PRIO_INTERESTING);
+  b.add_time_avg   (l_bluefs_fsync_lat, "fsync_lat",
+                    "Average bluefs fsync latency",
+                    "fs_t",
+                    PerfCountersBuilder::PRIO_INTERESTING);
+  b.add_time_avg   (l_bluefs_flush_lat, "flush_lat",
+                    "Average bluefs flush latency",
+                    "fl_t",
+                    PerfCountersBuilder::PRIO_INTERESTING);
+  b.add_time_avg   (l_bluefs_unlink_lat, "unlink_lat",
+                    "Average bluefs unlink latency",
+                    "unlt",
+                    PerfCountersBuilder::PRIO_INTERESTING);
+  b.add_time_avg   (l_bluefs_truncate_lat, "truncate_lat",
+                    "Average bluefs truncate latency",
+                    "trnt",
+                    PerfCountersBuilder::PRIO_INTERESTING);
   b.add_u64_counter(l_bluefs_alloc_shared_dev_fallbacks, "alloc_slow_fallback",
                    "Amount of allocations that required fallback to "
                     " slow/shared device",
@@ -2086,6 +2110,7 @@ int64_t BlueFS::_read_random(
   uint64_t len,          ///< [in] this many bytes
   char *out)             ///< [out] copy it here
 {
+  auto t0 = mono_clock::now();
   auto* buf = &h->buf;
 
   int64_t ret = 0;
@@ -2171,6 +2196,7 @@ int64_t BlueFS::_read_random(
            << " got 0x" << ret
            << std::dec  << dendl;
   --h->file->num_reading;
+  logger->tinc(l_bluefs_read_random_lat, mono_clock::now() - t0);
   return ret;
 }
 
@@ -2181,6 +2207,7 @@ int64_t BlueFS::_read(
   bufferlist *outbl,     ///< [out] optional: reference the result here
   char *out)             ///< [out] optional: or copy it here
 {
+  auto t0 = mono_clock::now();
   FileReaderBuffer *buf = &(h->buf);
 
   bool prefetch = !outbl && !out;
@@ -2302,6 +2329,7 @@ int64_t BlueFS::_read(
            << std::dec  << dendl;
   ceph_assert(!outbl || (int)outbl->length() == ret);
   --h->file->num_reading;
+  logger->tinc(l_bluefs_read_lat, mono_clock::now() - t0);
   return ret;
 }
 
@@ -3369,6 +3397,7 @@ void BlueFS::flush_range(FileWriter *h, uint64_t offset, uint64_t length)/*_WF*/
 
 int BlueFS::_flush_range_F(FileWriter *h, uint64_t offset, uint64_t length)
 {
+  auto t0 = mono_clock::now();
   ceph_assert(ceph_mutex_is_locked(h->lock));
   ceph_assert(h->file->num_readers.load() == 0);
   ceph_assert(h->file->fnode.ino > 1);
@@ -3424,6 +3453,7 @@ int BlueFS::_flush_range_F(FileWriter *h, uint64_t offset, uint64_t length)
   dout(20) << __func__ << " file now, unflushed " << h->file->fnode << dendl;
   int res = _flush_data(h, offset, length, buffered);
   vselector->add_usage(h->file->vselector_hint, h->file->fnode);
+  logger->tinc(l_bluefs_flush_lat, mono_clock::now() - t0);
   return res;
 }
 
@@ -3645,6 +3675,7 @@ uint64_t BlueFS::_flush_special(FileWriter *h)
 
 int BlueFS::truncate(FileWriter *h, uint64_t offset)/*_WF_L*/
 {
+  auto t0 = mono_clock::now();
   std::lock_guard hl(h->lock);
   dout(10) << __func__ << " 0x" << std::hex << offset << std::dec
            << " file " << h->file->fnode << dendl;
@@ -3683,11 +3714,13 @@ int BlueFS::truncate(FileWriter *h, uint64_t offset)/*_WF_L*/
   h->file->is_dirty = true;
   vselector->add_usage(h->file->vselector_hint, h->file->fnode.size);
   log.t.op_file_update_inc(h->file->fnode);
+  logger->tinc(l_bluefs_truncate_lat, mono_clock::now() - t0);
   return 0;
 }
 
 int BlueFS::fsync(FileWriter *h)/*_WF_WD_WLD_WLNF_WNF*/
 {
+  auto t0 = mono_clock::now();
   _maybe_check_vselector_LNF();
   std::unique_lock hl(h->lock);
   uint64_t old_dirty_seq = 0;
@@ -3715,7 +3748,7 @@ int BlueFS::fsync(FileWriter *h)/*_WF_WD_WLD_WLNF_WNF*/
     _flush_and_sync_log_LD(old_dirty_seq);
   }
   _maybe_compact_log_LNF_NF_LD_D();
-
+  logger->tinc(l_bluefs_fsync_lat, mono_clock::now() - t0);
   return 0;
 }
 
@@ -4357,6 +4390,7 @@ int BlueFS::readdir(std::string_view dirname, vector<string> *ls)/*_N*/
 
 int BlueFS::unlink(std::string_view dirname, std::string_view filename)/*_LND*/
 {
+  auto t0 = mono_clock::now();
   std::lock_guard ll(log.lock);
   std::lock_guard nl(nodes.lock);
   dout(10) << __func__ << " " << dirname << "/" << filename << dendl;
@@ -4381,6 +4415,8 @@ int BlueFS::unlink(std::string_view dirname, std::string_view filename)/*_LND*/
   dir->file_map.erase(string{filename});
   log.t.op_dir_unlink(dirname, filename);
   _drop_link_D(file);
+  logger->tinc(l_bluefs_unlink_lat, mono_clock::now() - t0);
+
   return 0;
 }
 

diff --git a/src/os/bluestore/BlueFS.h b/src/os/bluestore/BlueFS.h
index 9c5fb4981592c26accb4ae58fcc859a59307f002..f0493a758dab1c544bc5c040316e281f5a3093cb 100644 (file)
--- a/src/os/bluestore/BlueFS.h
+++ b/src/os/bluestore/BlueFS.h
@@ -46,6 +46,7 @@ enum {
   l_bluefs_main_alloc_unit,
   l_bluefs_db_alloc_unit,
   l_bluefs_wal_alloc_unit,
+  l_bluefs_read_random_lat,
   l_bluefs_read_random_count,
   l_bluefs_read_random_bytes,
   l_bluefs_read_random_disk_count,
@@ -55,6 +56,7 @@ enum {
   l_bluefs_read_random_disk_bytes_slow,
   l_bluefs_read_random_buffer_count,
   l_bluefs_read_random_buffer_bytes,
+  l_bluefs_read_lat,
   l_bluefs_read_count,
   l_bluefs_read_bytes,
   l_bluefs_read_disk_count,
@@ -69,6 +71,10 @@ enum {
   l_bluefs_write_bytes,
   l_bluefs_compaction_lat,
   l_bluefs_compaction_lock_lat,
+  l_bluefs_fsync_lat,
+  l_bluefs_flush_lat,
+  l_bluefs_unlink_lat,
+  l_bluefs_truncate_lat,
   l_bluefs_alloc_shared_dev_fallbacks,
   l_bluefs_alloc_shared_size_fallbacks,
   l_bluefs_read_zeros_candidate,
@@ -445,7 +451,6 @@ private:
   int _flush_data(FileWriter *h, uint64_t offset, uint64_t length, bool buffered);
   int _flush_F(FileWriter *h, bool force, bool *flushed = nullptr);
   uint64_t _flush_special(FileWriter *h);
-  int _fsync(FileWriter *h);
 
 #ifdef HAVE_LIBAIO
   void _claim_completed_aios(FileWriter *h, std::list<aio_t> *ls);