Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1727008 > unrolled thread

[PATCH v2 08/40] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP

Started byTom Zanussi <tom.zanussi@linux.intel.com>
First post2017-09-06 00:00 +0200
Last post2017-09-07 17:10 +0200
Articles 3 — 2 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  [PATCH v2 08/40] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-09-06 00:00 +0200
    Re: [PATCH v2 08/40] ring-buffer: Redefine the unimplemented  RINGBUF_TIME_TIME_STAMP Steven Rostedt <rostedt@goodmis.org> - 2017-09-07 16:40 +0200
      Re: [PATCH v2 08/40] ring-buffer: Redefine the unimplemented  RINGBUF_TIME_TIME_STAMP Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-09-07 17:10 +0200

#1727008 — [PATCH v2 08/40] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP

FromTom Zanussi <tom.zanussi@linux.intel.com>
Date2017-09-06 00:00 +0200
Subject[PATCH v2 08/40] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP
Message-ID<umu2Z-5m-3@gated-at.bofh.it>
RINGBUF_TYPE_TIME_STAMP is defined but not used, and from what I can
gather was reserved for something like an absolute timestamp feature
for the ring buffer, if not a complete replacement of the current
time_delta scheme.

This code redefines RINGBUF_TYPE_TIME_STAMP to implement absolute time
stamps.  Another way to look at it is that it essentially forces
extended time_deltas for all events.

The motivation for doing this is to enable time_deltas that aren't
dependent on previous events in the ring buffer, making it feasible to
use the ring_buffer_event timetamps in a more random-access way, for
purposes other than serial event printing.

To set/reset this mode, use tracing_set_timestamp_abs() from the
previous interface patch.

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
 include/linux/ring_buffer.h |  12 ++---
 kernel/trace/ring_buffer.c  | 105 ++++++++++++++++++++++++++++++++------------
 2 files changed, 83 insertions(+), 34 deletions(-)

diff --git a/include/linux/ring_buffer.h b/include/linux/ring_buffer.h
index 28e3472..74bc276 100644
--- a/include/linux/ring_buffer.h
+++ b/include/linux/ring_buffer.h
@@ -36,10 +36,12 @@ struct ring_buffer_event {
  *				 array[0] = time delta (28 .. 59)
  *				 size = 8 bytes
  *
- * @RINGBUF_TYPE_TIME_STAMP:	Sync time stamp with external clock
- *				 array[0]    = tv_nsec
- *				 array[1..2] = tv_sec
- *				 size = 16 bytes
+ * @RINGBUF_TYPE_TIME_STAMP:	Absolute timestamp
+ *				 Same format as TIME_EXTEND except that the
+ *				 value is an absolute timestamp, not a delta
+ *				 event.time_delta contains bottom 27 bits
+ *				 array[0] = top (28 .. 59) bits
+ *				 size = 8 bytes
  *
  * <= @RINGBUF_TYPE_DATA_TYPE_LEN_MAX:
  *				Data record
@@ -56,12 +58,12 @@ enum ring_buffer_type {
 	RINGBUF_TYPE_DATA_TYPE_LEN_MAX = 28,
 	RINGBUF_TYPE_PADDING,
 	RINGBUF_TYPE_TIME_EXTEND,
-	/* FIXME: RINGBUF_TYPE_TIME_STAMP not implemented */
 	RINGBUF_TYPE_TIME_STAMP,
 };
 
 unsigned ring_buffer_event_length(struct ring_buffer_event *event);
 void *ring_buffer_event_data(struct ring_buffer_event *event);
+u64 ring_buffer_event_time_stamp(struct ring_buffer_event *event);
 
 /*
  * ring_buffer_discard_commit will remove an event that has not
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index cff15a2..0bcc53e 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -42,6 +42,8 @@ int ring_buffer_print_entry_header(struct trace_seq *s)
 			 RINGBUF_TYPE_PADDING);
 	trace_seq_printf(s, "\ttime_extend : type == %d\n",
 			 RINGBUF_TYPE_TIME_EXTEND);
+	trace_seq_printf(s, "\ttime_stamp : type == %d\n",
+			 RINGBUF_TYPE_TIME_STAMP);
 	trace_seq_printf(s, "\tdata max type_len  == %d\n",
 			 RINGBUF_TYPE_DATA_TYPE_LEN_MAX);
 
@@ -141,12 +143,15 @@ int ring_buffer_print_entry_header(struct trace_seq *s)
 
 enum {
 	RB_LEN_TIME_EXTEND = 8,
-	RB_LEN_TIME_STAMP = 16,
+	RB_LEN_TIME_STAMP =  8,
 };
 
 #define skip_time_extend(event) \
 	((struct ring_buffer_event *)((char *)event + RB_LEN_TIME_EXTEND))
 
+#define extended_time(event) \
+	(event->type_len >= RINGBUF_TYPE_TIME_EXTEND)
+
 static inline int rb_null_event(struct ring_buffer_event *event)
 {
 	return event->type_len == RINGBUF_TYPE_PADDING && !event->time_delta;
@@ -210,7 +215,7 @@ static void rb_event_set_padding(struct ring_buffer_event *event)
 {
 	unsigned len = 0;
 
-	if (event->type_len == RINGBUF_TYPE_TIME_EXTEND) {
+	if (extended_time(event)) {
 		/* time extends include the data event after it */
 		len = RB_LEN_TIME_EXTEND;
 		event = skip_time_extend(event);
@@ -232,7 +237,7 @@ unsigned ring_buffer_event_length(struct ring_buffer_event *event)
 {
 	unsigned length;
 
-	if (event->type_len == RINGBUF_TYPE_TIME_EXTEND)
+	if (extended_time(event))
 		event = skip_time_extend(event);
 
 	length = rb_event_length(event);
@@ -249,7 +254,7 @@ unsigned ring_buffer_event_length(struct ring_buffer_event *event)
 static __always_inline void *
 rb_event_data(struct ring_buffer_event *event)
 {
-	if (event->type_len == RINGBUF_TYPE_TIME_EXTEND)
+	if (extended_time(event))
 		event = skip_time_extend(event);
 	BUG_ON(event->type_len > RINGBUF_TYPE_DATA_TYPE_LEN_MAX);
 	/* If length is in len field, then array[0] has the data */
@@ -276,6 +281,27 @@ void *ring_buffer_event_data(struct ring_buffer_event *event)
 #define TS_MASK		((1ULL << TS_SHIFT) - 1)
 #define TS_DELTA_TEST	(~TS_MASK)
 
+/**
+ * ring_buffer_event_time_stamp - return the event's extended timestamp
+ * @event: the event to get the timestamp of
+ *
+ * Returns the extended timestamp associated with a data event.
+ * An extended time_stamp is a 64-bit timestamp represented
+ * internally in a special way that makes the best use of space
+ * contained within a ring buffer event.  This function decodes
+ * it and maps it to a straight u64 value.
+ */
+u64 ring_buffer_event_time_stamp(struct ring_buffer_event *event)
+{
+	u64 ts;
+
+	ts = event->array[0];
+	ts <<= TS_SHIFT;
+	ts += event->time_delta;
+
+	return ts;
+}
+
 /* Flag when events were overwritten */
 #define RB_MISSED_EVENTS	(1 << 31)
 /* Missed count stored at end */
@@ -2220,13 +2246,16 @@ static void rb_inc_iter(struct ring_buffer_iter *iter)
 }
 
 /* Slow path, do not inline */
-static noinline struct ring_buffer_event *
-rb_add_time_stamp(struct ring_buffer_event *event, u64 delta)
+static struct noinline ring_buffer_event *
+rb_add_time_stamp(struct ring_buffer_event *event, u64 delta, bool abs)
 {
-	event->type_len = RINGBUF_TYPE_TIME_EXTEND;
+	if (abs)
+		event->type_len = RINGBUF_TYPE_TIME_STAMP;
+	else
+		event->type_len = RINGBUF_TYPE_TIME_EXTEND;
 
-	/* Not the first event on the page? */
-	if (rb_event_index(event)) {
+	/* Not the first event on the page, or not delta? */
+	if (abs || rb_event_index(event)) {
 		event->time_delta = delta & TS_MASK;
 		event->array[0] = delta >> TS_SHIFT;
 	} else {
@@ -2269,7 +2298,9 @@ static inline bool rb_event_is_commit(struct ring_buffer_per_cpu *cpu_buffer,
 	 * add it to the start of the resevered space.
 	 */
 	if (unlikely(info->add_timestamp)) {
-		event = rb_add_time_stamp(event, delta);
+		bool abs = ring_buffer_time_stamp_abs(cpu_buffer->buffer);
+
+		event = rb_add_time_stamp(event, info->delta, abs);
 		length -= RB_LEN_TIME_EXTEND;
 		delta = 0;
 	}
@@ -2457,7 +2488,7 @@ static __always_inline void rb_end_commit(struct ring_buffer_per_cpu *cpu_buffer
 
 static inline void rb_event_discard(struct ring_buffer_event *event)
 {
-	if (event->type_len == RINGBUF_TYPE_TIME_EXTEND)
+	if (extended_time(event))
 		event = skip_time_extend(event);
 
 	/* array[0] holds the actual length for the discarded event */
@@ -2488,6 +2519,10 @@ static inline void rb_event_discard(struct ring_buffer_event *event)
 {
 	u64 delta;
 
+	/* In TIME_STAMP mode, write_stamp is unused, nothing to do */
+	if (event->type_len == RINGBUF_TYPE_TIME_STAMP)
+		return;
+
 	/*
 	 * The event first in the commit queue updates the
 	 * time stamp.
@@ -2501,9 +2536,7 @@ static inline void rb_event_discard(struct ring_buffer_event *event)
 			cpu_buffer->write_stamp =
 				cpu_buffer->commit_page->page->time_stamp;
 		else if (event->type_len == RINGBUF_TYPE_TIME_EXTEND) {
-			delta = event->array[0];
-			delta <<= TS_SHIFT;
-			delta += event->time_delta;
+			delta = ring_buffer_event_time_stamp(event);
 			cpu_buffer->write_stamp += delta;
 		} else
 			cpu_buffer->write_stamp += event->time_delta;
@@ -2687,7 +2720,7 @@ int ring_buffer_unlock_commit(struct ring_buffer *buffer,
 	 * If this is the first commit on the page, then it has the same
 	 * timestamp as the page itself.
 	 */
-	if (!tail)
+	if (!tail && !ring_buffer_time_stamp_abs(cpu_buffer->buffer))
 		info->delta = 0;
 
 	/* See if we shot pass the end of this buffer page */
@@ -2765,8 +2798,11 @@ int ring_buffer_unlock_commit(struct ring_buffer *buffer,
 	/* make sure this diff is calculated here */
 	barrier();
 
-	/* Did the write stamp get updated already? */
-	if (likely(info.ts >= cpu_buffer->write_stamp)) {
+	if (ring_buffer_time_stamp_abs(buffer)) {
+		info.delta = info.ts;
+		rb_handle_timestamp(cpu_buffer, &info);
+	} else /* Did the write stamp get updated already? */
+		if (likely(info.ts >= cpu_buffer->write_stamp)) {
 		info.delta = diff;
 		if (unlikely(test_time_stamp(info.delta)))
 			rb_handle_timestamp(cpu_buffer, &info);
@@ -3448,14 +3484,12 @@ int ring_buffer_iter_empty(struct ring_buffer_iter *iter)
 		return;
 
 	case RINGBUF_TYPE_TIME_EXTEND:
-		delta = event->array[0];
-		delta <<= TS_SHIFT;
-		delta += event->time_delta;
+		delta = ring_buffer_event_time_stamp(event);
 		cpu_buffer->read_stamp += delta;
 		return;
 
 	case RINGBUF_TYPE_TIME_STAMP:
-		/* FIXME: not implemented */
+		/* In TIME_STAMP mode, write_stamp is unused, nothing to do */
 		return;
 
 	case RINGBUF_TYPE_DATA:
@@ -3479,14 +3513,12 @@ int ring_buffer_iter_empty(struct ring_buffer_iter *iter)
 		return;
 
 	case RINGBUF_TYPE_TIME_EXTEND:
-		delta = event->array[0];
-		delta <<= TS_SHIFT;
-		delta += event->time_delta;
+		delta = ring_buffer_event_time_stamp(event);
 		iter->read_stamp += delta;
 		return;
 
 	case RINGBUF_TYPE_TIME_STAMP:
-		/* FIXME: not implemented */
+		/* In TIME_STAMP mode, write_stamp is unused, nothing to do */
 		return;
 
 	case RINGBUF_TYPE_DATA:
@@ -3710,6 +3742,8 @@ static int rb_lost_events(struct ring_buffer_per_cpu *cpu_buffer)
 	struct buffer_page *reader;
 	int nr_loops = 0;
 
+	if (ts)
+		*ts = 0;
  again:
 	/*
 	 * We repeat when a time extend is encountered.
@@ -3746,12 +3780,17 @@ static int rb_lost_events(struct ring_buffer_per_cpu *cpu_buffer)
 		goto again;
 
 	case RINGBUF_TYPE_TIME_STAMP:
-		/* FIXME: not implemented */
+		if (ts) {
+			*ts = ring_buffer_event_time_stamp(event);
+			ring_buffer_normalize_time_stamp(cpu_buffer->buffer,
+							 cpu_buffer->cpu, ts);
+		}
+		/* Internal data, OK to advance */
 		rb_advance_reader(cpu_buffer);
 		goto again;
 
 	case RINGBUF_TYPE_DATA:
-		if (ts) {
+		if (ts && !(*ts)) {
 			*ts = cpu_buffer->read_stamp + event->time_delta;
 			ring_buffer_normalize_time_stamp(cpu_buffer->buffer,
 							 cpu_buffer->cpu, ts);
@@ -3776,6 +3815,9 @@ static int rb_lost_events(struct ring_buffer_per_cpu *cpu_buffer)
 	struct ring_buffer_event *event;
 	int nr_loops = 0;
 
+	if (ts)
+		*ts = 0;
+
 	cpu_buffer = iter->cpu_buffer;
 	buffer = cpu_buffer->buffer;
 
@@ -3828,12 +3870,17 @@ static int rb_lost_events(struct ring_buffer_per_cpu *cpu_buffer)
 		goto again;
 
 	case RINGBUF_TYPE_TIME_STAMP:
-		/* FIXME: not implemented */
+		if (ts) {
+			*ts = ring_buffer_event_time_stamp(event);
+			ring_buffer_normalize_time_stamp(cpu_buffer->buffer,
+							 cpu_buffer->cpu, ts);
+		}
+		/* Internal data, OK to advance */
 		rb_advance_iter(iter);
 		goto again;
 
 	case RINGBUF_TYPE_DATA:
-		if (ts) {
+		if (ts && !(*ts)) {
 			*ts = iter->read_stamp + event->time_delta;
 			ring_buffer_normalize_time_stamp(buffer,
 							 cpu_buffer->cpu, ts);
-- 
1.9.3

[toc] | [next] | [standalone]

#1728244 — Re: [PATCH v2 08/40] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP

FromSteven Rostedt <rostedt@goodmis.org>
Date2017-09-07 16:40 +0200
SubjectRe: [PATCH v2 08/40] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP
Message-ID<un68h-160-1@gated-at.bofh.it>
In reply to#1727008
On Tue,  5 Sep 2017 16:57:20 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> diff --git a/include/linux/ring_buffer.h b/include/linux/ring_buffer.h
> index 28e3472..74bc276 100644
> --- a/include/linux/ring_buffer.h
> +++ b/include/linux/ring_buffer.h
> @@ -36,10 +36,12 @@ struct ring_buffer_event {
>   *				 array[0] = time delta (28 .. 59)
>   *				 size = 8 bytes
>   *
> - * @RINGBUF_TYPE_TIME_STAMP:	Sync time stamp with external clock
> - *				 array[0]    = tv_nsec
> - *				 array[1..2] = tv_sec
> - *				 size = 16 bytes
> + * @RINGBUF_TYPE_TIME_STAMP:	Absolute timestamp
> + *				 Same format as TIME_EXTEND except that the
> + *				 value is an absolute timestamp, not a delta
> + *				 event.time_delta contains bottom 27 bits
> + *				 array[0] = top (28 .. 59) bits
> + *				 size = 8 bytes

Is it going to be an issue that our time stamp is only 59 bits?

2^59 = 576,460,752,303,423,488

Thus, 2^59 nanoseconds (I doubt we will need to have precision better
than nanoseconds) = 576,460,752 seconds = 9,607,679 minutes = 160,127
hours = 6,671 days = 18 years.

We would be screwed if we trace for more than 18 years. ;-)

That's why I had it as 16 bytes, to be able to hold a full 64 bit
timestamp (and still be 8 byte aligned). But since we've gone this long
without needing this, I'm sure a 59 bit absolute timestamp should be
good enough.

>   *
>   * <= @RINGBUF_TYPE_DATA_TYPE_LEN_MAX:
>   *				Data record
> @@ -56,12 +58,12 @@ enum ring_buffer_type {
>  	RINGBUF_TYPE_DATA_TYPE_LEN_MAX = 28,
>  	RINGBUF_TYPE_PADDING,
>  	RINGBUF_TYPE_TIME_EXTEND,
> -	/* FIXME: RINGBUF_TYPE_TIME_STAMP not implemented */
>  	RINGBUF_TYPE_TIME_STAMP,
>  };
>  
>  unsigned ring_buffer_event_length(struct ring_buffer_event *event);
>  void *ring_buffer_event_data(struct ring_buffer_event *event);
> +u64 ring_buffer_event_time_stamp(struct ring_buffer_event *event);
>  
>  /*
>   * ring_buffer_discard_commit will remove an event that has not




> @@ -2488,6 +2519,10 @@ static inline void rb_event_discard(struct ring_buffer_event *event)
>  {
>  	u64 delta;
>  
> +	/* In TIME_STAMP mode, write_stamp is unused, nothing to do */

No, we still need to keep the write_stamp updated. Sure, it doesn't use
it, but I do want to have absolute and delta timestamps working
together in a single buffer. It shouldn't be one or the other. In fact,
I plan on using it that way for nested events.

Maybe for this feature we can let it slide. But I will be working on
fixing that.

-- Steve

> +	if (event->type_len == RINGBUF_TYPE_TIME_STAMP)
> +		return;
> +
>  	/*
>  	 * The event first in the commit queue updates the
>  	 * time stamp.
> @@ -2501,9 +2536,7 @@ static inline void rb_event_discard(struct ring_buffer_event *event)
>  			cpu_buffer->write_stamp =
>  				cpu_buffer->commit_page->page->time_stamp;
>  		else if (event->type_len == RINGBUF_TYPE_TIME_EXTEND) {
> -			delta = event->array[0];
> -			delta <<= TS_SHIFT;
> -			delta += event->time_delta;
> +			delta = ring_buffer_event_time_stamp(event);
>  			cpu_buffer->write_stamp += delta;
>  		} else

[toc] | [prev] | [next] | [standalone]

#1728253 — Re: [PATCH v2 08/40] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP

FromTom Zanussi <tom.zanussi@linux.intel.com>
Date2017-09-07 17:10 +0200
SubjectRe: [PATCH v2 08/40] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP
Message-ID<un6Bk-1LE-9@gated-at.bofh.it>
In reply to#1728244
Hi Steve,

On Thu, 2017-09-07 at 10:35 -0400, Steven Rostedt wrote:
> On Tue,  5 Sep 2017 16:57:20 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> > diff --git a/include/linux/ring_buffer.h b/include/linux/ring_buffer.h
> > index 28e3472..74bc276 100644
> > --- a/include/linux/ring_buffer.h
> > +++ b/include/linux/ring_buffer.h
> > @@ -36,10 +36,12 @@ struct ring_buffer_event {
> >   *				 array[0] = time delta (28 .. 59)
> >   *				 size = 8 bytes
> >   *
> > - * @RINGBUF_TYPE_TIME_STAMP:	Sync time stamp with external clock
> > - *				 array[0]    = tv_nsec
> > - *				 array[1..2] = tv_sec
> > - *				 size = 16 bytes
> > + * @RINGBUF_TYPE_TIME_STAMP:	Absolute timestamp
> > + *				 Same format as TIME_EXTEND except that the
> > + *				 value is an absolute timestamp, not a delta
> > + *				 event.time_delta contains bottom 27 bits
> > + *				 array[0] = top (28 .. 59) bits
> > + *				 size = 8 bytes
> 
> Is it going to be an issue that our time stamp is only 59 bits?
> 
> 2^59 = 576,460,752,303,423,488
> 
> Thus, 2^59 nanoseconds (I doubt we will need to have precision better
> than nanoseconds) = 576,460,752 seconds = 9,607,679 minutes = 160,127
> hours = 6,671 days = 18 years.
> 
> We would be screwed if we trace for more than 18 years. ;-)
> 
> That's why I had it as 16 bytes, to be able to hold a full 64 bit
> timestamp (and still be 8 byte aligned). But since we've gone this long
> without needing this, I'm sure a 59 bit absolute timestamp should be
> good enough.
> 

Yeah, I would think it should be good enough, but then I don't
realistically envision a machine with an 18 year uptime with tracing
enabled, maybe someone else does though. ;-)

> >   *
> >   * <= @RINGBUF_TYPE_DATA_TYPE_LEN_MAX:
> >   *				Data record
> > @@ -56,12 +58,12 @@ enum ring_buffer_type {
> >  	RINGBUF_TYPE_DATA_TYPE_LEN_MAX = 28,
> >  	RINGBUF_TYPE_PADDING,
> >  	RINGBUF_TYPE_TIME_EXTEND,
> > -	/* FIXME: RINGBUF_TYPE_TIME_STAMP not implemented */
> >  	RINGBUF_TYPE_TIME_STAMP,
> >  };
> >  
> >  unsigned ring_buffer_event_length(struct ring_buffer_event *event);
> >  void *ring_buffer_event_data(struct ring_buffer_event *event);
> > +u64 ring_buffer_event_time_stamp(struct ring_buffer_event *event);
> >  
> >  /*
> >   * ring_buffer_discard_commit will remove an event that has not
> 
> 
> 
> 
> > @@ -2488,6 +2519,10 @@ static inline void rb_event_discard(struct ring_buffer_event *event)
> >  {
> >  	u64 delta;
> >  
> > +	/* In TIME_STAMP mode, write_stamp is unused, nothing to do */
> 
> No, we still need to keep the write_stamp updated. Sure, it doesn't use
> it, but I do want to have absolute and delta timestamps working
> together in a single buffer. It shouldn't be one or the other. In fact,
> I plan on using it that way for nested events.
> 
> Maybe for this feature we can let it slide. But I will be working on
> fixing that.
> 

OK, great, thanks.

Tom

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web