From: Zhao Liu <zhao1.liu@intel.com>
To: Stefan Hajnoczi <stefanha@gmail.com>
Cc: Mads Ynddal <mads@ynddal.dk>, John Snow <jsnow@redhat.com>,
Cleber Rosa <crosa@redhat.com>,
Stefan Hajnoczi <stefanha@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 11:59:10 +0800 [thread overview]
Message-ID: <ZjxKDkZjAitxCasH@intel.com> (raw)
In-Reply-To: <CAJSP0QX0y_J1pu+hgUNhXn7bFJfoAMm9Ux9vq3u+k_UDjwK8Ww@mail.gmail.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
next prev parent reply other threads:[~2024-05-09 3:45 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 [this message]
2024-05-09 13:47 ` Stefan Hajnoczi
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=ZjxKDkZjAitxCasH@intel.com \
--to=zhao1.liu@intel.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=stefanha@redhat.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).