osdtrace: don't report a latency for peers that don't exist - #194
Open
majianpeng wants to merge 1 commit into
Open
majianpeng wants to merge 1 commit into
majianpeng wants to merge 1 commit into
Conversation
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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Every replicated write to a size=2 pool was printed with a bogus second peer:
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
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.