Hi Philippe, On Wed, May 08, 2024 at 03:09:39PM +0200, Philippe Mathieu-Daudé wrote: > Date: Wed, 8 May 2024 15:09:39 +0200 > From: Philippe Mathieu-Daudé <phi...@linaro.org> > Subject: Re: [PATCH] scripts/simpletrace: Mark output with unstable > timestamp as WARN > > On 8/5/24 06:32, Zhao Liu 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: > > > > 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. > > Can't we reorder them instead?
I think so...IIUC, when the current event with "wrong" timestamp is detected, its previous events records have already been output and cannot be reordered. Regards, Zhao
