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