In some trace log, there're unstable timestamp breaking temporal
ordering of trace records. For example:
kvm_run_exit -0.015 pid=3289596 cpu_index=0x0 reason=0x6
kvm_vm_ioctl -0.020 pid=3289596 type=0xffffffffc008ae67 arg=0x7ffeefb5aa60
kvm_vm_ioctl -0.021 pid=3289596 type=0xffffffffc008ae67 arg=0x7ffeefb5aa60
Negative delta intervals tend to get drowned in the massive trace logs,
and an unstable timestamp can corrupt the calculation of intervals
between two events adjacent to it.
Therefore, mark the outputs with unstable timestamps as WARN like:
WARN: skip unstable timestamp: kvm_run_exit
cur(8497404907761146)-pre(8497404907761161) pid=3289596 cpu_index=0x0 reason=0x6
WARN: skip unstable timestamp: kvm_vm_ioctl
cur(8497404908603653)-pre(8497404908603673) pid=3289596 type=0xffffffffc008ae67
arg=0x7ffeefb5aa60
WARN: skip unstable timestamp: kvm_vm_ioctl
cur(8497404908625787)-pre(8497404908625808) pid=3289596 type=0xffffffffc008ae67
arg=0x7ffeefb5aa60
This would help to identify unusual events.
And skip them without updating Formatter2.last_timestamp_ns to avoid
time back.
Signed-off-by: Zhao Liu <zhao1....@intel.com>
---
scripts/simpletrace.py | 11 +++++++++++
1 file changed, 11 insertions(+)
diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index cef81b0707f0..23911dddb8a6 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -343,6 +343,17 @@ def __init__(self):
def catchall(self, *rec_args, event, timestamp_ns, pid, event_id):
if self.last_timestamp_ns is None:
self.last_timestamp_ns = timestamp_ns
+
+ if timestamp_ns < self.last_timestamp_ns:
+ fields = [
+ f'{name}={r}' if is_string(type) else f'{name}=0x{r:x}'
+ for r, (type, name) in zip(rec_args, event.args)
+ ]
+ print(f'WARN: skip unstable timestamp: {event.name} '
+ f'cur({timestamp_ns})-pre({self.last_timestamp_ns})
{pid=} ' +
+ f' '.join(fields))
+ return
+
delta_ns = timestamp_ns - self.last_timestamp_ns
self.last_timestamp_ns = timestamp_ns
--
2.34.1
