Kernel commit dc4e2801d4 (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
Link: http://lkml.kernel.org/r/[email protected]
Link: http://lore.kernel.org/linux-trace-devel/[email protected]
Signed-off-by: Tom Zanussi <[email protected]>
[ Ported from trace-cmd.git ]
Cc: Andrew Morton <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Cc: [email protected]
Link: http://lore.kernel.org/lkml/[email protected]
Signed-off-by: Tzvetomir Stoyanov (VMware) <[email protected]>
Signed-off-by: Steven Rostedt (VMware) <[email protected]>
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
A undefined value was being used for the OLD_RING_BUFFER_TYPE_TIME_STAMP
case entry, as the 'length' variable was not being initialized, fix it.
Caught by the reporter when building tools/perf/ using clang, which emmitted
this warning:
kbuffer-parse.c:312:7: warning: variable 'length' is used uninitialized whenever switch case is taken [-Wsometimes-uninitialized]
case OLD_RINGBUF_TYPE_TIME_EXTEND:
^~~~~~~~~~~~~~~~~~~~~~~~~~~~
kbuffer-parse.c:339:29: note: uninitialized use occurs here
kbuf->next = kbuf->index + length;
^~~~~~
kbuffer-parse.c:297:21: note: initialize the variable 'length' to silence this warning
unsigned int length;
^
= 0
Reported-by: Arnaldo Carvalho de Melo <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Cc: Adrian Hunter <[email protected]>
Cc: David Ahern <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Cc: Wang Nan <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
When a event PADDING is hit (a deleted event that is still in the ring
buffer), translate_data() sets the length of the padding and also updates
the data pointer which is passed back to the caller.
This is unneeded because the caller also updates the data pointer with
the passed back length. translate_data() should not update the pointer,
only set the length.
Signed-off-by: Steven Rostedt <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Cc: [email protected] # 3.12+
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
Tom Zanussi