Skip to content

refactor(osdtrace): remove BlueStore sub-latencies from output #173

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

Merged
taodd merged 2 commits into from
Aug 13, 2026
Merged

refactor(osdtrace): remove BlueStore sub-latencies from output #173

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
803c4ad
refactor(osdtrace): remove BlueStore sub-latencies from output
taodd Aug 12, 2026
fdf8ff8
Merge branch 'main' into refactor/remove-bluestore-sub-latencies
taodd Aug 13, 2026
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
14 changes: 8 additions & 6 deletions src/osdtrace.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -597,15 +597,16 @@ void print_subop_w(osd_op_t &op, int osd_id) {
"object %s txn_ops %s "
"throttle_lat %lld recv_lat %lld dispatch_lat %lld "
"queue_lat %lld osd_lat %lld "
"bluestore_lat %lld (prepare %lld aio_wait %lld (aio_size %d) seq_wait %lld kv_commit %lld) "
"subop_lat %lld\n",
"bluestore_lat %lld "
"subop_lat %lld
",
osd_id, op.pg.m_pool, pgid.c_str(),
op.wb, op.client_id, op.req_id,
object_name.c_str(),
detail_ops.c_str(),
op.throttle_lat, op.recv_lat, op.dispatch_lat,
op.queue_lat, op.osd_lat,
op.bs_lat, op.bs_prepare_lat, op.bs_aio_wait_lat, op.aio_size, op.bs_pg_seq_lat, op.bs_kv_commit_lat,
op.bs_lat,
op.op_lat);
print_delayed_info(op);
}
Expand All @@ -623,15 +624,16 @@ void print_op_w(osd_op_t &op, int osd_id) {
"object %s osd_ops %s "
"throttle_lat %lld recv_lat %lld dispatch_lat %lld "
"queue_lat %lld osd_lat %lld peers [(%d, %lld), (%d, %lld)] "
"bluestore_lat %lld (prepare %lld aio_wait %lld (aio_size %d) seq_wait %lld kv_commit %lld) "
"op_lat %lld\n",
"bluestore_lat %lld "
"op_lat %lld
",
osd_id, op.pg.m_pool, pgid.c_str(),
op.wb, op.client_id, op.req_id,
object_name.c_str(),
detail_ops.c_str(),
op.throttle_lat, op.recv_lat, op.dispatch_lat,
op.queue_lat, op.osd_lat, op.peers[0].peer, op.peers[0].latency, op.peers[1].peer, op.peers[1].latency,
op.bs_lat, op.bs_prepare_lat, op.bs_aio_wait_lat, op.aio_size, op.bs_pg_seq_lat, op.bs_kv_commit_lat,
op.bs_lat,
op.op_lat);
print_delayed_info(op);
}
Expand Down
253 changes: 2 additions & 251 deletions tests/lib/verify-trace-output.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,262 +35,13 @@ TRACE_EXPECTED_IO_SIZE=2097152
# _osdtrace_rows <log>
#
# Stream typed, pipe-separated osdtrace data rows to stdout. The first
# field is the op-type discriminator (op_r / subop_w / op_w); the
# remaining fields are the op-type's full schema, in printf order.
#
# Schemas — note these are the *emitted row* layouts, which deliberately keep
# object/osd_ops last so the field-name mapping below stays stable. The three
# print_op_* functions in src/osdtrace.cc print object and osd_ops/txn_ops
# immediately after `tid`, ahead of the latency block, so the awk field
# indices do not run in row order:
#
# op_r | osd | pool | pg | size | client | tid
# | throttle_lat | recv_lat | dispatch_lat | queue_lat | osd_lat
# | bluestore_lat | op_lat | object | osd_ops
#
# subop_w | osd | pool | pg | size | client | tid
# | throttle_lat | recv_lat | dispatch_lat | queue_lat | osd_lat
# | bluestore_lat | prepare_lat | aio_wait_lat | seq_wait_lat
# | kv_commit_lat | subop_lat | object | txn_ops
#
# op_w | osd | pool | pg | size | client | tid
# | throttle_lat | recv_lat | dispatch_lat | queue_lat | osd_lat
# | peer0_id | peer0_lat | peer1_id | peer1_lat
# | bluestore_lat | prepare_lat | aio_wait_lat | seq_wait_lat
# | kv_commit_lat | op_lat | object | osd_ops
#
# The object field is "-" when the trace could not capture the object name
# (the relevant capture point was not reached, or the DWARF data predates
# object-name support). Whitespace, control bytes, and percent signs in
# captured names are percent-encoded so each object remains one field.
#
# Rejection of malformed/truncated rows is critical: a SIGKILL hitting
# osdtrace mid-printf can leave a row whose tail is the underflowed
# peer-latency token (`(-1, 18446743169577026)]`), and a naive `$NF + 0`
# verifier mistakes that for the total op_lat. This parser instead
# matches each op type by exact NF AND by literal field-name landmarks
# (e.g. `$28 == "op_lat"` for op_r, `$26 == "peers"` + `$43 == "op_lat"`
# for op_w). Truncated rows fail at least one landmark and are dropped.
# Same logic drops rows with the `[delayed%d ... ]` continuation tokens
# appended (their NF is inflated past the expected count).
_osdtrace_rows() {
# The "prev" buffer + END (no flush of prev) makes the LAST data row
# the parser would otherwise emit get dropped. Defense-in-depth on
# top of the NF/landmark check: if SIGKILL hits osdtrace mid-printf
# at a buffer-flush boundary (libc splitting a large stdio flush
# across multiple write() syscalls), the byte-truncation can land
# somewhere the strict NF/landmark check still happens to accept.
# Skipping the last emit closes that corner. Cost: one good row per
# trace, against thousands captured.
awk '
function num(s, _t) { _t = s; gsub(/[^0-9-]/, "", _t); return _t + 0 }
function flush_pending() { if (prev != "") { print prev; prev = "" } }

$1 == "osd" && $3 == "pg" && \
$2 ~ /^-?[0-9]+$/ && \
$4 ~ /^[0-9]+\.[0-9a-fA-F]+$/ {
split($4, pg, ".")
op = $5
candidate = ""
if (op == "op_r" && NF == 29 && \
$6 == "size" && $12 == "object" && $14 == "osd_ops" && \
$28 == "op_lat") {
candidate = sprintf("op_r|%d|%s|%s|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%s|%s", \
$2, pg[1], pg[2], \
$7, $9, $11, \
$17, $19, $21, $23, $25, \
$27, $29, $13, $15)
} else if (op == "subop_w" && NF == 39 && \
$12 == "object" && $14 == "txn_ops" && \
$26 == "bluestore_lat" && $28 == "(prepare" && \
$38 == "subop_lat") {
candidate = sprintf("subop_w|%d|%s|%s|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%s|%s", \
$2, pg[1], pg[2], \
$7, $9, $11, \
$17, $19, $21, $23, $25, \
$27, $29, $31, $35, num($37), $39, $13, $15)
} else if (op == "op_w" && NF == 44 && \
$12 == "object" && $14 == "osd_ops" && \
$26 == "peers" && $31 == "bluestore_lat" && \
$33 == "(prepare" && $43 == "op_lat") {
candidate = sprintf("op_w|%d|%s|%s|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%s|%s", \
$2, pg[1], pg[2], \
$7, $9, $11, \
$17, $19, $21, $23, $25, \
num($27), num($28), num($29), num($30), \
$32, $34, $36, $40, num($42), $44, $13, $15)
}
# else: row was truncated, has [delayed...] suffix, or printed
# an op type we do not parse. Dropped silently.
if (candidate != "") {
flush_pending()
prev = candidate
}
}
# END deliberately omitted: prev holds the last data row the
# parser would have emitted; not flushing it here drops it.
' "$1"
}


# _radostrace_rows <log>
#
# Stream pipe-separated radostrace data rows to stdout, one per line:
# pid|client|tid|pool|pg|acting|wr|size|latency|object
# Data rows start with a numeric PID (the traced process's PID). Predicate
# `$1 ~ /^[0-9]+$/ && NF >= 10` rejects the header line ("pid client … "),
# status messages, tool log noise, and — importantly — any truncated tail
# record left behind when SIGKILL hits radostrace mid-printf (after the
# latency field but before object_name). Numeric coercion on $8/$9
# guards against the same kind of partial-write artifact appearing in
# the size/latency fields.
_radostrace_rows() {
# Drop the last data row. SIGKILL/SIGTERM of the writer can leave
# the file's tail mid-printf (e.g. an `rbd_data.<hex>.<seq>` object
# name truncated to just `rbd`), and the NF >= 10 predicate is
# loose enough to admit those byte-truncated rows. Buffering the
# latest match in `prev` and not flushing it at END drops exactly
# the one potentially-malformed row; previously-completed write()
# syscalls already landed atomically, so every earlier match is
# safe. Cost: one good row per trace among thousands.
awk '
function flush_pending() { if (prev != "") { print prev; prev = "" } }
$1 ~ /^[0-9]+$/ && NF >= 10 {
flush_pending()
prev = $1 "|" $2 "|" $3 "|" $4 "|" $5 "|" $6 "|" $7 "|" \
($8 + 0) "|" ($9 + 0) "|" $10
}
# END deliberately omitted: prev holds the last data row; not
# flushing it here drops it.
' "$1"
}


# verify_osdtrace_output <log> <test_pool_id> <max_osd_id> <pg_num> <min_rows>
#
# The tight per-row loop is wrapped so that shell xtrace (set -x) is
# silenced during it: under CI the test scripts run with set -x for
# orchestration visibility, but tracing ~15 commands per row over tens of
# thousands of rows drowns the runner's log pipe and effectively hangs the
# job. xtrace state is restored before return so the caller keeps tracing.
verify_osdtrace_output() {
local _xtrace=0
case $- in *x*) _xtrace=1; set +x;; esac

_verify_osdtrace_output_impl "$@"
local rc=$?

(( _xtrace == 1 )) && set -x
return $rc
}

# Per-row invariants shared across all three op types:
# - osd_id within [0, max_osd_id]
# - total op_lat (or subop_lat) within TRACE_MAX_LATENCY_US
# Helpers read $row (associative array) and $max_osd_id from the caller's
# scope; bash dynamic-scoped locals make that work.
_osdtrace_check_common() {
if (( row[osd_id] < 0 || row[osd_id] > max_osd_id )); then
err "Found OSD id ${row[osd_id]} outside [0, $max_osd_id] (op=${row[op]} pool=${row[pool]} tid=${row[tid]})"
return 1
fi
if (( row[op_lat] > TRACE_MAX_LATENCY_US )); then
err "Found op_lat ${row[op_lat]} µs > $TRACE_MAX_LATENCY_US µs in osdtrace output (op=${row[op]} osd=${row[osd_id]} pool=${row[pool]} tid=${row[tid]})"
return 1
fi
}

# Strict invariant: every named sub-latency field must be <= total op_lat.
# A sub-latency exceeding the total signals an unsigned-underflow in the
# BPF timestamp subtraction (end < start), which has been seen on rare
# events; without this check the underflowed value just looks like a
# huge µs number and quietly poisons downstream analysis.
_osdtrace_check_sublatencies() {
local field
for field in "$@"; do
if (( row[$field] > row[op_lat] )); then
err "Sub-latency ${field}=${row[$field]} µs > op_lat=${row[op_lat]} µs (op=${row[op]} osd=${row[osd_id]} pool=${row[pool]} tid=${row[tid]})"
return 1
fi
done
}

# Optional per-peer check for op_w only. Peer slot is -1 when the pool's
# replication factor leaves that slot unused; the corresponding peer_lat
# is uninitialised garbage and must be skipped.
_osdtrace_check_peer() {
local id_field=$1 lat_field=$2
if (( row[$id_field] == -1 )); then
return 0
fi
if (( row[$id_field] < 0 || row[$id_field] > max_osd_id )); then
err "Peer OSD id ${row[$id_field]} outside [0, $max_osd_id] (op_w osd=${row[osd_id]} pool=${row[pool]} tid=${row[tid]})"
return 1
fi
if (( row[$lat_field] > row[op_lat] )); then
err "Peer latency ${lat_field}=${row[$lat_field]} µs > op_lat=${row[op_lat]} µs (op_w osd=${row[osd_id]} peer=${row[$id_field]} tid=${row[tid]})"
return 1
fi
}

_verify_osdtrace_output_impl() {
local log=$1
local test_pool_id=$2
local max_osd_id=$3
local pg_num=$4
local min_rows=$5

local pool_rows=0
local op_r_total=0 subop_w_total=0 op_w_total=0
local op_r_pool=0 subop_w_pool=0 op_w_pool=0
local named_objects=0
local -A row
local line op_type _
local pg_dec

# Per-op-type field lists, used to populate $row from the parser
# output and to enumerate sub-latency fields for the strict bound.
local -a OP_R_SUBLATS=(throttle_lat recv_lat dispatch_lat queue_lat osd_lat bluestore_lat)
local -a SUBOP_W_SUBLATS=(throttle_lat recv_lat dispatch_lat queue_lat osd_lat bluestore_lat prepare_lat aio_wait_lat seq_wait_lat kv_commit_lat)
local -a OP_W_SUBLATS=(throttle_lat recv_lat dispatch_lat queue_lat osd_lat bluestore_lat prepare_lat aio_wait_lat seq_wait_lat kv_commit_lat)

while IFS= read -r line; do
[ -z "$line" ] && continue
op_type=${line%%|*}
row=( [op]="$op_type" )

case "$op_type" in
op_r)
IFS='|' read -r _ row[osd_id] row[pool] row[pg] \
row[size] row[client] row[tid] \
row[throttle_lat] row[recv_lat] row[dispatch_lat] \
row[queue_lat] row[osd_lat] \
row[bluestore_lat] row[op_lat] row[object] \
row[detail_ops] <<< "$line"
op_r_total=$((op_r_total + 1))
_osdtrace_check_common || return 1
_osdtrace_check_sublatencies "${OP_R_SUBLATS[@]}" || return 1
;;
subop_w)
IFS='|' read -r _ row[osd_id] row[pool] row[pg] \
row[size] row[client] row[tid] \
row[throttle_lat] row[recv_lat] row[dispatch_lat] \
row[queue_lat] row[osd_lat] \
row[bluestore_lat] row[prepare_lat] row[aio_wait_lat] \
row[seq_wait_lat] row[kv_commit_lat] row[op_lat] \
row[object] row[detail_ops] <<< "$line"
subop_w_total=$((subop_w_total + 1))
_osdtrace_check_common || return 1
_osdtrace_check_sublatencies "${SUBOP_W_SUBLATS[@]}" || return 1
;;
op_w)
# field is the op-type discriminator (op_r / subop_w / op_w)
IFS='|' read -r _ row[osd_id] row[pool] row[pg] \
row[size] row[client] row[tid] \
row[throttle_lat] row[recv_lat] row[dispatch_lat] \
row[queue_lat] row[osd_lat] \
row[peer0_id] row[peer0_lat] row[peer1_id] row[peer1_lat] \
row[bluestore_lat] row[prepare_lat] row[aio_wait_lat] \
row[seq_wait_lat] row[kv_commit_lat] row[op_lat] \
row[bluestore_lat] row[op_lat] \
row[object] row[detail_ops] <<< "$line"
op_w_total=$((op_w_total + 1))
_osdtrace_check_common || return 1
Expand Down
Loading