On Wed, 8 May 2024 at 00:19, Zhao Liu <zhao1....@intel.com> 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:
Why are the timestamps non-monotonic?
In a situation like that maybe not only the negative timestamps are
useless but even some positive timestamps are incorrect. I think it's
worth understanding the nature of the instability before merging a
fix.
Stefan
>
> 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.
>
> Signed-off-by: Zhao Liu <zhao1....@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
>
> --
> 2.34.1
>
>
