From 1b443af34c4e30ed757eb207c1ac8ebdca33c8c2 Mon Sep 17 00:00:00 2001 From: Igor Fedotov Date: Wed, 20 May 2026 19:41:20 +0300 Subject: [PATCH] os/bluesore,kv/rocksdbstore: dump KV txc ops when slow Depending on bluestore_log_op_verbose parameter one can see either short: 2026-05-20T19:45:05.792+0300 7f60980006c0 0 bluestore(/home/if/ceph.2/build/dev/osd0) log_latency_fn slow operation observed for _txc_committed_kv, latency = 0.004759922s, txc = 0x55c357bde900, txc bytes = 2756989, txc ios = 43, txc cost = 31566989, txc onodes = 1, DB ops = ' p:P, p:P, p:O, p:O, p:O, p:O, p:O, p:O, p:O, p:O, p:O, p:L, m:b, m:b, m:b, m:b, m:b, m:b, m:b, m:b, m:b, m:b, m:b, m:b', DB updates = 24, DB bytes = 8937, cost max = 95489052 on 2026-05-20T18:38:20.749901+0300, txc max = 100 on 2026-05-20T18:38:21.215016+0300 or verbose: 2026-05-20T18:42:01.551+0300 7f60980006c0 0 bluestore(/home/if/ceph.2/build/dev/osd0) log_latency_fn slow operation observed for _txc_committe d_kv, latency = 0.003735413s, txc = 0x55c356a35500, txc bytes = 2757061, txc ios = 44, txc cost = 32237061, txc onodes = 1, DB ops = ' PutCF( prefix = P key = 0x0000000000000499'.0000000032.00000000000000000005' value size = 185) PutCF( prefix = P key = 0x0000000000000499'._fastinfo' value size = 194) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F0000000078 value size = 453) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F0006000078 value size = 455) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F000C000078 value size = 455) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F0012000078 value size = 455) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F0018000078 value size = 455) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F001E000078 value size = 455) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F0024000078 value size = 455) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F002A000078 value size = 21) PutCF( prefix = O key = 0x7F8000000000000002DB7D25F2'!c!='0xFFFFFFFFFFFFFFFEFFFFFFFFFFFFFFFF6F value size = 388) MergeCF( prefix = b key = 0x0000000019080000 value size = 16) MergeCF( prefix = b key = 0x0000000019100000 value size = 16) MergeCF( prefix = b key = 0x0000000019180000 value size = 16) MergeCF( prefix = b key = 0x0000000019200000 value size = 16) MergeCF( prefix = b key = 0x0000000019280000 value size = 16) MergeCF( prefix = b key = 0x0000000019300000 value size = 16) MergeCF( prefix = T key = 0x0000000000000002 value size = 40)', DB updates = 18, DB bytes = 4668, cost max = 95489052 on 2026-05-20T18:38:20.74 9901+0300, txc max = 100 on 2026-05-20T18:38:21.215016+0300 operations list when BlueStore observes slow op on KV commit. Signed-off-by: Igor Fedotov --- src/common/options/global.yaml.in | 6 +++ src/kv/KeyValueDB.h | 4 ++ src/kv/RocksDBStore.cc | 68 +++++++++++++++++++++---------- src/kv/RocksDBStore.h | 2 + src/os/bluestore/BlueStore.cc | 2 + 5 files changed, 61 insertions(+), 21 deletions(-) diff --git a/src/common/options/global.yaml.in b/src/common/options/global.yaml.in index 59317a8d6b21..f87172458bba 100644 --- a/src/common/options/global.yaml.in +++ b/src/common/options/global.yaml.in @@ -5870,6 +5870,12 @@ options: desc: Log a collection list operation if it is slower than this age (seconds) default: 1_min with_legacy: true +- name: bluestore_log_op_verbose + type: bool + level: advanced + desc: Enable verbose dump of slow transaction(s) + default: false + with_legacy: true - name: bluestore_debug_enforce_settings type: str level: dev diff --git a/src/kv/KeyValueDB.h b/src/kv/KeyValueDB.h index 381492fa1d7b..8364a6683e3a 100644 --- a/src/kv/KeyValueDB.h +++ b/src/kv/KeyValueDB.h @@ -52,6 +52,10 @@ public: // total encoded data size virtual size_t get_size_bytes() const = 0; + // returns list of ops within txc, + // depending on the param it could be either short(false) or verbose(true) + virtual std::string get_summary_string(bool) const {return std::string();} + /// Set Keys void set( const std::string &prefix, ///< [in] Prefix for keys, or CF name diff --git a/src/kv/RocksDBStore.cc b/src/kv/RocksDBStore.cc index 6d9470306a14..0d7886ae6595 100644 --- a/src/kv/RocksDBStore.cc +++ b/src/kv/RocksDBStore.cc @@ -1549,20 +1549,19 @@ void RocksDBStore::get_statistics(Formatter *f) } struct RocksDBStore::RocksWBHandler: public rocksdb::WriteBatch::Handler { - RocksWBHandler(const RocksDBStore& db) : db(db) {} + RocksWBHandler(const RocksDBStore& db, bool verbose) + : db(db), verbose(verbose) {} const RocksDBStore& db; std::stringstream seen; int num_seen = 0; + bool verbose = true; - void dump(const char* op_name, + void dump(const char* op_name, const char* op_short, uint32_t column_family_id, const rocksdb::Slice& key_in, const rocksdb::Slice* value = nullptr) { string prefix; string key; - ssize_t size = value ? value->size() : -1; - seen << std::endl << op_name << "("; - if (column_family_id == 0) { db.split_key(key_in, &prefix, &key); } else { @@ -1571,46 +1570,64 @@ struct RocksDBStore::RocksWBHandler: public rocksdb::WriteBatch::Handler { prefix = it->second; key = key_in.ToString(); } - seen << " prefix = " << prefix; - seen << " key = " << pretty_binary_string(key); - if (size != -1) - seen << " value size = " << std::to_string(size); - seen << ")"; + if (verbose) { + ssize_t size = value ? value->size() : -1; + seen << std::endl << op_name << "("; + + seen << " prefix = " << prefix; + seen << " key = " << pretty_binary_string(key); + if (size != -1) + seen << " value size = " << std::to_string(size); + seen << ")"; + } else { + if (num_seen) + seen << ","; + seen << op_short << ":" << prefix; + } num_seen++; } void Put(const rocksdb::Slice& key, const rocksdb::Slice& value) override { - dump("Put", 0, key, &value); + dump("Put", " P", 0, key, &value); } rocksdb::Status PutCF(uint32_t column_family_id, const rocksdb::Slice& key, const rocksdb::Slice& value) override { - dump("PutCF", column_family_id, key, &value); + dump("PutCF", " p", column_family_id, key, &value); return rocksdb::Status::OK(); } void SingleDelete(const rocksdb::Slice& key) override { - dump("SingleDelete", 0, key); + dump("SingleDelete", "ds", 0, key); } rocksdb::Status SingleDeleteCF(uint32_t column_family_id, const rocksdb::Slice& key) override { - dump("SingleDeleteCF", column_family_id, key); + dump("SingleDeleteCF", "DS", column_family_id, key); return rocksdb::Status::OK(); } void Delete(const rocksdb::Slice& key) override { - dump("Delete", 0, key); + dump("Delete", " D", 0, key); } rocksdb::Status DeleteCF(uint32_t column_family_id, const rocksdb::Slice& key) override { - dump("DeleteCF", column_family_id, key); + dump("DeleteCF", " d", column_family_id, key); return rocksdb::Status::OK(); } void Merge(const rocksdb::Slice& key, const rocksdb::Slice& value) override { - dump("Merge", 0, key, &value); + dump("Merge", " M", 0, key, &value); } rocksdb::Status MergeCF(uint32_t column_family_id, const rocksdb::Slice& key, const rocksdb::Slice& value) override { - dump("MergeCF", column_family_id, key, &value); + dump("MergeCF", " m", column_family_id, key, &value); return rocksdb::Status::OK(); } - bool Continue() override { return num_seen < 50; } + bool Continue() override { + bool r = verbose ? num_seen < 128 : num_seen < 50; + if (!r) { + if (verbose) { + seen << std::endl; + } + seen << " "; + } + return r; + } }; int RocksDBStore::submit_common(rocksdb::WriteOptions& woptions, KeyValueDB::Transaction t) @@ -1626,13 +1643,13 @@ int RocksDBStore::submit_common(rocksdb::WriteOptions& woptions, KeyValueDB::Tra static_cast(t.get()); woptions.disableWAL = disableWAL; lgeneric_subdout(cct, rocksdb, 30) << __func__; - RocksWBHandler bat_txc(*this); + RocksWBHandler bat_txc(*this, true); _t->bat.Iterate(&bat_txc); *_dout << " Rocksdb transaction: " << bat_txc.seen.str() << dendl; rocksdb::Status s = db->Write(woptions, &_t->bat); if (!s.ok()) { - RocksWBHandler rocks_txc(*this); + RocksWBHandler rocks_txc(*this, true); _t->bat.Iterate(&rocks_txc); derr << __func__ << " error: " << s.ToString() << " code = " << s.code() << " Rocksdb transaction: " << rocks_txc.seen.str() << dendl; @@ -1715,6 +1732,15 @@ void RocksDBStore::RocksDBTransactionImpl::put_bat( } } +string RocksDBStore::RocksDBTransactionImpl::get_summary_string( + bool verbose) const +{ + ceph_assert(db); + RocksWBHandler bat_txc(*db, verbose); + bat.Iterate(&bat_txc); + return bat_txc.seen.str(); +} + void RocksDBStore::RocksDBTransactionImpl::set( const string &prefix, const string &k, diff --git a/src/kv/RocksDBStore.h b/src/kv/RocksDBStore.h index 2bd310aa44fc..0dc36485f1d6 100644 --- a/src/kv/RocksDBStore.h +++ b/src/kv/RocksDBStore.h @@ -328,6 +328,7 @@ public: rocksdb::ColumnFamilyHandle *cf, const std::string &k, const ceph::bufferlist &to_set_bl); + public: size_t get_count() const override { return bat.Count(); @@ -335,6 +336,7 @@ public: size_t get_size_bytes() const override { return bat.GetDataSize(); } + std::string get_summary_string(bool verbose) const override; void set( const std::string &prefix, const std::string &k, diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc index d2afa093e526..fc06fe86183d 100644 --- a/src/os/bluestore/BlueStore.cc +++ b/src/os/bluestore/BlueStore.cc @@ -15014,11 +15014,13 @@ void BlueStore::_txc_committed_kv(TransContext *txc) mono_clock::now() - txc->start, cct->_conf->bluestore_log_op_age, [&](auto lat) { + bool v = cct->_conf->bluestore_log_op_verbose; return ", txc = " + stringify(txc) + ", txc bytes = " + stringify(txc->bytes) + ", txc ios = " + stringify(txc->ios) + ", txc cost = " + stringify(txc->cost) + ", txc onodes = " + stringify(txc->onodes.size()) + + ", DB ops = '" + stringify(txc->t->get_summary_string(v)) + "'" ", DB updates = " + stringify(txc->t->get_count()) + ", DB bytes = " + stringify(txc->t->get_size_bytes()) + ", cost max = " + stringify(throttle.bytes_observed_max) + -- 2.47.3