Re: [PATCH v3] ring-buffer: Simplify reservation with try_cmpxchg() loop
On Tue, 20 Feb 2024 10:40:23 -0500 Steven Rostedt 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
Re: [PATCH v3] ring-buffer: Simplify reservation with try_cmpxchg() loop
On Tue, 20 Feb 2024 09:50:13 -0500
Mathieu Desnoyers wrote:
> On 2024-02-20 09:19, Steven Rostedt wrote:
> > On Mon, 19 Feb 2024 18:20:32 -0500
> > Steven Rostedt 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(_page->write);
> >>/* get time stamps */
> >>write = local_add_return(length, _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(_page->write);
> >> again:
> >>/* get time stamps */
> >>if (!local_try_cmpxchg(_page->write, , 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
Re: [PATCH v3] ring-buffer: Simplify reservation with try_cmpxchg() loop
On 2024-02-20 09:19, Steven Rostedt wrote:
On Mon, 19 Feb 2024 18:20:32 -0500
Steven Rostedt 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(_page->write);
/* get time stamps */
write = local_add_return(length, _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(_page->write);
again:
/* get time stamps */
if (!local_try_cmpxchg(_page->write, , 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
Re: [PATCH v3] ring-buffer: Simplify reservation with try_cmpxchg() loop
On Mon, 19 Feb 2024 18:20:32 -0500
Steven Rostedt 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(_page->write);
> /* get time stamps */
> write = local_add_return(length, _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(_page->write);
> again:
> /* get time stamps */
> if (!local_try_cmpxchg(_page->write, , 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
[PATCH v3] ring-buffer: Simplify reservation with try_cmpxchg() loop
From: "Steven Rostedt (Google)"
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(_page->write);
/* get time stamps */
write = local_add_return(length, _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(_page->write);
again:
/* get time stamps */
if (!local_try_cmpxchg(_page->write, , 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 80 -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
Signed-off-by: Steven Rostedt (Google)
---
Changes since v2:
https://lore.kernel.org/linux-trace-kernel/20240219173003.08339...@gandalf.local.home
- 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(_page->write) &
