Re: [PATCH] scripts/simpletrace: Mark output with unstable timestamp as WARN

[Zhao Liu <zhao1.liu@intel.com>]

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é <philmd@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é <philmd@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