diff --git a/doc/man/8/osdtrace.rst b/doc/man/8/osdtrace.rst index 26941fa..bbdf161 100644 --- a/doc/man/8/osdtrace.rst +++ b/doc/man/8/osdtrace.rst @@ -33,7 +33,10 @@ OPTIONS -s - Single OP probe mode: log PrimaryLogPG::log_op_stats only (lower overhead). + Single OP probe mode (lower overhead): one lightweight probe per event + prints a per-op line for client ops (PrimaryLogPG::log_op_stats) and for + replica subop writes (ReplicatedBackend::repop_commit), plus exit-time + latency histograms for the client ops. The default mode is full tracing with the complete latency breakdown. -b diff --git a/src/osdtrace.bpf.c b/src/osdtrace.bpf.c index c28b67d..eba95ee 100644 --- a/src/osdtrace.bpf.c +++ b/src/osdtrace.bpf.c @@ -1048,3 +1048,82 @@ int uprobe_txc_add_transaction(struct pt_regs *ctx) return 0; } + +// Single-mode replica subop (MSG_OSD_REPOP) tracing. Standalone like +// uprobe_log_op_stats_v2: no map state, latency computed in-kernel from the +// message's recv_stamp, subject to the same LATENCY_THRESHOLD_NS gate. +// repop_commit runs on the replica right before the MOSDRepOpReply is sent +// and only ever handles MSG_OSD_REPOP, so no message-type filter is needed. +// +// Varid layout for ReplicatedBackend::repop_commit (base 170), declaration +// order of its varpath list in osdtrace.cc: +// +0 owner +1 tid +2 request data._len +3 poid-name len +4 poid-name ptr +// +5 recv_stamp +6 pg m_pool +7 pg m_seed +// Varids 5..7 may be absent when tracing with DWARF JSON exported before they +// were added; +5 aborts the event (no latency without it), +6/+7 degrade to +// zeroed fields. +// +// This program must stay the last SEC("uprobe") in the file: func_progid +// indices in osdtrace.cc are positional in skeleton declaration order. +SEC("uprobe") +int uprobe_repop_commit_v2(struct pt_regs *ctx) { + int base_varid = 170; + __u64 recv_stamp = 0; + if (read_hprobe_utime(ctx, base_varid + 5, &recv_stamp) != 0 || recv_stamp == 0) + return 0; + + __u64 reply_stamp = bpf_ktime_get_boot_ns(); + + if (LATENCY_THRESHOLD_NS > 0) { + __u64 op_lat_ns = 0; + if (recv_stamp > BOOTSTAMP_NS) { + __u64 recv_boot_ns = recv_stamp - BOOTSTAMP_NS; + if (reply_stamp > recv_boot_ns) + op_lat_ns = reply_stamp - recv_boot_ns; + } + if (op_lat_ns < LATENCY_THRESHOLD_NS) + return 0; + } + + __u64 owner = 0; + __u64 tid = 0; + read_hprobe_varfield(ctx, base_varid, &owner, sizeof(owner)); + if (read_hprobe_varfield(ctx, base_varid + 1, &tid, sizeof(tid)) != 0) + return 0; + + // bufferlist::_len is a 32-bit unsigned; read exactly 4 bytes. + __u32 len = 0; + if (read_hprobe_varfield(ctx, base_varid + 2, &len, sizeof(len)) != 0) + return 0; + + struct op_v *op = bpf_ringbuf_reserve(&rb, sizeof(struct op_v), 0); + if (op == NULL) + return 0; + *op = zero_op_v; + + op->owner = owner; + op->tid = tid; + op->pid = get_pid(); + op->reply_stamp = reply_stamp; + op->recv_stamp = recv_stamp; + op->op_type = MSG_OSD_REPOP; + op->wb = len; + + read_hprobe_varfield_opt(ctx, base_varid + 6, &op->m_pool, sizeof(op->m_pool)); + read_hprobe_varfield_opt(ctx, base_varid + 7, &op->m_seed, sizeof(op->m_seed)); + + __u64 name_len = 0; + __u64 str_addr = 0; + if (read_hprobe_varfield_opt(ctx, base_varid + 3, &name_len, sizeof(name_len)) == 0 && + read_hprobe_varfield_opt(ctx, base_varid + 4, &str_addr, sizeof(str_addr)) == 0 && + name_len > 0 && str_addr != 0) { + __u32 nlen = name_len; + if (nlen > OBJECT_NAME_LEN - 1) + nlen = OBJECT_NAME_LEN - 1; + bpf_probe_read_user(op->object_name, nlen & (OBJECT_NAME_LEN - 1), + (void *)str_addr); + } + + bpf_ringbuf_submit(op, 0); + return 0; +} diff --git a/src/osdtrace.cc b/src/osdtrace.cc index b2a9c82..6fa69d1 100644 --- a/src/osdtrace.cc +++ b/src/osdtrace.cc @@ -85,7 +85,8 @@ std::map func_progid = { {"ReplicatedBackend::repop_commit", 17}, {"OpRequest::mark_flag_point", 18}, {"BlueStore::log_latency_fn", 19}, - {"BlueStore::_txc_add_transaction", 20} + {"BlueStore::_txc_add_transaction", 20}, + {"ReplicatedBackend::repop_commit_v2", 21} }; DwarfParser::probes_t osd_probes = { @@ -201,6 +202,10 @@ DwarfParser::probes_t osd_probes = { {"ECBackend::submit_transaction", {{"reqid", "name", "_num"}, {"reqid", "tid"}}}, + // List order is ABI: varids 170..177 in declaration order, hardcoded in + // uprobe_repop_commit{,_v2}. The trailing three entries (recv_stamp and + // the pg id via cast:MOSDRepOp) exist for the single-mode v2 program; + // full mode's v1 reads only the first five. {"ReplicatedBackend::repop_commit", {{"rm", "_M_ptr", "op", "px", "reqid", "name", "_num"}, {"rm", "_M_ptr", "op", "px", "reqid", "tid"}, @@ -208,7 +213,12 @@ DwarfParser::probes_t osd_probes = { {"rm", "_M_ptr", "op", "px", "request", "cast:MOSDRepOp", "poid", "oid", "name", "_M_string_length"}, {"rm", "_M_ptr", "op", "px", "request", "cast:MOSDRepOp", - "poid", "oid", "name", "_M_dataplus", "_M_p"}}}, + "poid", "oid", "name", "_M_dataplus", "_M_p"}, + {"rm", "_M_ptr", "op", "px", "request", "recv_stamp"}, + {"rm", "_M_ptr", "op", "px", "request", "cast:MOSDRepOp", + "pgid", "pgid", "m_pool"}, + {"rm", "_M_ptr", "op", "px", "request", "cast:MOSDRepOp", + "pgid", "pgid", "m_seed"}}}, {"OpRequest::mark_flag_point", {{"flag"}, @@ -418,6 +428,11 @@ void handle_single(struct op_v *val, int osd_id) { return ; } print_single_op(val, osd_id); + // The histograms measure client-visible op latency; replica subops would + // both skew them and count each client write once per replica, so they get + // per-op lines only. + if (val->op_type == MSG_OSD_REPOP) + return; __u64 op_lat = (val->reply_stamp - (val->recv_stamp - bootstamp)); __u64 wb = val->wb; __u64 rb = val->rb; @@ -616,22 +631,39 @@ static bool detail_ops_indicate_write(const osd_op_t &op) { 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. +// Single-mode per-op line. Only fields the lightweight single-mode probes +// supply; 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); + + // Replica subop write (from uprobe_repop_commit_v2). A repop carries a + // serialized ObjectStore transaction, not a decoded OSDOp vector, so there + // is no osd_ops field; decoding it would need the full-mode + // _txc_add_transaction probe. + if (op.type == MSG_OSD_REPOP) { + printf("osd %d pg %lld.%s subop_w " + "size %d client %lld tid %lld " + "object %s " + "subop_lat %lld\n", + osd_id, op.pg.m_pool, pgid.c_str(), + op.wb, op.client_id, op.req_id, + object_name.c_str(), + op.op_lat); + return; + } + + // 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); std::string detail_ops = format_detail_ops(op, false); printf("osd %d pg %lld.%s %s " @@ -1122,7 +1154,7 @@ int parse_args(int argc, char **argv) { case '?': case 'h': std::cout << "Usage: " << argv[0] << " [-s] [-l ] [-b] [-j] [-i ] [-t ] [-a] [-p ] [--id ] [--skip-version-check] [--list] [--list-embedded]\n"; - std::cout << " -s Set probe mode to Single OP (logs PrimaryLogPG::log_op_stats only)\n"; + std::cout << " -s Set probe mode to Single OP (low overhead: per-op lines for client ops and replica subop writes)\n"; std::cout << " -l Set operation latency threshold to capture\n"; std::cout << " -b Set probe mode to Bluestore\n"; std::cout << " -j Export DWARF info to JSON file\n"; @@ -1603,6 +1635,7 @@ struct AttachEntry { static const AttachEntry ATTACH_LIST[] = { {"PrimaryLogPG::log_op_stats", OP_SINGLE_PROBE, /*exact=*/true, 2}, + {"ReplicatedBackend::repop_commit", OP_SINGLE_PROBE, /*exact=*/true, 2}, {"OSD::dequeue_op", OP_FULL_PROBE, false, 0}, {"PrimaryLogPG::execute_ctx", OP_FULL_PROBE, false, 0}, {"ReplicatedBackend::submit_transaction", OP_FULL_PROBE, false, 0},