Skip to content

osdtrace: don't report a latency for peers that don't exist - #194

Open
majianpeng wants to merge 1 commit into
taodd:mainfrom
majianpeng:fix/osdtrace-peer-latency-underflow
Open

majianpeng wants to merge 1 commit into
taodd:mainfrom
majianpeng:fix/osdtrace-peer-latency-underflow

Conversation

@majianpeng

Copy link
Copy Markdown

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.

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.
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