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

["Philippe Mathieu-Daudé" <philmd@linaro.org>]

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?

> Signed-off-by: Zhao Liu <zhao1.liu@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
>