diff --git a/src/common/options/global.yaml.in b/src/common/options/global.yaml.in index 59317a8d6b2..f87172458bb 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 381492fa1d7..8364a6683e3 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 6d9470306a1..0d7886ae659 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 2bd310aa44f..0dc36485f1d 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 d2afa093e52..fc06fe86183 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) +