From: Tom Zanussi <zanussi@kernel.org>
To: Linux Trace Devel <linux-trace-devel@vger.kernel.org>
Cc: Steven Rostedt <rostedt@goodmis.org>,
LKML <linux-kernel@vger.kernel.org>
Subject: [PATCH] trace-cmd: Add proper KBUFFER_TYPE_TIME_STAMP handling
Date: Wed, 04 Sep 2019 15:17:04 -0500 [thread overview]
Message-ID: <1567628224.13841.4.camel@kernel.org> (raw)
From: Tom Zanussi <zanussi@kernel.org>
Kernel commit dc4e2801d400 (ring-buffer: Redefine the unimplemented
RINGBUF_TYPE_TIME_STAMP) changed the way the ring buffer timestamps
work - after that commit the previously unimplemented
RINGBUF_TYPE_TIME_STAMP type causes the time delta to be used as a
timestamp rather than a delta to be added to the timestamp.
The trace-cmd code didn't get updated to handle this, so misinterprets
the event data for this case, which causes a cascade of errors,
including trace-report not being able to identify synthetic (or any
other) events generated by the histogram code (which uses TIME_STAMP
mode). For example, the following triggers along with the trace-cmd
shown cause an UNKNOWN_EVENT error and trace-cmd report crash:
# echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > /sys/kernel/debug/tracing/synthetic_events
# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_wakeup).trace(wakeup_latency,$wakeup_lat,next_pid,next_comm) if next_comm=="ping"' > /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# echo 'hist:keys=comm,pid,lat:wakeup_lat=lat:sort=lat' > /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
# trace-cmd record -e wakeup_latency -e sched_wakeup -f comm==\"ping\" ping localhost -c 5
# trace-cmd report
CPU 0 is empty
CPU 1 is empty
CPU 2 is empty
CPU 3 is empty
CPU 5 is empty
CPU 6 is empty
CPU 7 is empty
cpus=8
ug! no event found for type 0
[UNKNOWN TYPE 0]
ug! no event found for type 11520
Segmentation fault (core dumped)
After this patch we get the correct interpretation and the events are
shown properly:
# trace-cmd report
CPU 0 is empty
CPU 1 is empty
CPU 2 is empty
CPU 3 is empty
CPU 5 is empty
CPU 6 is empty
CPU 7 is empty
cpus=8
<idle>-0 [004] 23284.341392: sched_wakeup: ping:12031 [120] success=1 CPU:004
<idle>-0 [004] 23284.341464: wakeup_latency: lat=58, pid=12031, comm=ping
<idle>-0 [004] 23285.365303: sched_wakeup: ping:12031 [120] success=1 CPU:004
<idle>-0 [004] 23285.365382: wakeup_latency: lat=64, pid=12031, comm=ping
<idle>-0 [004] 23286.389290: sched_wakeup: ping:12031 [120] success=1 CPU:004
<idle>-0 [004] 23286.389378: wakeup_latency: lat=72, pid=12031, comm=ping
<idle>-0 [004] 23287.413213: sched_wakeup: ping:12031 [120] success=1 CPU:004
<idle>-0 [004] 23287.413291: wakeup_latency: lat=64, pid=12031, comm=ping
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
lib/traceevent/kbuffer-parse.c | 15 +++++++++------
tracecmd/trace-read.c | 13 +++++++++----
2 files changed, 18 insertions(+), 10 deletions(-)
diff --git a/lib/traceevent/kbuffer-parse.c b/lib/traceevent/kbuffer-parse.c
index 622f285..b18dedc 100644
--- a/lib/traceevent/kbuffer-parse.c
+++ b/lib/traceevent/kbuffer-parse.c
@@ -361,6 +361,7 @@ translate_data(struct kbuffer *kbuf, void *data, void **rptr,
break;
case KBUFFER_TYPE_TIME_EXTEND:
+ case KBUFFER_TYPE_TIME_STAMP:
extend = read_4(kbuf, data);
data += 4;
extend <<= TS_SHIFT;
@@ -369,10 +370,6 @@ translate_data(struct kbuffer *kbuf, void *data, void **rptr,
*length = 0;
break;
- case KBUFFER_TYPE_TIME_STAMP:
- data += 12;
- *length = 0;
- break;
case 0:
*length = read_4(kbuf, data) - 4;
*length = (*length + 3) & ~3;
@@ -397,7 +394,11 @@ static unsigned int update_pointers(struct kbuffer *kbuf)
type_len = translate_data(kbuf, ptr, &ptr, &delta, &length);
- kbuf->timestamp += delta;
+ if (type_len == KBUFFER_TYPE_TIME_STAMP)
+ kbuf->timestamp = delta;
+ else
+ kbuf->timestamp += delta;
+
kbuf->index = calc_index(kbuf, ptr);
kbuf->next = kbuf->index + length;
@@ -454,7 +455,9 @@ static int __next_event(struct kbuffer *kbuf)
if (kbuf->next >= kbuf->size)
return -1;
type = update_pointers(kbuf);
- } while (type == KBUFFER_TYPE_TIME_EXTEND || type == KBUFFER_TYPE_PADDING);
+ } while (type == KBUFFER_TYPE_TIME_EXTEND ||
+ type == KBUFFER_TYPE_TIME_STAMP ||
+ type == KBUFFER_TYPE_PADDING);
return 0;
}
diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index 12b8b3d..a1371f4 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -846,12 +846,17 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
trace_seq_printf(&s, "\n TIME EXTEND: ");
break;
case KBUFFER_TYPE_TIME_STAMP:
- trace_seq_printf(&s, "\n TIME STAMP?: ");
+ trace_seq_printf(&s, "\n TIME STAMP: ");
break;
}
- trace_seq_printf(&s, "delta:%lld length:%d",
- pi->delta,
- pi->length);
+ if (pi->type == KBUFFER_TYPE_TIME_STAMP)
+ trace_seq_printf(&s, "timestamp:%lld length:%d",
+ pi->delta,
+ pi->length);
+ else
+ trace_seq_printf(&s, "delta:%lld length:%d",
+ pi->delta,
+ pi->length);
}
}
}
--
2.14.1
reply other threads:[~2019-09-04 20:17 UTC|newest]
Thread overview: [no followups] expand[flat|nested] mbox.gz Atom feed
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=1567628224.13841.4.camel@kernel.org \
--to=zanussi@kernel.org \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-trace-devel@vger.kernel.org \
--cc=rostedt@goodmis.org \
/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 NNTP newsgroup(s).