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

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

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.

Regards,

Phil.