gian/ceph-mirror
1
0
Fork 0
mirror of https://github.com/ceph/ceph synced 2026-08-01 22:45:39 +00:00
Code Issues Actions 1 Packages Projects Releases Wiki Activity

os/bluesore,kv/rocksdbstore: dump KV txc ops when slow

Browse Source 
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>
This commit is contained in:
Igor Fedotov 2026-05-20 19:41:20 +03:00
parent cc1f41c8d2
commit 1b443af34c
5 changed files with 61 additions and 21 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
src/common/options/global.yaml.in
View File

@ -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

4
src/kv/KeyValueDB.h
View File

@ -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

68
src/kv/RocksDBStore.cc
View File

@ -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,

2
src/kv/RocksDBStore.h
View File

@ -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,

2
src/os/bluestore/BlueStore.cc
View File

@ -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) +