On Wed, 8 May 2024 at 00:19, Zhao Liu <zhao1....@intel.com> wrote: > > 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:
Why are the timestamps non-monotonic? In a situation like that maybe not only the negative timestamps are useless but even some positive timestamps are incorrect. I think it's worth understanding the nature of the instability before merging a fix. Stefan > > 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 > >