diff --git a/src/osdtrace.cc b/src/osdtrace.cc index 5335f2c..be0ff6b 100644 --- a/src/osdtrace.cc +++ b/src/osdtrace.cc @@ -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); } @@ -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); } diff --git a/tests/lib/verify-trace-output.sh b/tests/lib/verify-trace-output.sh index 40043df..02bd7bb 100644 --- a/tests/lib/verify-trace-output.sh +++ b/tests/lib/verify-trace-output.sh @@ -35,262 +35,13 @@ TRACE_EXPECTED_IO_SIZE=2097152 # _osdtrace_rows # # 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 -# -# 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..` 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 -# -# 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