linux-trace-devel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Steven Rostedt <rostedt@goodmis.org>
To: linux-kernel@vger.kernel.org, linux-trace-devel@vger.kernel.org
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>,
	Ingo Molnar <mingo@kernel.org>, Jiri Olsa <jolsa@redhat.com>,
	Namhyung Kim <namhyung@kernel.org>,
	Andrew Morton <akpm@linux-foundation.org>,
	Tom Zanussi <zanussi@kernel.org>,
	"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com>
Subject: [PATCH v2 02/15] tools lib traceevent: Add proper KBUFFER_TYPE_TIME_STAMP handling
Date: Thu, 02 Jul 2020 14:53:46 -0400	[thread overview]
Message-ID: <20200702185703.785094515@goodmis.org> (raw)
In-Reply-To: 20200702185344.913492689@goodmis.org

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



  parent reply	other threads:[~2020-07-02 18:57 UTC|newest]

Thread overview: 28+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2020-07-02 18:53 [PATCH v2 00/15] tools lib traceevent: Patches from the trace-cmd repo Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 01/15] tools lib traceevent: Add API to read time information from kbuffer Steven Rostedt
2020-07-03 11:31   ` Arnaldo Carvalho de Melo
2020-07-03 16:18     ` Steven Rostedt
2020-07-02 18:53 ` Steven Rostedt [this message]
2020-07-02 18:53 ` [PATCH v2 03/15] tools lib traceevent: Add tep_load_plugins_hook() API Steven Rostedt
2020-07-07 14:55   ` Namhyung Kim
2020-07-07 15:35     ` Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 04/15] tools lib traceevent: Add interface for options to plugins Steven Rostedt
2020-07-07 15:03   ` Namhyung Kim
2020-07-02 18:53 ` [PATCH v2 05/15] tools lib traceevent: Introduced new traceevent API, for adding new plugins directories Steven Rostedt
2020-07-07 15:06   ` Namhyung Kim
2020-07-07 15:24     ` Steven Rostedt
2020-07-08  0:02       ` Namhyung Kim
2020-07-02 18:53 ` [PATCH v2 06/15] tools lib traceevent: Add support for more printk format specifiers Steven Rostedt
2020-07-07 15:09   ` Namhyung Kim
2020-07-02 18:53 ` [PATCH v2 07/15] tools lib traceevent: Optimize pretty_print() function Steven Rostedt
2020-07-07 15:11   ` Namhyung Kim
2020-07-07 15:31     ` Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 08/15] tools lib traceevent: Add plugin for tlb_flush Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 09/15] tools lib traceevent: Add more SVM exit reasons Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 10/15] tools lib traceevent: Add offset option for function plugin Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 11/15] tools lib traceevent: Add plugin for decoding syscalls/sys_enter_futex Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 12/15] tools lib traceevent: Move kernel_stack event handler to "function" plugin Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 13/15] tools lib traceevent: Add builtin handler for trace_marker_raw Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 14/15] tools lib traceevent: Change to SPDX License format Steven Rostedt
2020-07-02 18:53 ` [PATCH v2 15/15] tools lib traceevent: Fix reporting of unknown SVM exit reasons Steven Rostedt
2020-07-08  2:02 ` [PATCH v2 00/15] tools lib traceevent: Patches from the trace-cmd repo Namhyung Kim

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20200702185703.785094515@goodmis.org \
    --to=rostedt@goodmis.org \
    --cc=acme@kernel.org \
    --cc=akpm@linux-foundation.org \
    --cc=jolsa@redhat.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=linux-trace-devel@vger.kernel.org \
    --cc=mingo@kernel.org \
    --cc=namhyung@kernel.org \
    --cc=tz.stoyanov@gmail.com \
    --cc=zanussi@kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).