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.
Regards,
Phil.
