tools: Skip backward time entries v2 (#1958)
* tools: Skip backward time entries in xfsslower
While using xfsslower on RHEL7 we occasionally get
following screwed up latencies:
# xfsslower
Tracing XFS operations slower than 1 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
13:25:03 git 3385 R 62 4704 18446744073708.55 tmp_pack_bDUbwZ
13:25:03 git 3385 S 0 0 3.05 tmp_idx_Kjb2bW
...
The reason for this is that on RHEL7 it's possible to get backward
timetamp with bpf_ktime_get_ns. This needs to be fixed, but meanwhile
this fix makes sure the latencies with backward times are skipped.
For the rest of the kernels this is just sanity fix with
possibly just single compare instruction overhead.
It's temporary workaround for #728.
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
* tools: Skip backward time entries in ext4dist
While using ext4dist on RHEL7 we occasionally get
following screwed up latencies:
# ext4dist
Tracing ext4 operation latency... Hit Ctrl-C to end.
^C
operation = write
usecs : count distribution
0 -> 1 : 1134529 |******** |
2 -> 3 : 2777582 |********************|
4 -> 7 : 688014 |**** |
8 -> 15 : 36160 | |
16 -> 31 : 698 | |
32 -> 63 : 6 | |
64 -> 127 : 15 | |
128 -> 255 : 7 | |
256 -> 511 : 1 | |
512 -> 1023 : 0 | |
1024 -> 2047 : 0 | |
2048 -> 4095 : 2 | |
4096 -> 8191 : 1 | |
8192 -> 16383 : 5 | |
16384 -> 32767 : 0 | |
32768 -> 65535 : 0 | |
9007199254740992 -> 18014398509481983 : 0 | |
18014398509481984 -> 36028797018963967 : 1 | |
The reason for this is that on RHEL7 it's possible to get backward
timestamp with bpf_ktime_get_ns. This needs to be fixed, but meanwhile
this fix makes sure the latencies with backward times are skipped.
For the rest of the kernels this is just sanity fix with
possibly just single compare instruction overhead.
It's temporary workaround for #728.
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
diff --git a/tools/xfsslower.py b/tools/xfsslower.py
index da70c57..c70721a 100755
--- a/tools/xfsslower.py
+++ b/tools/xfsslower.py
@@ -173,8 +173,15 @@
// calculate delta
u64 ts = bpf_ktime_get_ns();
- u64 delta_us = (ts - valp->ts) / 1000;
+ u64 delta_us = ts - valp->ts;
entryinfo.delete(&id);
+
+ // Skip entries with backwards time: temp workaround for #728
+ if ((s64) delta_us < 0)
+ return 0;
+
+ delta_us /= 1000;
+
if (FILTER_US)
return 0;