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

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

On Wed, May 08, 2024 at 02:05:04PM -0400, Stefan Hajnoczi wrote:
> Date: Wed, 8 May 2024 14:05:04 -0400
> From: Stefan Hajnoczi <stefanha@gmail.com>
> Subject: Re: [PATCH] scripts/simpletrace: Mark output with unstable
>  timestamp as WARN
> 
> On Wed, 8 May 2024 at 00:19, Zhao Liu <zhao1.liu@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.

I grabbed more traces (by -trace "*" to cover as many events as possible
) and have a couple observations:

* It's not an issue with kvm's ioctl, and that qemu_mutex_lock/
  object_dynamic_cast_assert accounted for the vast majority of all
  exception timestamps.
* The total exception timestamp occurrence probability was roughly 0.013%
  (608 / 4,616,938) in a 398M trace file.
* And the intervals between the "wrong" timestamp and its pre event are
  almost all within 50ns, even more concentrated within 20ns (there are
  even quite a few 1~10ns).

Just a guess:

Would it be possible that a trace event which is too short of an interval,
and happen to meet a delay in signaling to send to writeout_thread?

It seems that this short interval like a lack of real-time guarantees in
the underlying mechanism...

If it's QEMU's own issue, I feel like the intervals should be randomized,
not just within 50ns...

May I ask what you think? Any suggestions for researching this situation
;-)

Thanks,
Zhao