Commit 2160d6c8 authored by Tom Zanussi's avatar Tom Zanussi Committed by Arnaldo Carvalho de Melo

tools lib traceevent: Add proper KBUFFER_TYPE_TIME_STAMP handling

Kernel commit dc4e2801 (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/1567628224.13841.4.camel@kernel.org
Link: http://lore.kernel.org/linux-trace-devel/20200625100516.365338-3-tz.stoyanov@gmail.comSigned-off-by: default avatarTom Zanussi <zanussi@kernel.org>
[ Ported from trace-cmd.git ]
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: linux-trace-devel@vger.kernel.org
Link: http://lore.kernel.org/lkml/20200702185703.785094515@goodmis.orgSigned-off-by: default avatarTzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
parent 374855c5
...@@ -361,6 +361,7 @@ translate_data(struct kbuffer *kbuf, void *data, void **rptr, ...@@ -361,6 +361,7 @@ translate_data(struct kbuffer *kbuf, void *data, void **rptr,
break; break;
case KBUFFER_TYPE_TIME_EXTEND: case KBUFFER_TYPE_TIME_EXTEND:
case KBUFFER_TYPE_TIME_STAMP:
extend = read_4(kbuf, data); extend = read_4(kbuf, data);
data += 4; data += 4;
extend <<= TS_SHIFT; extend <<= TS_SHIFT;
...@@ -369,10 +370,6 @@ translate_data(struct kbuffer *kbuf, void *data, void **rptr, ...@@ -369,10 +370,6 @@ translate_data(struct kbuffer *kbuf, void *data, void **rptr,
*length = 0; *length = 0;
break; break;
case KBUFFER_TYPE_TIME_STAMP:
data += 12;
*length = 0;
break;
case 0: case 0:
*length = read_4(kbuf, data) - 4; *length = read_4(kbuf, data) - 4;
*length = (*length + 3) & ~3; *length = (*length + 3) & ~3;
...@@ -397,7 +394,11 @@ static unsigned int update_pointers(struct kbuffer *kbuf) ...@@ -397,7 +394,11 @@ static unsigned int update_pointers(struct kbuffer *kbuf)
type_len = translate_data(kbuf, ptr, &ptr, &delta, &length); 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->index = calc_index(kbuf, ptr);
kbuf->next = kbuf->index + length; kbuf->next = kbuf->index + length;
...@@ -454,7 +455,9 @@ static int __next_event(struct kbuffer *kbuf) ...@@ -454,7 +455,9 @@ static int __next_event(struct kbuffer *kbuf)
if (kbuf->next >= kbuf->size) if (kbuf->next >= kbuf->size)
return -1; return -1;
type = update_pointers(kbuf); 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; return 0;
} }
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment