Skip to content

osdtrace: trace replica subop writes in single mode - #187

Open
taodd wants to merge 1 commit into
osdtrace-single-mode-op-detailfrom
osdtrace-single-mode-subop
Open

taodd wants to merge 1 commit into
osdtrace-single-mode-op-detailfrom
osdtrace-single-mode-subop

Conversation

@taodd

@taodd taodd commented Aug 26, 2026

Copy link
Copy Markdown
Owner

Summary

Stacked on #186. Single mode traced only PrimaryLogPG::log_op_stats, which fires solely for client ops on the primary — replica write subops (MSG_OSD_REPOP) were invisible, although on a replicated pool they are two thirds of the write work. This adds a second lightweight probe so -s prints one line per replica subop write, with the same in-kernel -l threshold behavior:

osd 0 pg 1.18 subop_w size 4483 client 4126 tid 500 object benchmark_data_..._object499 subop_lat 4886
osd 1 pg 1.18 subop_w size 4483 client 4126 tid 500 object benchmark_data_..._object499 subop_lat 5575
osd 2 pg 1.18 op_w   size 4096 client 4126 tid 500 object benchmark_data_..._object499 osd_ops [set-alloc-hint,write] op_lat 6396

Anchor choice: repop_commit, not log_subop_stats

Both fire at essentially the same instant — in current Ceph, log_subop_stats is a static function whose only call site is the last statement of repop_commit. But a static single-caller function is inlined at -O2: it is absent from every embedded release DWARF JSON (checked quincy 17.2.6/el8, reef 18.2.4/el9, squid 19.2.0/el9) and only exists out-of-line on debug builds. ReplicatedBackend::repop_commit is invoked through the C_OSD_RepModifyCommit callback, so it cannot be inlined away, and is present in all embedded release JSONs. It also only ever handles MSG_OSD_REPOP, so no message-type filter is needed.

Changes

  • Varpaths: append recv_stamp and pg id (cast:MOSDRepOp → pgid.pgid.m_pool/m_seed, layout gdb-verified: MOSDRepOp::pgid declared directly at 0x1a0) to the repop_commit list — varids 175-177; 170-174 keep their positions so full mode's v1 program is untouched. 8/10 varid budget.
  • BPF: uprobe_repop_commit_v2, a standalone sibling of uprobe_log_op_stats_v2 — recv_stamp first, in-kernel -l gate, then owner/tid/payload/object-name/pg into a ringbuf event; no map state, no printk. Appended as the last program in the file since func_progid indices are positional in skeleton declaration order.
  • Userspace: attach-table entry (OP_SINGLE_PROBE, exact, v=2), print_single_op branch for subop_w lines (no osd_ops field — a repop carries a serialized ObjectStore transaction, not a decoded OSDOp vector), and subops are excluded from the size-range histograms (they measure client-visible latency and would count each client write once per replica).
  • Docs: -s help text and man page updated.

Verification (3-OSD vstart cluster, size-3 pool, tentacle dev build)

  • subop_w line count = exactly 2× the client op_w count (136,438 vs 68,218 over a bench run)
  • for any tid, the primary's op_w pairs with two replica subop_w lines on the same pg/object, with subop_lat < op_lat
  • -l 15: only above-threshold ops and subops print — including matched slow pairs (client op slow because its replica subop was slow)
  • histograms unchanged: entry count equals the 4K writes only (34,109), subops and deletes excluded
  • full-mode regression: 15 probes × 3 OSDs attach, identical output — now with live peers [(0, 7136), (2, 5906)] on the replicated cluster
  • probe body cost via bpftool stats: ~3.5 µs per subop event (debug build, contended laptop); -l fast path structurally identical to the validated log_op_stats_v2 gate

🤖 Generated with Claude Code

https://claude.ai/code/session_01SQMVEJezhKCMbVMWFpNi5B

Single mode traced only PrimaryLogPG::log_op_stats, which fires solely
for client ops on the primary -- replica write subops (MSG_OSD_REPOP)
were invisible, although on a replicated pool they are two thirds of
the write work.  Add a second lightweight probe so single mode prints
one line per replica subop write:

  osd 0 pg 1.18 subop_w size 4483 client 4126 tid 500 \
    object benchmark_data_..._object499 subop_lat 4886

Anchor: ReplicatedBackend::repop_commit, via a standalone v2 program
mirroring uprobe_log_op_stats_v2 (no map state, latency computed
in-kernel from the message recv_stamp, same -l threshold gate).
log_subop_stats was considered and rejected: it is a static function
with a single call site (the last statement of repop_commit itself),
inlined away on -O2 release builds -- it is absent from every embedded
release DWARF JSON (quincy/reef/squid), while repop_commit, invoked
through the C_OSD_RepModifyCommit callback, exists on all of them.

- Append recv_stamp and pg id (cast:MOSDRepOp pgid) varpaths to the
  repop_commit list (varids 175-177; 170-174 keep their positions, so
  full mode's v1 program is unaffected).
- uprobe_repop_commit_v2 is appended as the last program in the file:
  func_progid indices are positional in skeleton declaration order.
- Subop events are excluded from the single-mode size-range histograms:
  those measure client-visible latency, and replica subops would also
  count each client write once per replica.
- Reads of the new varids degrade gracefully with older DWARF JSON:
  no recv_stamp aborts the event (no latency without it), missing pg
  fields print as zeros.

Verified on a 3-OSD vstart cluster (size-3 pool, rados bench 4K
writes): subop_w line count is exactly 2x the client op_w count; for
any tid the primary's op_w pairs with two replica subop_w lines on the
same pg/object with subop_lat < op_lat; -l 15 prints only ops and
subops above threshold; histograms unchanged (client writes only);
full mode still attaches 15 probes per OSD with identical output.
Probe body cost measured via bpftool: ~3.5us per subop event.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant