Linux-Trace-Devel Archive on lore.kernel.org
 help / color / Atom feed
* [PATCH] trace-cmd: Add proper KBUFFER_TYPE_TIME_STAMP handling
@ 2019-09-04 20:17 Tom Zanussi
  0 siblings, 0 replies; only message in thread
From: Tom Zanussi @ 2019-09-04 20:17 UTC (permalink / raw)
  To: Linux Trace Devel; +Cc: Steven Rostedt, LKML

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

Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
 lib/traceevent/kbuffer-parse.c | 15 +++++++++------
 tracecmd/trace-read.c          | 13 +++++++++----
 2 files changed, 18 insertions(+), 10 deletions(-)

diff --git a/lib/traceevent/kbuffer-parse.c b/lib/traceevent/kbuffer-parse.c
index 622f285..b18dedc 100644
--- a/lib/traceevent/kbuffer-parse.c
+++ b/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;
 }
diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index 12b8b3d..a1371f4 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -846,12 +846,17 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 					trace_seq_printf(&s, "\n TIME EXTEND: ");
 					break;
 				case KBUFFER_TYPE_TIME_STAMP:
-					trace_seq_printf(&s, "\n TIME STAMP?: ");
+					trace_seq_printf(&s, "\n TIME STAMP: ");
 					break;
 				}
-				trace_seq_printf(&s, "delta:%lld length:%d",
-						 pi->delta,
-						 pi->length);
+				if (pi->type == KBUFFER_TYPE_TIME_STAMP)
+					trace_seq_printf(&s, "timestamp:%lld length:%d",
+							 pi->delta,
+							 pi->length);
+				else
+					trace_seq_printf(&s, "delta:%lld length:%d",
+							 pi->delta,
+							 pi->length);
 			}
 		}
 	}
-- 
2.14.1


^ permalink raw reply	[flat|nested] only message in thread

only message in thread, back to index

Thread overview: (only message) (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-09-04 20:17 [PATCH] trace-cmd: Add proper KBUFFER_TYPE_TIME_STAMP handling Tom Zanussi

Linux-Trace-Devel Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-trace-devel/0 linux-trace-devel/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-trace-devel linux-trace-devel/ https://lore.kernel.org/linux-trace-devel \
		linux-trace-devel@vger.kernel.org linux-trace-devel@archiver.kernel.org
	public-inbox-index linux-trace-devel

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-trace-devel


AGPL code for this site: git clone https://public-inbox.org/ public-inbox