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

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

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.

Regards,
Zhao