From: "Steven Rostedt (Google)" <[email protected]>
Instead of using local_add_return() to reserve the ring buffer data,
Mathieu Desnoyers suggested using local_cmpxchg(). This would simplify the
reservation with the time keeping code.
Although, it does not get rid of the double time stamps (before_stamp and
write_stamp), using cmpxchg() does get rid of the more complex case when
an interrupting event occurs between getting the timestamps and reserving
the data, as when that happens, it just tries again instead of dealing
with it.
Before we had:
w = local_read(&tail_page->write);
/* get time stamps */
write = local_add_return(length, &tail_page->write);
if (write - length == w) {
/* do simple case */
} else {
/* do complex case */
}
By switching the local_add_return() to a local_try_cmpxchg() it can now be:
w = local_read(&tail_page->write);
again:
/* get time stamps */
if (!local_try_cmpxchg(&tail_page->write, &w, w + length))
goto again;
/* do simple case */
The benchmarks between the two showed no regressions when trying this:
Enable: CONFIG_TRACEPOINT_BENCHMARK
# trace-cmd record -m 800000 -e benchmark sleep 60
Before the patch:
# trace-cmd report | tail
event_benchmark-944 [003] 1998.910191: benchmark_event: last=150 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=150
event_benchmark-944 [003] 1998.910192: benchmark_event: last=149 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=149
event_benchmark-944 [003] 1998.910193: benchmark_event: last=150 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=150
event_benchmark-944 [003] 1998.910193: benchmark_event: last=150 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=150
event_benchmark-944 [003] 1998.910194: benchmark_event: last=136 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=136
event_benchmark-944 [003] 1998.910194: benchmark_event: last=138 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=138
event_benchmark-944 [003] 1998.910195: benchmark_event: last=150 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=150
event_benchmark-944 [003] 1998.910196: benchmark_event: last=151 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=151
event_benchmark-944 [003] 1998.910196: benchmark_event: last=150 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=150
event_benchmark-944 [003] 1998.910197: benchmark_event: last=152 first=3488 max=1199686 min=124 avg=208 std=39 std^2=1579 delta=152
After the patch:
# trace-cmd report | tail
event_benchmark-848 [004] 171.414716: benchmark_event: last=143 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=143
event_benchmark-848 [004] 171.414717: benchmark_event: last=142 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=142
event_benchmark-848 [004] 171.414718: benchmark_event: last=142 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=142
event_benchmark-848 [004] 171.414718: benchmark_event: last=141 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=141
event_benchmark-848 [004] 171.414719: benchmark_event: last=141 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=141
event_benchmark-848 [004] 171.414719: benchmark_event: last=141 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=141
event_benchmark-848 [004] 171.414720: benchmark_event: last=140 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=140
event_benchmark-848 [004] 171.414721: benchmark_event: last=142 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=142
event_benchmark-848 [004] 171.414721: benchmark_event: last=145 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=145
event_benchmark-848 [004] 171.414722: benchmark_event: last=144 first=14483 max=1155491 min=125 avg=189 std=16 std^2=264 delta=144
It may have even improved!
Suggested-by: Mathieu Desnoyers <[email protected]>
Signed-off-by: Steven Rostedt (Google) <[email protected]>
---
Changes since v2: https://lore.kernel.org/linux-trace-kernel/[email protected]
- Fixed info.field to be info->field
kernel/trace/ring_buffer.c | 103 ++++++++++++-------------------------
1 file changed, 34 insertions(+), 69 deletions(-)
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index fd4bfe3ecf01..6809d085ae98 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -3455,9 +3455,11 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
/* Don't let the compiler play games with cpu_buffer->tail_page */
tail_page = info->tail_page = READ_ONCE(cpu_buffer->tail_page);
- /*A*/ w = local_read(&tail_page->write) & RB_WRITE_MASK;
+ /*A*/ w = local_read(&tail_page->write);
barrier();
rb_time_read(&cpu_buffer->before_stamp, &info->before);
+ /* Read before_stamp only the first time through */
+ again:
rb_time_read(&cpu_buffer->write_stamp, &info->after);
barrier();
info->ts = rb_time_stamp(cpu_buffer->buffer);
@@ -3470,7 +3472,7 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
* absolute timestamp.
* Don't bother if this is the start of a new page (w == 0).
*/
- if (!w) {
+ if (!(w & RB_WRITE_MASK)) {
/* Use the sub-buffer timestamp */
info->delta = 0;
} else if (unlikely(info->before != info->after)) {
@@ -3487,89 +3489,52 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
/*B*/ rb_time_set(&cpu_buffer->before_stamp, info->ts);
- /*C*/ write = local_add_return(info->length, &tail_page->write);
+ /*C*/ if (!local_try_cmpxchg(&tail_page->write, &w, w + info->length)) {
+ if (info->add_timestamp & (RB_ADD_STAMP_FORCE | RB_ADD_STAMP_EXTEND))
+ info->length -= RB_LEN_TIME_EXTEND;
+ goto again;
+ }
- /* set write to only the index of the write */
- write &= RB_WRITE_MASK;
+ /* Set write to the start of this event */
+ write = w & RB_WRITE_MASK;
- tail = write - info->length;
+ /* set tail to the end of the event */
+ tail = write + info->length;
/* See if we shot pass the end of this buffer page */
- if (unlikely(write > cpu_buffer->buffer->subbuf_size)) {
+ if (unlikely(tail > cpu_buffer->buffer->subbuf_size)) {
check_buffer(cpu_buffer, info, CHECK_FULL_PAGE);
- return rb_move_tail(cpu_buffer, tail, info);
+ return rb_move_tail(cpu_buffer, write, info);
}
- if (likely(tail == w)) {
- /* Nothing interrupted us between A and C */
- /*D*/ rb_time_set(&cpu_buffer->write_stamp, info->ts);
- /*
- * If something came in between C and D, the write stamp
- * may now not be in sync. But that's fine as the before_stamp
- * will be different and then next event will just be forced
- * to use an absolute timestamp.
- */
- if (likely(!(info->add_timestamp &
- (RB_ADD_STAMP_FORCE | RB_ADD_STAMP_ABSOLUTE))))
- /* This did not interrupt any time update */
- info->delta = info->ts - info->after;
- else
- /* Just use full timestamp for interrupting event */
- info->delta = info->ts;
- check_buffer(cpu_buffer, info, tail);
- } else {
- u64 ts;
- /* SLOW PATH - Interrupted between A and C */
-
- /* Save the old before_stamp */
- rb_time_read(&cpu_buffer->before_stamp, &info->before);
-
- /*
- * Read a new timestamp and update the before_stamp to make
- * the next event after this one force using an absolute
- * timestamp. This is in case an interrupt were to come in
- * between E and F.
- */
- ts = rb_time_stamp(cpu_buffer->buffer);
- rb_time_set(&cpu_buffer->before_stamp, ts);
-
- barrier();
- /*E*/ rb_time_read(&cpu_buffer->write_stamp, &info->after);
- barrier();
- /*F*/ if (write == (local_read(&tail_page->write) & RB_WRITE_MASK) &&
- info->after == info->before && info->after < ts) {
- /*
- * Nothing came after this event between C and F, it is
- * safe to use info->after for the delta as it
- * matched info->before and is still valid.
- */
- info->delta = ts - info->after;
- } else {
- /*
- * Interrupted between C and F:
- * Lost the previous events time stamp. Just set the
- * delta to zero, and this will be the same time as
- * the event this event interrupted. And the events that
- * came after this will still be correct (as they would
- * have built their delta on the previous event.
- */
- info->delta = 0;
- }
- info->ts = ts;
- info->add_timestamp &= ~RB_ADD_STAMP_FORCE;
- }
+ /* Nothing interrupted us between A and C */
+ /*D*/ rb_time_set(&cpu_buffer->write_stamp, info->ts);
+ /*
+ * If something came in between C and D, the write stamp
+ * may now not be in sync. But that's fine as the before_stamp
+ * will be different and then next event will just be forced
+ * to use an absolute timestamp.
+ */
+ if (likely(!(info->add_timestamp &
+ (RB_ADD_STAMP_FORCE | RB_ADD_STAMP_ABSOLUTE))))
+ /* This did not interrupt any time update */
+ info->delta = info->ts - info->after;
+ else
+ /* Just use full timestamp for interrupting event */
+ info->delta = info->ts;
+ check_buffer(cpu_buffer, info, write);
/*
* If this is the first commit on the page, then it has the same
* timestamp as the page itself.
*/
- if (unlikely(!tail && !(info->add_timestamp &
+ if (unlikely(!write && !(info->add_timestamp &
(RB_ADD_STAMP_FORCE | RB_ADD_STAMP_ABSOLUTE))))
info->delta = 0;
/* We reserved something on the buffer */
- event = __rb_page_index(tail_page, tail);
+ event = __rb_page_index(tail_page, write);
rb_update_event(cpu_buffer, event, info);
local_inc(&tail_page->entries);
@@ -3578,7 +3543,7 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
* If this is the first commit on the page, then update
* its timestamp.
*/
- if (unlikely(!tail))
+ if (unlikely(!write))
tail_page->page->time_stamp = info->ts;
/* account for these added bytes */
--
2.43.0
On Mon, 19 Feb 2024 18:20:32 -0500
Steven Rostedt <[email protected]> wrote:
> Instead of using local_add_return() to reserve the ring buffer data,
> Mathieu Desnoyers suggested using local_cmpxchg(). This would simplify the
> reservation with the time keeping code.
>
> Although, it does not get rid of the double time stamps (before_stamp and
> write_stamp), using cmpxchg() does get rid of the more complex case when
> an interrupting event occurs between getting the timestamps and reserving
> the data, as when that happens, it just tries again instead of dealing
> with it.
>
> Before we had:
>
> w = local_read(&tail_page->write);
> /* get time stamps */
> write = local_add_return(length, &tail_page->write);
> if (write - length == w) {
> /* do simple case */
> } else {
> /* do complex case */
> }
>
> By switching the local_add_return() to a local_try_cmpxchg() it can now be:
>
> w = local_read(&tail_page->write);
> again:
> /* get time stamps */
> if (!local_try_cmpxchg(&tail_page->write, &w, w + length))
> goto again;
>
> /* do simple case */
Something about this logic is causing __rb_next_reserve() to sometimes
always return -EAGAIN and triggering the:
RB_WARN_ON(cpu_buffer, ++nr_loops > 1000)
Which disables the ring buffer.
I'm not sure what it is, but until I do, I'm removing the patch from my
queue.
-- Steve
On 2024-02-20 09:19, Steven Rostedt wrote:
> On Mon, 19 Feb 2024 18:20:32 -0500
> Steven Rostedt <[email protected]> wrote:
>
>> Instead of using local_add_return() to reserve the ring buffer data,
>> Mathieu Desnoyers suggested using local_cmpxchg(). This would simplify the
>> reservation with the time keeping code.
>>
>> Although, it does not get rid of the double time stamps (before_stamp and
>> write_stamp), using cmpxchg() does get rid of the more complex case when
>> an interrupting event occurs between getting the timestamps and reserving
>> the data, as when that happens, it just tries again instead of dealing
>> with it.
>>
>> Before we had:
>>
>> w = local_read(&tail_page->write);
>> /* get time stamps */
>> write = local_add_return(length, &tail_page->write);
>> if (write - length == w) {
>> /* do simple case */
>> } else {
>> /* do complex case */
>> }
>>
>> By switching the local_add_return() to a local_try_cmpxchg() it can now be:
>>
>> w = local_read(&tail_page->write);
>> again:
>> /* get time stamps */
>> if (!local_try_cmpxchg(&tail_page->write, &w, w + length))
>> goto again;
>>
>> /* do simple case */
>
> Something about this logic is causing __rb_next_reserve() to sometimes
> always return -EAGAIN and triggering the:
>
> RB_WARN_ON(cpu_buffer, ++nr_loops > 1000)
>
> Which disables the ring buffer.
>
> I'm not sure what it is, but until I do, I'm removing the patch from my
> queue.
Try resetting the info->add_timestamp flags to add_ts_default on goto again
within __rb_reserve_next().
Thanks,
Mathieu
--
Mathieu Desnoyers
EfficiOS Inc.
https://www.efficios.com
On Tue, 20 Feb 2024 09:50:13 -0500
Mathieu Desnoyers <[email protected]> wrote:
> On 2024-02-20 09:19, Steven Rostedt wrote:
> > On Mon, 19 Feb 2024 18:20:32 -0500
> > Steven Rostedt <[email protected]> wrote:
> >
> >> Instead of using local_add_return() to reserve the ring buffer data,
> >> Mathieu Desnoyers suggested using local_cmpxchg(). This would simplify the
> >> reservation with the time keeping code.
> >>
> >> Although, it does not get rid of the double time stamps (before_stamp and
> >> write_stamp), using cmpxchg() does get rid of the more complex case when
> >> an interrupting event occurs between getting the timestamps and reserving
> >> the data, as when that happens, it just tries again instead of dealing
> >> with it.
> >>
> >> Before we had:
> >>
> >> w = local_read(&tail_page->write);
> >> /* get time stamps */
> >> write = local_add_return(length, &tail_page->write);
> >> if (write - length == w) {
> >> /* do simple case */
> >> } else {
> >> /* do complex case */
> >> }
> >>
> >> By switching the local_add_return() to a local_try_cmpxchg() it can now be:
> >>
> >> w = local_read(&tail_page->write);
> >> again:
> >> /* get time stamps */
> >> if (!local_try_cmpxchg(&tail_page->write, &w, w + length))
> >> goto again;
> >>
> >> /* do simple case */
> >
> > Something about this logic is causing __rb_next_reserve() to sometimes
> > always return -EAGAIN and triggering the:
> >
> > RB_WARN_ON(cpu_buffer, ++nr_loops > 1000)
> >
> > Which disables the ring buffer.
> >
> > I'm not sure what it is, but until I do, I'm removing the patch from my
> > queue.
>
> Try resetting the info->add_timestamp flags to add_ts_default on goto again
> within __rb_reserve_next().
>
I was looking at that too, but I don't know how it will make a difference.
Note, the test that fails is in my test suite, and takes about a half hour
to get there. Running that suite takes up resources (it's my main test
suite for all changes). I'm currently testing other patches so I either
need to figure it out through inspection, or this will need to wait a while.
-- Steve
On Tue, 20 Feb 2024 10:40:23 -0500
Steven Rostedt <[email protected]> wrote:
> > Try resetting the info->add_timestamp flags to add_ts_default on goto again
> > within __rb_reserve_next().
> >
>
> I was looking at that too, but I don't know how it will make a difference.
>
> Note, the test that fails is in my test suite, and takes about a half hour
> to get there. Running that suite takes up resources (it's my main test
> suite for all changes). I'm currently testing other patches so I either
> need to figure it out through inspection, or this will need to wait a while.
I did a bit of debugging and it's just getting weird. It triggers when I
run with the "perf" clock, which is the local_clock() (and this has
CONFIG_HAVE_UNSTABLE_SCHED_CLOCK=y which does some strange paths for
local_clock()).
It appears that on function_graph tracing with perf clock, it fails the
local_cmpxchg a lot! And for some reason, this is causing it to fail the
overflow more often. Well, if it pushes the header page forward too, it
will also cause that to go back and add to the counter.
I tried moving the "again:" to the beginning of the function (after
resetting the add_timestamp flags and length) so that it gets a new
tail_page each time, but that doesn't appear to make a difference either.
It looks like that retry loop in some configs causes it to fail allocation
on the subbuffer over a 1000 times!
Looks like this changes expectations a bit, and will need more design
changes to make it work.
-- Steve