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

Signed-off-by: Igor Fedotov <ifedotov@suse.com>
(cherry picked from commit 76c5993601e7fa3346a7958f6e8d2f4e68b07c9a)

diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index acd0b6102248ce90e9d08795e49d3327582c3607..c8239f1d9fd521d7929cc78087b69bf9a68e2f19 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
@@ -3881,6 +3882,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) {
@@ -3905,6 +3907,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) {
@@ -3929,6 +3932,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) {
@@ -3962,6 +3966,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) {
@@ -3979,6 +3984,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;
 }
 
@@ -8486,7 +8492,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;
@@ -8515,7 +8522,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;
 }
 
@@ -8607,7 +8615,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;
@@ -8802,7 +8811,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); }
   );
@@ -8951,7 +8961,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;
   }
@@ -8986,7 +8997,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;
 }
 
@@ -10141,12 +10153,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);
+    }
   );
 }
 
@@ -10652,9 +10666,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) {
@@ -10748,7 +10765,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();
     }
@@ -11076,8 +11094,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;
 }
 
@@ -12078,8 +12098,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;
     }
@@ -13546,11 +13567,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 91d3ee8c36b7dc52ff23731b431fe9c6c5581f85..972f41b36727e9088c584f4409b64629a314c30d 100644 (file)
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -2669,7 +2669,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);