lkml.org 
[lkml]   [2020]   [Jul]   [21]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    Subject[PATCH 02/23 v3] tools lib traceevent: Add proper KBUFFER_TYPE_TIME_STAMP handling
    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

    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 <zanussi@kernel.org>
    [ Ported from trace-cmd.git ]
    Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
    Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
    ---
    tools/lib/traceevent/kbuffer-parse.c | 15 +++++++++------
    1 file changed, 9 insertions(+), 6 deletions(-)

    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;
    }
    --
    2.26.2

    \
     
     \ /
      Last update: 2020-07-22 03:19    [W:3.377 / U:0.088 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site