From: Zhao Liu <zhao1.liu@intel.com>
To: 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>
Cc: qemu-devel@nongnu.org, Zhao Liu <zhao1.liu@intel.com>
Subject: [PATCH] scripts/simpletrace: Mark output with unstable timestamp as WARN
Date: Wed, 8 May 2024 12:32:29 +0800 [thread overview]
Message-ID: <20240508043229.3433128-1-zhao1.liu@intel.com> (raw)
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:
WARN: skip unstable timestamp: kvm_run_exit cur(8497404907761146)-pre(8497404907761161) pid=3289596 cpu_index=0x0 reason=0x6
WARN: skip unstable timestamp: kvm_vm_ioctl cur(8497404908603653)-pre(8497404908603673) pid=3289596 type=0xffffffffc008ae67 arg=0x7ffeefb5aa60
WARN: skip unstable timestamp: kvm_vm_ioctl cur(8497404908625787)-pre(8497404908625808) pid=3289596 type=0xffffffffc008ae67 arg=0x7ffeefb5aa60
This would help to identify unusual events.
And skip them without updating Formatter2.last_timestamp_ns to avoid
time back.
Signed-off-by: Zhao Liu <zhao1.liu@intel.com>
---
scripts/simpletrace.py | 11 +++++++++++
1 file changed, 11 insertions(+)
diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index cef81b0707f0..23911dddb8a6 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -343,6 +343,17 @@ def __init__(self):
def catchall(self, *rec_args, event, timestamp_ns, pid, event_id):
if self.last_timestamp_ns is None:
self.last_timestamp_ns = timestamp_ns
+
+ if timestamp_ns < self.last_timestamp_ns:
+ fields = [
+ f'{name}={r}' if is_string(type) else f'{name}=0x{r:x}'
+ for r, (type, name) in zip(rec_args, event.args)
+ ]
+ print(f'WARN: skip unstable timestamp: {event.name} '
+ f'cur({timestamp_ns})-pre({self.last_timestamp_ns}) {pid=} ' +
+ f' '.join(fields))
+ return
+
delta_ns = timestamp_ns - self.last_timestamp_ns
self.last_timestamp_ns = timestamp_ns
--
2.34.1
next reply other threads:[~2024-05-08 4:19 UTC|newest]
Thread overview: 11+ messages / expand[flat|nested] mbox.gz Atom feed top
2024-05-08 4:32 Zhao Liu [this message]
2024-05-08 13:09 ` [PATCH] scripts/simpletrace: Mark output with unstable timestamp as WARN 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
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=20240508043229.3433128-1-zhao1.liu@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@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).