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 <igor.fedotov@croit.io>

diff --git a/src/common/options/global.yaml.in b/src/common/options/global.yaml.in
index 59317a8d6b21491a475558110b467cb74e4643aa..f87172458bbab339427d2e0914889c876169407e 100644 (file)
--- 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 381492fa1d7ba7d90807bc98b362ccd0e1b17ac8..8364a6683e3a1987873ac3bb36367bb121eeb813 100644 (file)
--- 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 6d9470306a147bfb68f80303e06abcebd7e6f6fa..0d7886ae6595b1200e5485da40b9cff73b09f063 100644 (file)
--- 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 << " <skipped>";
+    }
+    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<RocksDBTransactionImpl *>(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 2bd310aa44fcce614ab354b4f29bdc6d64df2e59..0dc36485f1d6aa552e34dc0dbfb3827d47d984aa 100644 (file)
--- 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 d2afa093e526f3a1d1401a33e0caf24e9e81b37e..fc06fe86183daf288685d8322312e9b2c494df07 100644 (file)
--- 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) +