From 374855c5e4a76f7cc7f9aeb613c54929510eff18 Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Red Hat)" Date: Thu, 2 Jul 2020 14:53:45 -0400 Subject: tools lib traceevent: Add API to read time information from kbuffer Add the functions kbuffer_subbuf_timestamp() and kbuffer_ptr_delta() to get the timing data stored in the ring buffer that is used to produced the time stamps of the records. This is useful for tools like trace-cmd to be able to display the content of the read data to understand why the records show the time stamps that they do. Link: http://lore.kernel.org/linux-trace-devel/20200625100516.365338-2-tz.stoyanov@gmail.com Signed-off-by: Steven Rostedt (VMware) [ Ported from trace-cmd.git ] Cc: Andrew Morton Cc: Jiri Olsa Cc: Namhyung Kim Cc: linux-trace-devel@vger.kernel.org Link: http://lore.kernel.org/lkml/20200702185703.619656282@goodmis.org Signed-off-by: Tzvetomir Stoyanov (VMware) Signed-off-by: Arnaldo Carvalho de Melo --- tools/lib/traceevent/kbuffer-parse.c | 28 ++++++++++++++++++++++++++++ tools/lib/traceevent/kbuffer.h | 2 ++ 2 files changed, 30 insertions(+) (limited to 'tools/lib/traceevent') diff --git a/tools/lib/traceevent/kbuffer-parse.c b/tools/lib/traceevent/kbuffer-parse.c index 27f3b07fdae8..583db99aee94 100644 --- a/tools/lib/traceevent/kbuffer-parse.c +++ b/tools/lib/traceevent/kbuffer-parse.c @@ -546,6 +546,34 @@ int kbuffer_load_subbuffer(struct kbuffer *kbuf, void *subbuffer) return 0; } +/** + * kbuffer_subbuf_timestamp - read the timestamp from a sub buffer + * @kbuf: The kbuffer to load + * @subbuf: The subbuffer to read from. + * + * Return the timestamp from a subbuffer. + */ +unsigned long long kbuffer_subbuf_timestamp(struct kbuffer *kbuf, void *subbuf) +{ + return kbuf->read_8(subbuf); +} + +/** + * kbuffer_ptr_delta - read the delta field from a record + * @kbuf: The kbuffer to load + * @ptr: The record in the buffe. + * + * Return the timestamp delta from a record + */ +unsigned int kbuffer_ptr_delta(struct kbuffer *kbuf, void *ptr) +{ + unsigned int type_len_ts; + + type_len_ts = read_4(kbuf, ptr); + return ts4host(kbuf, type_len_ts); +} + + /** * kbuffer_read_event - read the next event in the kbuffer subbuffer * @kbuf: The kbuffer to read from diff --git a/tools/lib/traceevent/kbuffer.h b/tools/lib/traceevent/kbuffer.h index ed4d697fc137..5fa8292e341b 100644 --- a/tools/lib/traceevent/kbuffer.h +++ b/tools/lib/traceevent/kbuffer.h @@ -49,6 +49,8 @@ int kbuffer_load_subbuffer(struct kbuffer *kbuf, void *subbuffer); void *kbuffer_read_event(struct kbuffer *kbuf, unsigned long long *ts); void *kbuffer_next_event(struct kbuffer *kbuf, unsigned long long *ts); unsigned long long kbuffer_timestamp(struct kbuffer *kbuf); +unsigned long long kbuffer_subbuf_timestamp(struct kbuffer *kbuf, void *subbuf); +unsigned int kbuffer_ptr_delta(struct kbuffer *kbuf, void *ptr); void *kbuffer_translate_data(int swap, void *data, unsigned int *size); -- cgit v1.2.3-58-ga151 From 2160d6c8a13e685b7b2bacbe9cd1e9600506a05f Mon Sep 17 00:00:00 2001 From: Tom Zanussi Date: Thu, 2 Jul 2020 14:53:46 -0400 Subject: tools lib traceevent: Add proper KBUFFER_TYPE_TIME_STAMP handling 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 -0 [004] 23284.341392: sched_wakeup: ping:12031 [120] success=1 CPU:004 -0 [004] 23284.341464: wakeup_latency: lat=58, pid=12031, comm=ping -0 [004] 23285.365303: sched_wakeup: ping:12031 [120] success=1 CPU:004 -0 [004] 23285.365382: wakeup_latency: lat=64, pid=12031, comm=ping -0 [004] 23286.389290: sched_wakeup: ping:12031 [120] success=1 CPU:004 -0 [004] 23286.389378: wakeup_latency: lat=72, pid=12031, comm=ping -0 [004] 23287.413213: sched_wakeup: ping:12031 [120] success=1 CPU:004 -0 [004] 23287.413291: wakeup_latency: lat=64, pid=12031, comm=ping Link: http://lkml.kernel.org/r/1567628224.13841.4.camel@kernel.org Link: http://lore.kernel.org/linux-trace-devel/20200625100516.365338-3-tz.stoyanov@gmail.com Signed-off-by: Tom Zanussi [ Ported from trace-cmd.git ] Cc: Andrew Morton Cc: Jiri Olsa Cc: Namhyung Kim Cc: linux-trace-devel@vger.kernel.org Link: http://lore.kernel.org/lkml/20200702185703.785094515@goodmis.org Signed-off-by: Tzvetomir Stoyanov (VMware) Signed-off-by: Steven Rostedt (VMware) Signed-off-by: Arnaldo Carvalho de Melo --- tools/lib/traceevent/kbuffer-parse.c | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) (limited to 'tools/lib/traceevent') diff --git a/tools/lib/traceevent/kbuffer-parse.c b/tools/lib/traceevent/kbuffer-parse.c index 583db99aee94..f1640d651c8a 100644 --- a/tools/lib/traceevent/kbuffer-parse.c +++ b/tools/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; } -- cgit v1.2.3-58-ga151