From 0c8f3d9fb9c2ad61d7a93d6de8580b746b70d19f Mon Sep 17 00:00:00 2001 From: Dongdong Tao Date: Wed, 26 Aug 2026 09:53:02 +0900 Subject: [PATCH] feat(osdtrace): print detailed per-op info in single mode Single mode (-s) previously emitted only exit-time latency histograms. Extend the single-probe uprobe_log_op_stats_v2 to capture and print one line per op with the target pg id, object name, decoded osd op list (including cls calls), client id, tid and total latency, while keeping the histograms: osd 0 pg 1.11 op_w size 4096 client 4446 tid 8 \ object benchmark_data_..._object7 \ osd_ops [set-alloc-hint,write] op_lat 1942 - Rework the PrimaryLogPG::log_op_stats varpath list: drop the unused inb/outb entries (both programs read them from PT_REGS_PARM3/4) and add pg, object-name and MOSDOp::ops chains via cast:MOSDOp, filling the 10-varid budget exactly. - Populate the new fields in uprobe_log_op_stats_v2 only after the -l threshold gate, keeping the in-kernel fast path unchanged (~670ns); the enriched body costs ~3.0us/op vs ~2.4us before (measured via bpftool prog stats on a vstart cluster). - Reads of the new varids degrade silently to zeroed fields when tracing with DWARF JSON exported before this change (read_hprobe_varfield_opt), instead of dropping events or spamming bpf_printk. - Classify read/write by decoded opcode mode bits, which labels zero-payload deletes and omap-only class methods correctly; fall back to wb>0 when detail ops are unavailable. - Teach resolve_type_name to strip typedef/cv wrappers and keep scanning CUs for a complete definition: MOSDOp is now a using-alias for the templated _mosdop::MOSDOp> living in a namespace the type cache does not descend into, so the first cached hit may be a typedef leading to a declaration-only DIE. - Harden fill_map_hprobes against varid budget/field capacity overflows in both osdtrace and radostrace. --- src/dwarf_parser.cc | 30 ++++++++++- src/dwarf_parser.h | 3 ++ src/osdtrace.bpf.c | 59 ++++++++++++++++++++- src/osdtrace.cc | 125 +++++++++++++++++++++++++++++++++++--------- src/radostrace.cc | 12 +++++ 5 files changed, 199 insertions(+), 30 deletions(-) diff --git a/src/dwarf_parser.cc b/src/dwarf_parser.cc index 9d6ae96..1ad7eba 100644 --- a/src/dwarf_parser.cc +++ b/src/dwarf_parser.cc @@ -101,21 +101,47 @@ Dwarf_Die *DwarfParser::resolve_typedecl(Dwarf_Die *type) { return NULL; } +static void strip_type_wrappers(DwarfParser *dp, Dwarf_Die *die); + +// Resolve a type name for a cast: varpath token. A candidate hit may be a +// typedef (e.g. `using MOSDOp = _mosdop::MOSDOp>` -- the +// class itself lives in a namespace the type cache does not descend into), +// and in a given CU the typedef may lead to a declaration-only DIE. Strip +// wrappers and keep scanning CUs until a complete definition turns up; +// fall back to the first (incomplete) hit only if no CU has the definition. Dwarf_Die *DwarfParser::resolve_type_name(const std::string& name) { const std::string candidates[] = { name, "struct " + name, "union " + name, "enum " + name}; + bool have_fallback = false; + Dwarf_Die fallback; for (auto &module : global_type_cache) { for (auto &cu : module.second) { for (const auto& candidate : candidates) { auto found = cu.second.find(candidate); - if (found != cu.second.end()) { - return &found->second; + if (found == cu.second.end()) + continue; + Dwarf_Die stripped = found->second; + strip_type_wrappers(this, &stripped); + if (!dwarf_hasattr(&stripped, DW_AT_declaration)) { + resolved_cast_type = stripped; + return &resolved_cast_type; + } + if (!have_fallback) { + fallback = stripped; + have_fallback = true; } } } } + if (have_fallback) { + // Declaration-only everywhere; return it and let the caller's + // resolve_typedecl path report the failure if it cannot complete it. + resolved_cast_type = fallback; + return &resolved_cast_type; + } + cerr << "Couldn't resolve type " << name << endl; return NULL; } diff --git a/src/dwarf_parser.h b/src/dwarf_parser.h index 78332f1..98bb4ec 100644 --- a/src/dwarf_parser.h +++ b/src/dwarf_parser.h @@ -78,6 +78,9 @@ class DwarfParser { bool has_loclist(); Dwarf_Die *resolve_typedecl(Dwarf_Die *); Dwarf_Die *resolve_type_name(const std::string&); + // Storage for resolve_type_name's result: the cached DIE is stripped of + // typedef/cv wrappers before being returned, so it cannot alias the cache. + Dwarf_Die resolved_cast_type; void request_type_size(const std::string&); int get_type_size(const std::string&, const std::string&) const; // Byte offset of a (possibly nested) member within a type, e.g. diff --git a/src/osdtrace.bpf.c b/src/osdtrace.bpf.c index 76f6edd..c28b67d 100644 --- a/src/osdtrace.bpf.c +++ b/src/osdtrace.bpf.c @@ -63,6 +63,21 @@ static __always_inline int read_hprobe_varfield(struct pt_regs *ctx, int varid, return -1; } +// Like read_hprobe_varfield but silent when the varid is absent, for +// optional fields that older DWARF JSON exports do not carry -- the +// per-invocation bpf_printk would otherwise fire on every traced op. +static __always_inline int read_hprobe_varfield_opt(struct pt_regs *ctx, int varid, void *dst, size_t size) { + struct VarField *vf = bpf_map_lookup_elem(&hprobes, &varid); + if (NULL == vf) + return -1; + __u64 v = fetch_register(ctx, vf->varloc.reg); + __u64 addr = fetch_var_member_addr(v, vf); + if (addr == 0) + return -1; + bpf_probe_read_user(dst, size, (void *)addr); + return 0; +} + static __always_inline int read_hprobe_utime(struct pt_regs *ctx, int varid, __u64 *nsec_dst) { struct VarField *vf = bpf_map_lookup_elem(&hprobes, &varid); if (NULL != vf) { @@ -521,11 +536,19 @@ int uprobe_log_op_stats(struct pt_regs *ctx) { return 0; } +// Varid layout for PrimaryLogPG::log_op_stats (base 90), in declaration +// order of its varpath list in osdtrace.cc: +// +0 owner +1 tid +2 recv_stamp +3 header.type +// +4 pg m_pool +5 pg m_seed +6 object-name len +7 object-name data ptr +// +8 MOSDOp::ops _M_start +9 _M_finish +// Varids 4..9 may be absent when tracing with DWARF JSON exported before +// they were added; their reads must degrade to zeroed fields, never drop +// the event. SEC("uprobe") int uprobe_log_op_stats_v2(struct pt_regs *ctx) { int base_varid = 90; __u64 recv_stamp = 0; - if (read_hprobe_utime(ctx, base_varid + 4, &recv_stamp) != 0 || recv_stamp == 0) { + if (read_hprobe_utime(ctx, base_varid + 2, &recv_stamp) != 0 || recv_stamp == 0) { return 0; } @@ -554,7 +577,7 @@ int uprobe_log_op_stats_v2(struct pt_regs *ctx) { } __u16 op_type = 0; - if (read_hprobe_varfield(ctx, base_varid + 5, &op_type, sizeof(op_type)) != 0) { + if (read_hprobe_varfield(ctx, base_varid + 3, &op_type, sizeof(op_type)) != 0) { return 0; } @@ -577,6 +600,38 @@ int uprobe_log_op_stats_v2(struct pt_regs *ctx) { op->recv_stamp = recv_stamp; op->op_type = op_type; + // Optional detail fields (pg, object name, decoded osd ops). These run + // only after the latency-threshold gate, so the -l fast path is + // unaffected. The MOSDOp casts are only valid for client ops. + if (op_type == MSG_OSD_OP) { + read_hprobe_varfield_opt(ctx, base_varid + 4, &op->m_pool, sizeof(op->m_pool)); + read_hprobe_varfield_opt(ctx, base_varid + 5, &op->m_seed, sizeof(op->m_seed)); + + __u64 name_len = 0; + __u64 str_addr = 0; + if (read_hprobe_varfield_opt(ctx, base_varid + 6, &name_len, sizeof(name_len)) == 0 && + read_hprobe_varfield_opt(ctx, base_varid + 7, &str_addr, sizeof(str_addr)) == 0 && + name_len > 0 && str_addr != 0) { + __u32 len = name_len; + if (len > OBJECT_NAME_LEN - 1) + len = OBJECT_NAME_LEN - 1; + bpf_probe_read_user(op->object_name, len & (OBJECT_NAME_LEN - 1), + (void *)str_addr); + } + + if (CEPH_OSD_OP_SIZE != 0) { + __u64 ops_start = 0; + if (read_hprobe_varfield_opt(ctx, base_varid + 8, &ops_start, + sizeof(ops_start)) == 0 && + ops_start != 0) { + __u64 ops_finish = 0; + if (read_hprobe_varfield_opt(ctx, base_varid + 9, &ops_finish, + sizeof(ops_finish)) == 0) + capture_decoded_osd_ops(op, ops_start, ops_finish); + } + } + } + bpf_ringbuf_submit(op, 0); return 0; } diff --git a/src/osdtrace.cc b/src/osdtrace.cc index b7f794a..b2a9c82 100644 --- a/src/osdtrace.cc +++ b/src/osdtrace.cc @@ -146,14 +146,26 @@ DwarfParser::probes_t osd_probes = { {"BlueStore::_txc_apply_kv", {{"txc", "state"}}}, + // List order is ABI: varids 90..99 in declaration order, hardcoded in + // uprobe_log_op_stats{,_v2}. inb/outb are intentionally absent -- both + // programs read them from PT_REGS_PARM3/4. The full varid budget of 10 + // is in use; adding an entry requires renumbering func_id. + // The cast:MOSDOp members (hobj/pgid/ops) are declared directly on + // MOSDOp -- the only case cast: resolves reliably -- and are only valid + // for client MSG_OSD_OP requests; the v2 program gates on header.type. + // (this->pg_id would be cheaper but find_class_member fails to resolve + // it through PrimaryLogPG's inheritance chain.) {"PrimaryLogPG::log_op_stats", {{"op", "reqid", "name", "_num"}, {"op", "reqid", "tid"}, - {"inb"}, - {"outb"}, {"op", "request", "recv_stamp"}, - //{"op", "request", "throttle_stamp"}, - {"op", "request", "header", "type"}}}, + {"op", "request", "header", "type"}, + {"op", "request", "cast:MOSDOp", "pgid", "pgid", "m_pool"}, + {"op", "request", "cast:MOSDOp", "pgid", "pgid", "m_seed"}, + {"op", "request", "cast:MOSDOp", "hobj", "oid", "name", "_M_string_length"}, + {"op", "request", "cast:MOSDOp", "hobj", "oid", "name", "_M_dataplus", "_M_p"}, + {"op", "request", "cast:MOSDOp", "ops", "_M_impl", "_M_start"}, + {"op", "request", "cast:MOSDOp", "ops", "_M_impl", "_M_finish"}}}, {"ReplicatedBackend::generate_subop", {{"reqid", "name", "_num"}, @@ -390,6 +402,8 @@ int index(int k) { return min(10, b - 2); } +void print_single_op(struct op_v *val, int osd_id); + void handle_single(struct op_v *val, int osd_id) { auto &wvecs = osd_wsrl[osd_id]; if(wvecs.empty()) { @@ -403,7 +417,8 @@ void handle_single(struct op_v *val, int osd_id) { if (val->recv_stamp == 0) {//TODO weird bug, occationaly, 1/10000 of the ops could have recv_stamp==0 return ; } - __u64 op_lat = (val->reply_stamp - (val->recv_stamp - bootstamp)); + print_single_op(val, osd_id); + __u64 op_lat = (val->reply_stamp - (val->recv_stamp - bootstamp)); __u64 wb = val->wb; __u64 rb = val->rb; int k, idx; @@ -566,6 +581,72 @@ std::string format_detail_ops(const osd_op_t& op, bool transaction_ops) { return out.str(); } +// Fields every op event carries regardless of probe mode; shared between +// generate_op (full mode) and print_single_op (single mode). +static void fill_op_identity(osd_op_t &op, const op_v *val) { + op.type = val->op_type; + op.wb = val->wb; + op.rb = val->rb; + op.client_id = val->owner; + op.req_id = val->tid; + op.pg.m_pool = val->m_pool; + op.pg.m_seed = val->m_seed; + op.object_name.assign(val->object_name, + strnlen(val->object_name, OBJECT_NAME_LEN)); + op.detail_ops_total = val->detail_ops_total; + op.detail_ops_unavailable = val->detail_ops_unavailable != 0; + for (__u32 i = 0; + i < val->detail_ops_captured && i < MAX_DETAIL_OPS; + ++i) { + op.detail_ops.push_back(val->detail_ops[i]); + op.cls_ops[i] = val->cls_ops[i]; + } +} + +// Classify by the decoded opcodes' mode bits. More reliable than wb > 0: +// an omap-only class method (rgw.bucket_prepare_op, ...) is a write with no +// payload. CACHE-mode ops mutate object state, so they count as writes. +static bool detail_ops_indicate_write(const osd_op_t &op) { + for (__u32 opcode : op.detail_ops) { + __u32 opmode = opcode & CEPH_OSD_OP_MODE; + if (opmode == CEPH_OSD_OP_MODE_WR || opmode == CEPH_OSD_OP_MODE_RMW || + opmode == CEPH_OSD_OP_MODE_CACHE) + return true; + } + return false; +} + +// Single-mode per-op line. Only fields the one log_op_stats probe supplies; +// the full-mode stage latencies (queue/osd/bluestore/peers) are omitted +// rather than printed as zeros. +void print_single_op(struct op_v *val, int osd_id) { + osd_op_t op = osd_op_t(); + fill_op_identity(op, val); + // Fall back to the payload heuristic when detail ops are unavailable + // (DWARF JSON exported before the pg/object/ops varpaths existed). + op.is_write = op.detail_ops.empty() ? (op.wb > 0) + : detail_ops_indicate_write(op); + op.op_lat = (val->reply_stamp - (val->recv_stamp - bootstamp)) / 1000; + + std::stringstream ss; + ss << std::hex << op.pg.m_seed; + std::string pgid(ss.str()); + std::string object_name = format_object_name(op.object_name); + std::string detail_ops = format_detail_ops(op, false); + + printf("osd %d pg %lld.%s %s " + "size %d client %lld tid %lld " + "object %s osd_ops %s " + "op_lat %lld\n", + osd_id, op.pg.m_pool, pgid.c_str(), + op.is_write ? "op_w" : "op_r", + op.is_write ? op.wb : op.rb, + op.client_id, op.req_id, + object_name.c_str(), + detail_ops.c_str(), + op.op_lat); +} + void print_op_r(osd_op_t &op, int osd_id) { std::stringstream ss; ss << std::hex << op.pg.m_seed; @@ -659,10 +740,7 @@ void timeout_handler(int signum) { osd_op_t generate_op(op_v *val) { osd_op_t op = osd_op_t(); - op.type = val->op_type; - - op.wb = val->wb; - op.rb = val->rb; + fill_op_identity(op, val); // wb is the request payload size reported by log_op_stats, not a write // indicator: a class method that only touches omap (rgw.bucket_prepare_op, @@ -674,23 +752,6 @@ osd_op_t generate_op(op_v *val) { op.is_write = val->op_type == MSG_OSD_REPOP || val->submit_transaction_stamp != 0 || val->wb > 0; - op.client_id = val->owner; - op.req_id = val->tid; - - op.pg.m_pool = val->m_pool; - op.pg.m_seed = val->m_seed; - - op.object_name.assign(val->object_name, - strnlen(val->object_name, OBJECT_NAME_LEN)); - op.detail_ops_total = val->detail_ops_total; - op.detail_ops_unavailable = val->detail_ops_unavailable != 0; - for (__u32 i = 0; - i < val->detail_ops_captured && i < MAX_DETAIL_OPS; - ++i) { - op.detail_ops.push_back(val->detail_ops[i]); - op.cls_ops[i] = val->cls_ops[i]; - } - __u64 recv_stamp = val->recv_stamp; if (val->throttle_stamp < val->recv_stamp) { //Due to recv_stamp bug https://tracker.ceph.com/issues/52739 @@ -1090,6 +1151,13 @@ void fill_map_hprobes(std::string mod_path, DwarfParser &dwarfparser, struct bpf for (auto x : func2vf) { std::string funcname = x.first; int key_idx = func_id[funcname]; + // func_id bases are spaced 10 apart; an 11th varpath would silently + // overwrite the next function's first varid. + if (x.second.size() > 10) { + cerr << "fill_map_hprobes: " << funcname << " has " << x.second.size() + << " varpaths, exceeding the varid budget of 10" << endl; + exit(1); + } for (auto vf : x.second) { struct VarField_Kernel vfk; vfk.varloc = vf.varloc; @@ -1098,6 +1166,11 @@ void fill_map_hprobes(std::string mod_path, DwarfParser &dwarfparser, struct bpf << vfk.varloc.reg << " offset " << vfk.varloc.offset << " stack " << vfk.varloc.stack << endl; vfk.size = vf.fields.size(); + if (vfk.size > (int)(sizeof(vfk.fields) / sizeof(vfk.fields[0]))) { + cerr << "fill_map_hprobes: " << funcname << " varpath has " << vfk.size + << " fields, exceeding VarField_Kernel capacity" << endl; + exit(1); + } for (int i = 0; i < vfk.size; ++i) { vfk.fields[i] = vf.fields[i]; } diff --git a/src/radostrace.cc b/src/radostrace.cc index 8082788..970ffa6 100644 --- a/src/radostrace.cc +++ b/src/radostrace.cc @@ -105,6 +105,13 @@ void fill_map_hprobes(std::string mod_path, DwarfParser &dwarfparser, struct bpf for (auto x : func2vf) { std::string funcname = x.first; int key_idx = func_id[funcname]; + // func_id bases are spaced 10 apart; an 11th varpath would silently + // overwrite the next function's first varid. + if (x.second.size() > 10) { + cerr << "fill_map_hprobes: " << funcname << " has " << x.second.size() + << " varpaths, exceeding the varid budget of 10" << endl; + exit(1); + } for (auto vf : x.second) { struct VarField_Kernel vfk; vfk.varloc = vf.varloc; @@ -113,6 +120,11 @@ void fill_map_hprobes(std::string mod_path, DwarfParser &dwarfparser, struct bpf << vfk.varloc.reg << " offset " << vfk.varloc.offset << " stack " << vfk.varloc.stack << endl; vfk.size = vf.fields.size(); + if (vfk.size > (int)(sizeof(vfk.fields) / sizeof(vfk.fields[0]))) { + cerr << "fill_map_hprobes: " << funcname << " varpath has " << vfk.size + << " fields, exceeding VarField_Kernel capacity" << endl; + exit(1); + } for (int i = 0; i < vfk.size; ++i) { vfk.fields[i] = vf.fields[i]; }