Skip to content
  • Tom Zanussi's avatar
    tools lib traceevent: Add proper KBUFFER_TYPE_TIME_STAMP handling · 2160d6c8
    Tom Zanussi authored
    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.com
    
    
    
    Signed-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.org
    
    
    Signed-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>
    2160d6c8