Re: [RFC][PATCH] ring-buffer: Have nested events still record running time stamp
From: Steven Rostedt
Date: Mon Jun 29 2020 - 20:21:52 EST
On Thu, 25 Jun 2020 15:35:02 -0400 (EDT)
Mathieu Desnoyers <mathieu.desnoyers@xxxxxxxxxxxx> wrote:
> >> So the reservation is not "just" an add instruction, it's actually an
> >> xadd on x86. Is that really faster than a cmpxchg ?
> >
> > I believe the answer is still yes. But I can run some benchmarks to
> > make sure.
>
> This would be interesting to see, because if xadd and cmpxchg have
> similar overhead, then going for a cmpxchg-loop for the space
> reservation could vastly decrease the overall complexity of this
> timestamp+space reservation algorithm.
So I tested this on three different machines to see how it compared. I
applied this patch:
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index c2c0d25ea004..8a7d62375eb3 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -3161,7 +3161,19 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
/*B*/ rb_time_set(&cpu_buffer->before_stamp, info->ts);
+#if 0
/*C*/ write = local_add_return(info->length, &tail_page->write);
+#else
+ {
+ unsigned long expect, result;
+
+ do {
+ expect = local_read(&tail_page->write);
+ write = expect + info->length;
+ result = local_cmpxchg(&tail_page->write, expect, write);
+ } while (expect != result);
+ }
+#endif
/* set write to only the index of the write */
write &= RB_WRITE_MASK;
And tested before and after the results.
To test, I used my fedora 31 kernel config, and enabled
CONFIG_TRACEPOINT_BENCHMARK.
When that trace event is enabled, a kthread is kicked off that runs in
a loop (see kernel/trace/trace_benchmark.c) that basically does:
local_irq_disable();
start = trace_clock_local();
trace_benchmark_event();
end = trace_clock_local();
local_irq_enable();
It takes the delta of end - start. As the first time through is cold
cache it records it separately, and after that it creates a string that
lists the delta of the last event recorded (as it can't make the delta
before it records the end time stamp). The first time stamp (the cold
cache one), the max, min, running average. It also records a running
standard deviation. All numbers are in nanoseconds.
The test was simply doing:
# trace-cmd record -e benchmark:benchmark_event -o trace-tp-bench-{inc|cmpxchg}.dat sleep 3
# trace-cmd report trace-tp-bench-{inc|cmpxchg}.dat | tail
The reason for the tail, is to let the machine settle, as x86 has all
sorts of crazy optimizations there's a lot of noise in the beginning.
Anyway, here's the results of my three machines, and feel free to test
this out yourself.
Going from my fastest to slowest machines:
Machine 1:
model name : Intel(R) Core(TM) i7-3770 CPU @ 3.40GHz
(4 core / 8 logical)
# trace-cmd report trace-tp-bench-inc.dat |tail
event_benchmark-2072 [003] 2234.664661 benchmark_event: last=92 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664662 benchmark_event: last=92 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664662 benchmark_event: last=88 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664663 benchmark_event: last=85 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664663 benchmark_event: last=89 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664664 benchmark_event: last=86 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664664 benchmark_event: last=88 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664665 benchmark_event: last=171 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664665 benchmark_event: last=88 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
event_benchmark-2072 [003] 2234.664666 benchmark_event: last=87 first=2794 max=11707 min=81 avg=93 std=49 std^2=2469
# trace-cmd report trace-tp-bench-cmpxchg.dat |tail
event_benchmark-1924 [000] 499.515711 benchmark_event: last=309 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515711 benchmark_event: last=96 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515712 benchmark_event: last=189 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515713 benchmark_event: last=134 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515713 benchmark_event: last=92 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515714 benchmark_event: last=93 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515714 benchmark_event: last=92 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515715 benchmark_event: last=89 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515715 benchmark_event: last=86 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
event_benchmark-1924 [000] 499.515716 benchmark_event: last=107 first=2955 max=10636 min=81 avg=93 std=73 std^2=5367
Machine 2:
model name : Intel(R) Core(TM) i3-4130 CPU @ 3.40GHz
(2 core / 4 logical)
# trace-cmd report trace-tp-bench-inc.dat |tail
event_benchmark-3179 [001] 606.466907: benchmark_event: last=132 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466907: benchmark_event: last=133 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466908: benchmark_event: last=136 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466909: benchmark_event: last=135 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466909: benchmark_event: last=135 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466910: benchmark_event: last=133 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466911: benchmark_event: last=131 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466912: benchmark_event: last=132 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466913: benchmark_event: last=134 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
event_benchmark-3179 [001] 606.466913: benchmark_event: last=223 first=1463 max=1938 min=115 avg=140 std=36 std^2=1341
# trace-cmd report trace-tp-bench-cmpxchg.dat |tail
event_benchmark-3169 [001] 477.024485: benchmark_event: last=102 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024486: benchmark_event: last=103 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024486: benchmark_event: last=131 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024487: benchmark_event: last=104 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024487: benchmark_event: last=181 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024488: benchmark_event: last=195 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024489: benchmark_event: last=155 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024489: benchmark_event: last=102 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024490: benchmark_event: last=166 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
event_benchmark-3169 [001] 477.024490: benchmark_event: last=256 first=1820 max=12210 min=95 avg=266 std=75 std^2=5768
Machine 3:
model name : Intel(R) Core(TM)2 Quad CPU Q9450 @ 2.66GHz
( 4 cores / no hyperthreading enabled )
# trace-cmd report trace-tp-bench-inc.dat| tail
event_benchmark-2686 [000] 860.217674: benchmark_event: last=195 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217675: benchmark_event: last=196 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217676: benchmark_event: last=196 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217677: benchmark_event: last=193 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217679: benchmark_event: last=195 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217680: benchmark_event: last=195 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217681: benchmark_event: last=195 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217682: benchmark_event: last=193 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217683: benchmark_event: last=196 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
event_benchmark-2686 [000] 860.217684: benchmark_event: last=195 first=2527 max=4571 min=186 avg=264 std=144 std^2=20943
# trace-cmd report trace-tp-bench-cmpxchg.dat| tail
event_benchmark-2393 [003] 380.342603: benchmark_event: last=199 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342604: benchmark_event: last=196 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342606: benchmark_event: last=201 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342607: benchmark_event: last=195 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342608: benchmark_event: last=195 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342609: benchmark_event: last=198 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342610: benchmark_event: last=199 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342611: benchmark_event: last=196 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342613: benchmark_event: last=196 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
event_benchmark-2393 [003] 380.342614: benchmark_event: last=199 first=2707 max=3215 min=189 avg=297 std=163 std^2=26612
Not that big of a difference, but there is a difference. And the
standard deviation appears to be better, which would make sense as an
local_add_return() needs no repeat on collision.
-- Steve