On Thu, May 09, 2024 at 11:59:10AM +0800, Zhao Liu wrote: > 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 > ;-)
QEMU uses clock_gettime(CLOCK_MONOTONIC) on Linux hosts. The man page says: All CLOCK_MONOTONIC variants guarantee that the time returned by consecutive calls will not go backwards, but successive calls may—depending on the architecture—return identical (not-in‐ creased) time values. trace_record_start() calls clock_gettime(CLOCK_MONOTONIC) so trace events should have monotonically increasing timestamps. I don't see a scenario where trace record A's timestamp is greater than trace record B's timestamp unless the clock is non-monotonic. Which host CPU architecture and operating system are you running? Please attach to the QEMU process with gdb and print out the value of the use_rt_clock variable or add a printf in init_get_clock(). The value should be 1. Stefan
signature.asc
Description: PGP signature
