From c06e279fdf506d9581c4b408de0a317cc16b5aba Mon Sep 17 00:00:00 2001 From: majianpeng Date: Mon, 14 Sep 2026 17:13:00 +0800 Subject: [PATCH] osdtrace: don't report a latency for peers that don't exist Every replicated write to a size=2 pool was printed with a bogus second peer: osd 0 pg 2.3e op_w size 4096 client 15850 tid 287231121 object ... osd_ops [write] ... osd_lat 358 peers [(3, 735), (-1, 18446372483103698)] peer1/peer2 are initialised to -1 in uprobe_enqueue_op and only overwritten by uprobe_generate_subop, which assigns them in subop order: the first subop sets peer1, the second sets peer2. A size=2 pool issues a single subop per op, so peer2 keeps its -1 and recv_stamp2 is never written -- uprobe_do_repop_reply only fills it when the replying osd matches peer2. generate_op() nevertheless pushed both entries unconditionally, so for peer2 it computed (val->pi.recv_stamp2 - val->pi.sent_stamp) / 1000 with recv_stamp2 == 0 and sent_stamp == bpf_ktime_get_boot_ns(). Both are __u64, so the subtraction underflows and wraps to (2^64 - sent_stamp), i.e. values around 1.8e16 us. On the reproduction host (uptime 371590 s == ~4.3 days) it printed 18446372483103698 us, and it appeared on 2037 of 2037 traced op_w lines, so every single write was affected. Emit an entry only when the peer actually exists (peer != -1) and its reply has been observed (recv_stamp != 0), and clamp the delta so that a stamp which is not strictly newer than sent_stamp cannot underflow either. print_op_w() additionally indexed op.peers[0] and op.peers[1] unconditionally, which only worked because exactly two entries were always pushed; it would read out of bounds once the list became variable length. Format the list from the vector instead, so 0, 1 or 2 peers all print correctly; the two-peer output is byte-for-byte identical to before. Verified on Kylin V11, osd.0, fio 4k randwrite iodepth=32: size=2 pool: 2037/2037 op_w lines carried a (-1, ~1.8e16) entry before, 0 of 4415 after, now e.g. "peers [(1, 707)]". size=3 pool: 49390 of 53969 op_w lines still report both peers, e.g. "peers [(1, 337), (3, 351)]", and 0 lines contain -1. --- src/osdtrace.cc | 37 +++++++++++++++++++++++++++++++++---- 1 file changed, 33 insertions(+), 4 deletions(-) diff --git a/src/osdtrace.cc b/src/osdtrace.cc index f77f7e8..0e2f93e 100644 --- a/src/osdtrace.cc +++ b/src/osdtrace.cc @@ -622,6 +622,19 @@ void print_subop_w(osd_op_t &op, int osd_id) { print_delayed_info(op); } +// A replicated op only talks to (pool replica count - 1) peers, so the list can +// hold 0, 1 or 2 entries -- never assume two of them exist. +static std::string format_peers(const osd_op_t &op) { + std::string s; + for (size_t i = 0; i < op.peers.size(); ++i) { + if (i) + s += ", "; + s += "(" + std::to_string(op.peers[i].peer) + ", " + + std::to_string(op.peers[i].latency) + ")"; + } + return s; +} + void print_op_w(osd_op_t &op, int osd_id) { std::stringstream ss; @@ -629,12 +642,13 @@ void print_op_w(osd_op_t &op, int osd_id) { std::string pgid(ss.str()); std::string object_name = format_object_name(op.object_name); std::string detail_ops = format_detail_ops(op, false); + std::string peers_str = format_peers(op); printf("osd %d pg %lld.%s op_w " "size %d client %lld tid %lld " "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)] " + "queue_lat %lld osd_lat %lld peers [%s] " "bluestore_lat %lld " "op_lat %lld\n", osd_id, op.pg.m_pool, pgid.c_str(), @@ -642,7 +656,7 @@ void print_op_w(osd_op_t &op, int osd_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.queue_lat, op.osd_lat, peers_str.c_str(), op.bs_lat, op.op_lat); print_delayed_info(op); @@ -740,8 +754,23 @@ osd_op_t generate_op(op_v *val) { op.delayed_strs.push_back(std::string(val->di.delays[i])); } if (op.type == MSG_OSD_OP) { - op.peers.push_back(peer_lat(val->pi.peer1, (val->pi.recv_stamp1 - val->pi.sent_stamp)/1000)); - op.peers.push_back(peer_lat(val->pi.peer2, (val->pi.recv_stamp2 - val->pi.sent_stamp)/1000)); + // uprobe_generate_subop assigns peers in order: the first subop sets peer1, + // the second sets peer2, and uprobe_do_repop_reply only fills the matching + // recv_stamp. A size=2 pool generates a single subop, so peer2 keeps its -1 + // initialisation and recv_stamp2 is never written. Computing + // (recv_stamp2 - sent_stamp) from that 0 underflows the unsigned __u64 and + // reported a bogus ~1.8e16 us latency for peer -1. Emit an entry only for a + // peer that exists and whose reply has actually been observed. + if (val->pi.peer1 != -1 && val->pi.recv_stamp1 != 0) + op.peers.push_back(peer_lat( + val->pi.peer1, val->pi.recv_stamp1 > val->pi.sent_stamp + ? (val->pi.recv_stamp1 - val->pi.sent_stamp) / 1000 + : 0)); + if (val->pi.peer2 != -1 && val->pi.recv_stamp2 != 0) + op.peers.push_back(peer_lat( + val->pi.peer2, val->pi.recv_stamp2 > val->pi.sent_stamp + ? (val->pi.recv_stamp2 - val->pi.sent_stamp) / 1000 + : 0)); } //bluestore level op.aio_size = val->aio_size;