tools: Skip backward time entries v2 (iovisor#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 iovisor#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 iovisor#728. Signed-off-by: Jiri Olsa <jolsa@kernel.org>
egggHang · Sep 2, 2018 · fe26ca9 · fe26ca9
1 parent b1508e8
commit fe26ca9
Show file tree

Hide file tree

Showing 2 changed files with 16 additions and 3 deletions.
diff --git a/tools/ext4dist.py b/tools/ext4dist.py
@@ -110,14 +110,20 @@
     if (tsp == 0) {
         return 0;   // missed start or filtered
     }
-    u64 delta = (bpf_ktime_get_ns() - *tsp) / FACTOR;
+    u64 delta = bpf_ktime_get_ns() - *tsp;
+    start.delete(&pid);
+
+    // Skip entries with backwards time: temp workaround for #728
+    if ((s64) delta < 0)
+        return 0;
+
+    delta /= FACTOR;
 
     // store as histogram
     dist_key_t key = {.slot = bpf_log2l(delta)};
     __builtin_memcpy(&key.op, op, sizeof(key.op));
     dist.increment(key);
 
-    start.delete(&pid);
     return 0;
 }
 

diff --git 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;