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 <stefa...@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....@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
