From 2f01d2d6f4f00c44cfc0de86bf9ea2dc20df9fe9 Mon Sep 17 00:00:00 2001 From: Igor Fedotov Date: Fri, 3 May 2019 16:01:47 +0300 Subject: [PATCH] os/bluestore: fix origin reference in logging slow ops. Signed-off-by: Igor Fedotov (cherry picked from commit 76c5993601e7fa3346a7958f6e8d2f4e68b07c9a) --- src/os/bluestore/BlueStore.cc | 74 +++++++++++++++++++++++------------ src/os/bluestore/BlueStore.h | 3 +- 2 files changed, 50 insertions(+), 27 deletions(-) diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc index acd0b6102248c..c8239f1d9fd52 100644 --- 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 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 91d3ee8c36b7d..972f41b36727e 100644 --- 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 fn); -- 2.39.5