[PATCH] ring-buffer: set the right timestamp in the slow path of __rb_reserve_next()

[PATCH] ring-buffer: set the right timestamp in the slow path of __rb_reserve_next()

[Andrea Righi]

In the slow path of __rb_reserve_next() a nested event(s) can happen
between evaluating the timestamp delta of the current event and updating
write_stamp via local_cmpxchg(); in this case the delta is not valid
anymore and it should be set to 0 (same timestamp as the interrupting
event), since the event that we are currently processing is not the last
event in the buffer.

Link: https://lwn.net/Articles/831207
Fixes: a389d86f7fd0 ("ring-buffer: Have nested events still record running time stamp")
Signed-off-by: Andrea Righi <andrea.righi@canonical.com>
---
 kernel/trace/ring_buffer.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index dc83b3fa9fe7..5e30e0cdb6ce 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -3287,11 +3287,11 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
 		ts = rb_time_stamp(cpu_buffer->buffer);
 		barrier();
  /*E*/		if (write == (local_read(&tail_page->write) & RB_WRITE_MASK) &&
-		    info->after < ts) {
+		    info->after < ts &&
+		    rb_time_cmpxchg(&cpu_buffer->write_stamp,
+				    info->after, info->ts)) {
 			/* Nothing came after this event between C and E */
 			info->delta = ts - info->after;
-			(void)rb_time_cmpxchg(&cpu_buffer->write_stamp,
-					      info->after, info->ts);
 			info->ts = ts;
 		} else {
 			/*
-- 
2.29.2

Re: [PATCH] ring-buffer: set the right timestamp in the slow path of __rb_reserve_next()

[Steven Rostedt]

On Sat, 28 Nov 2020 10:15:17 +0100
Andrea Righi <andrea.righi@canonical.com> wrote:

> In the slow path of __rb_reserve_next() a nested event(s) can happen
> between evaluating the timestamp delta of the current event and updating
> write_stamp via local_cmpxchg(); in this case the delta is not valid
> anymore and it should be set to 0 (same timestamp as the interrupting
> event), since the event that we are currently processing is not the last
> event in the buffer.
> 
> Link: https://lwn.net/Articles/831207

And it looks like we have a WINNER!

Thanks! It shows someone is paying attention.

There's a few other patches I need to test, but I've queued this up for my
next pull request.

-- Steve


> Fixes: a389d86f7fd0 ("ring-buffer: Have nested events still record running time stamp")
> Signed-off-by: Andrea Righi <andrea.righi@canonical.com>
> ---
>  kernel/trace/ring_buffer.c | 6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index dc83b3fa9fe7..5e30e0cdb6ce 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -3287,11 +3287,11 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
>  		ts = rb_time_stamp(cpu_buffer->buffer);
>  		barrier();
>   /*E*/		if (write == (local_read(&tail_page->write) & RB_WRITE_MASK) &&
> -		    info->after < ts) {
> +		    info->after < ts &&
> +		    rb_time_cmpxchg(&cpu_buffer->write_stamp,
> +				    info->after, info->ts)) {
>  			/* Nothing came after this event between C and E */
>  			info->delta = ts - info->after;
> -			(void)rb_time_cmpxchg(&cpu_buffer->write_stamp,
> -					      info->after, info->ts);
>  			info->ts = ts;
>  		} else {
>  			/*