On Wed, May 08, 2024 at 04:23:00PM +0200, Philippe Mathieu-Daudé wrote: > Date: Wed, 8 May 2024 16:23:00 +0200 > From: Philippe Mathieu-Daudé <phi...@linaro.org> > Subject: Re: [PATCH] scripts/simpletrace: Mark output with unstable > timestamp as WARN > > On 8/5/24 15:55, Zhao Liu wrote: > > 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. > > Well, this certainly need rework to cleverly handle out of sync > events, reordering them to display them correctly. > > Skipping events really sounds a bad idea to me. Even more out > of sync ones. > > Some simple approach could be to queue up to N events, then sort them > and unqueue N/2, while processing all events.
Reordering might be possible, but as Stefan replied, some psitive value might also be problematic too. Maybe my negative value check is not enough in itself... Thanks, Zhao
