Skip to content

osdtrace: trace replica subop writes in single mode #187

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
taodd wants to merge 1 commit into
base: osdtrace-single-mode-op-detail
Choose a base branch
from
Open

osdtrace: trace replica subop writes in single mode #187

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 4 additions & 1 deletion doc/man/8/osdtrace.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
79 changes: 79 additions & 0 deletions src/osdtrace.bpf.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
53 changes: 43 additions & 10 deletions src/osdtrace.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -85,7 +85,8 @@ std::map<std::string, int> 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 = {
Expand Down Expand Up @@ -201,14 +202,23 @@ 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"},
{"rm", "_M_ptr", "op", "px", "request", "data", "_len"},
{"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"},
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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 "
Expand Down Expand Up @@ -1122,7 +1154,7 @@ int parse_args(int argc, char **argv) {
case '?':
case 'h':
std::cout << "Usage: " << argv[0] << " [-s] [-l <milliseconds>] [-b] [-j] [-i <filename>] [-t <seconds>] [-a] [-p <pid1,pid2,...>] [--id <osd-id1,osd-id2,...>] [--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 <milliseconds> 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";
Expand Down Expand Up @@ -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},
Expand Down
Loading