os/bluestore: fix origin reference in logging slow ops.

Signed-off-by: Igor Fedotov <ifedotov@suse.com>

diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index b623eeb4cc88b6e7fe1c3fcf06003beedc908b30..25b333f9f8151e0dc6619659e9d7319acafe872b 100644 (file)
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -132,31 +132,32 @@ const string BLUESTORE_GLOBAL_STATFS_KEY = "bluestore_statfs";
 
 // FIXME minor: make a BlueStore method once we have effecient way to
 // map idx to counter nickname
-#define LOG_LATENCY_I(logger, cct, idx, v, info) { \
+#define LOG_LATENCY_I(logger, cct, name, idx, v, info) { \
   ceph::timespan lat = v; \
   logger->tinc(idx, lat); \
   if (cct->_conf->bluestore_log_op_age > 0.0 && \
       lat >= make_timespan(cct->_conf->bluestore_log_op_age)) { \
-    dout(0) << __func__ << " slow operation observed for " #idx \
+    dout(0) << __func__ << " slow operation observed for " << name \
       << ", latency = " << lat \
       << info \
       << dendl; \
   } \
 }
 
-#define LOG_LATENCY_FN(logger, cct, idx, v, fn) { \
+#define LOG_LATENCY_FN(logger, cct, name, idx, v, fn) { \
   ceph::timespan lat = v; \
   logger->tinc(idx, lat); \
   if (cct->_conf->bluestore_log_op_age > 0.0 && \
       lat >= make_timespan(cct->_conf->bluestore_log_op_age)) { \
-    dout(0) << __func__ << " slow operation observed for " #idx \
+    dout(0) << __func__ << " slow operation observed for " << name \
       << ", latency = " << lat \
       << fn(lat) \
       << dendl; \
   } \
 }
 
-#define LOG_LATENCY(logger, cct, idx, v) LOG_LATENCY_I(logger, cct, idx, v, "")
+#define LOG_LATENCY(logger, cct, name, idx, v) \
+  LOG_LATENCY_I(logger, cct, name, idx, v, "")
 
 /*
  * string encoding in the key
@@ -3773,6 +3774,7 @@ int BlueStore::OmapIteratorImpl::seek_to_first()
     it = KeyValueDB::Iterator();
   }
   c->store->log_latency_fn(
+    __func__,
     l_bluestore_omap_seek_to_first_lat,
     mono_clock::now() - start1,
     [&] (const ceph::timespan& lat) {
@@ -3797,6 +3799,7 @@ int BlueStore::OmapIteratorImpl::upper_bound(const string& after)
     it = KeyValueDB::Iterator();
   }
   c->store->log_latency_fn(
+    __func__,
     l_bluestore_omap_upper_bound_lat,
     mono_clock::now() - start1,
     [&] (const ceph::timespan& lat) {
@@ -3821,6 +3824,7 @@ int BlueStore::OmapIteratorImpl::lower_bound(const string& to)
     it = KeyValueDB::Iterator();
   }
   c->store->log_latency_fn(
+    __func__,
     l_bluestore_omap_lower_bound_lat,
     mono_clock::now() - start1,
     [&] (const ceph::timespan& lat) {
@@ -3854,6 +3858,7 @@ int BlueStore::OmapIteratorImpl::next()
     r = 0;
   }
   c->store->log_latency_fn(
+    __func__,
     l_bluestore_omap_next_lat,
     mono_clock::now() - start1,
     [&] (const ceph::timespan& lat) {
@@ -3871,6 +3876,7 @@ string BlueStore::OmapIteratorImpl::key()
   string db_key = it->raw_key().second;
   string user_key;
   decode_omap_key(db_key, &user_key);
+
   return user_key;
 }
 
@@ -8383,7 +8389,8 @@ int BlueStore::read(
     RWLock::RLocker l(c->lock);
     auto start1 = mono_clock::now();
     OnodeRef o = c->get_onode(oid, false);
-    LOG_LATENCY(logger, cct, l_bluestore_read_onode_meta_lat, mono_clock::now() - start1);
+    LOG_LATENCY(logger, cct, "get_onode@read",
+      l_bluestore_read_onode_meta_lat, mono_clock::now() - start1);
     if (!o || !o->exists) {
       r = -ENOENT;
       goto out;
@@ -8412,7 +8419,8 @@ int BlueStore::read(
   dout(10) << __func__ << " " << cid << " " << oid
           << " 0x" << std::hex << offset << "~" << length << std::dec
           << " = " << r << dendl;
-  LOG_LATENCY(logger, cct, l_bluestore_read_lat, mono_clock::now() - start);
+  LOG_LATENCY(logger, cct, __func__,
+    l_bluestore_read_lat, mono_clock::now() - start);
   return r;
 }
 
@@ -8504,7 +8512,8 @@ int BlueStore::_do_read(
 
   auto start = mono_clock::now();
   o->extent_map.fault_range(db, offset, length);
-  LOG_LATENCY(logger, cct, l_bluestore_read_onode_meta_lat, mono_clock::now() - start);
+  LOG_LATENCY(logger, cct, __func__,
+    l_bluestore_read_onode_meta_lat, mono_clock::now() - start);
   _dump_onode<30>(cct, *o);
 
   ready_regions_t ready_regions;
@@ -8699,7 +8708,8 @@ int BlueStore::_do_read(
       return -EIO;
     }
   }
-  LOG_LATENCY_FN(logger, cct, l_bluestore_read_wait_aio_lat,
+  LOG_LATENCY_FN(logger, cct, __func__,
+    l_bluestore_read_wait_aio_lat,
     mono_clock::now() - start,
     [&](auto lat) { return ", num_ios = " + stringify(num_ios); }
   );
@@ -8848,7 +8858,8 @@ int BlueStore::_verify_csum(OnodeRef& o,
       derr << __func__ << " failed with exit code: " << cpp_strerror(r) << dendl;
     }
   }
-  LOG_LATENCY(logger, cct, l_bluestore_csum_lat, mono_clock::now() - start);
+  LOG_LATENCY(logger, cct, __func__,
+    l_bluestore_csum_lat, mono_clock::now() - start);
   if (cct->_conf->bluestore_ignore_data_csum) {
     return 0;
   }
@@ -8883,7 +8894,8 @@ int BlueStore::_decompress(bufferlist& source, bufferlist* result)
       r = -EIO;
     }
   }
-  LOG_LATENCY(logger, cct, l_bluestore_decompress_lat, mono_clock::now() - start);
+  LOG_LATENCY(logger, cct, __func__,
+    l_bluestore_decompress_lat, mono_clock::now() - start);
   return r;
 }
 
@@ -10074,12 +10086,14 @@ void BlueStore::_txc_committed_kv(TransContext *txc)
     }
   }
   txc->log_state_latency(logger, l_bluestore_state_kv_committing_lat);
-  LOG_LATENCY_FN(logger, cct, 
-              l_bluestore_commit_lat,
-              ceph::make_timespan(ceph_clock_now() - txc->start),
-             [&](auto lat) {
-               return ", txc = " + stringify(txc);
-              }
+  LOG_LATENCY_FN(logger,
+    cct,
+    __func__,
+    l_bluestore_commit_lat,
+    ceph::make_timespan(ceph_clock_now() - txc->start),
+    [&](auto lat) {
+      return ", txc = " + stringify(txc);
+    }
   );
 }
 
@@ -10585,9 +10599,12 @@ void BlueStore::_kv_sync_thread()
          << " in " << dur
          << " (" << dur_flush << " flush + " << dur_kv << " kv commit)"
          << dendl;
-       LOG_LATENCY(logger, cct, l_bluestore_kv_flush_lat, dur_flush);
-       LOG_LATENCY(logger, cct, l_bluestore_kv_commit_lat, dur_kv);
-       LOG_LATENCY(logger, cct, l_bluestore_kv_sync_lat, dur);
+       LOG_LATENCY(logger, cct, "kv_flush",
+         l_bluestore_kv_flush_lat, dur_flush);
+       LOG_LATENCY(logger, cct, "kv_commit",
+         l_bluestore_kv_commit_lat, dur_kv);
+       LOG_LATENCY(logger, cct, "kv_sync",
+         l_bluestore_kv_sync_lat, dur);
       }
 
       if (bluefs) {
@@ -10681,7 +10698,8 @@ void BlueStore::_kv_finalize_thread()
       logger->set(l_bluestore_fragmentation,
          (uint64_t)(alloc->get_fragmentation(min_alloc_size) * 1000));
 
-      LOG_LATENCY(logger, cct, l_bluestore_kv_final_lat, mono_clock::now() - start);
+      LOG_LATENCY(logger, cct, "kv_final",
+       l_bluestore_kv_final_lat, mono_clock::now() - start);
 
       l.lock();
     }
@@ -11009,8 +11027,10 @@ int BlueStore::queue_transactions(
     }
   }
 
-  LOG_LATENCY(logger, cct, l_bluestore_submit_lat, mono_clock::now() - start);
-  LOG_LATENCY(logger, cct, l_bluestore_throttle_lat, tend - tstart);
+  LOG_LATENCY(logger, cct, "submit_transact",
+    l_bluestore_submit_lat, mono_clock::now() - start);
+  LOG_LATENCY(logger, cct, "throttle_transact",
+    l_bluestore_throttle_lat, tend - tstart);
   return 0;
 }
 
@@ -12011,8 +12031,9 @@ int BlueStore::_do_alloc_write(
        logger->inc(l_bluestore_compress_rejected_count);
        need += wi.blob_length;
       }
-      LOG_LATENCY(logger, cct, l_bluestore_compress_lat,
-                  mono_clock::now() - start);
+      LOG_LATENCY(logger, cct, "compress@_do_alloc_write",
+       l_bluestore_compress_lat,
+        mono_clock::now() - start);
     } else {
       need += wi.blob_length;
     }
@@ -13479,11 +13500,12 @@ int BlueStore::_merge_collection(
 }
 
 void BlueStore::log_latency_fn(
+  const char* name,
   int idx,
   const ceph::timespan& l,
   std::function<string (const ceph::timespan& lat)> fn)
 {
-  LOG_LATENCY_FN(logger, cct, idx, l, fn);
+  LOG_LATENCY_FN(logger, cct, name, idx, l, fn);
 }
 
 

diff --git a/src/os/bluestore/BlueStore.h b/src/os/bluestore/BlueStore.h
index b74a873cd5241982b8c38ba2cc3c6330ac055497..536b5513a9a45babbc3b06ea39d65300ff401dc1 100644 (file)
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -2680,7 +2680,8 @@ public:
     uint64_t size,
     PExtentVector* extents);
 
-  void log_latency_fn(int idx,
+  void log_latency_fn(const char* name,
+                     int idx,
                      const ceph::timespan& lat,
                      std::function<string (const ceph::timespan& lat)> fn);