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]; }