From: Stefan Hajnoczi <stefanha@redhat.com>
To: Zhao Liu <zhao1.liu@intel.com>
Cc: Stefan Hajnoczi <stefanha@gmail.com>,
Mads Ynddal <mads@ynddal.dk>, John Snow <jsnow@redhat.com>,
Cleber Rosa <crosa@redhat.com>,
Paolo Bonzini <pbonzini@redhat.com>,
qemu-devel@nongnu.org
Subject: Re: [PATCH] scripts/simpletrace: Mark output with unstable timestamp as WARN
Date: Thu, 9 May 2024 09:47:12 -0400 [thread overview]
Message-ID: <20240509134712.GA515599@fedora.redhat.com> (raw)
In-Reply-To: <ZjxKDkZjAitxCasH@intel.com>
[-- Attachment #1: Type: text/plain, Size: 3212 bytes --]
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 <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
> ;-)
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
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]
next prev parent reply other threads:[~2024-05-09 13:48 UTC|newest]
Thread overview: 11+ messages / expand[flat|nested] mbox.gz Atom feed top
2024-05-08 4:32 [PATCH] scripts/simpletrace: Mark output with unstable timestamp as WARN Zhao Liu
2024-05-08 13:09 ` Philippe Mathieu-Daudé
2024-05-08 13:55 ` Zhao Liu
2024-05-08 14:23 ` Philippe Mathieu-Daudé
2024-05-09 4:14 ` Zhao Liu
2024-05-08 18:05 ` Stefan Hajnoczi
2024-05-09 3:59 ` Zhao Liu
2024-05-09 13:47 ` Stefan Hajnoczi [this message]
2024-05-14 8:12 ` Zhao Liu
2024-05-14 12:56 ` Stefan Hajnoczi
2024-05-13 6:54 ` Mads Ynddal
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20240509134712.GA515599@fedora.redhat.com \
--to=stefanha@redhat.com \
--cc=crosa@redhat.com \
--cc=jsnow@redhat.com \
--cc=mads@ynddal.dk \
--cc=pbonzini@redhat.com \
--cc=qemu-devel@nongnu.org \
--cc=stefanha@gmail.com \
--cc=zhao1.liu@intel.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).