* rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching @ 2013-11-01 17:19 Petr Mladek 2013-11-04 17:02 ` Paul E. McKenney 2014-08-22 3:35 ` Fengguang Wu 0 siblings, 2 replies; 9+ messages in thread From: Petr Mladek @ 2013-11-01 17:19 UTC (permalink / raw) To: Paul E. McKenney Cc: Tibor Billes, Josh Triplett, Steven Rostedt, Jiri Kosina, linux-kernel [-- Attachment #1: Type: text/plain, Size: 1086 bytes --] Hi, I am doing some clean up in x86 ftrace code. I check the performance by switching between different tracers and by enabling and disabling them. The operation has started to be much slower after rebasing on the kernel tip tree. Bisecting has shown that the difference was caused by the commit c229828ca6bc62d6c654 (rcu: Throttle rcu_try_advance_all_cbs() execution) The following times are from Intel 2xCore i7-3770 CPU @ 3.40GHz when calling the attached test script (time ./test-ftrace). It 100x switches between "function" and "nop" tracer. It also enables and disables the tracer each time. Results with the commit c229828ca6bc62d6c654: real 0m49.393s 0m49.632s 0m49.359s user 0m0.004s 0m0.000s 0m0.004s sys 0m0.996s 0m0.880s 0m0.892s Results after reverting the commit c229828ca6bc62d6c654: real 0m35.320s 0m35.687s 0m35.920s user 0m0.004s 0m0.004s 0m0.000s sys 0m1.140s 0m1.208s 0m1.152s I might do some more debugging on Monday. I wonder if you have any hints or ideas. Best Regards, Petr [-- Attachment #2: test-ftrace --] [-- Type: application/x-shellscript, Size: 318 bytes --] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching 2013-11-01 17:19 rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching Petr Mladek @ 2013-11-04 17:02 ` Paul E. McKenney 2013-11-05 15:43 ` Petr Mladek 2014-08-22 3:35 ` Fengguang Wu 1 sibling, 1 reply; 9+ messages in thread From: Paul E. McKenney @ 2013-11-04 17:02 UTC (permalink / raw) To: Petr Mladek Cc: Tibor Billes, Josh Triplett, Steven Rostedt, Jiri Kosina, linux-kernel On Fri, Nov 01, 2013 at 06:19:44PM +0100, Petr Mladek wrote: > Hi, > > I am doing some clean up in x86 ftrace code. I check the performance by > switching between different tracers and by enabling and disabling them. > > The operation has started to be much slower after rebasing on the > kernel tip tree. Bisecting has shown that the difference was caused by > the commit c229828ca6bc62d6c654 (rcu: Throttle > rcu_try_advance_all_cbs() execution) > > The following times are from Intel 2xCore i7-3770 CPU @ 3.40GHz when > calling the attached test script (time ./test-ftrace). It 100x switches > between "function" and "nop" tracer. It also enables and disables the > tracer each time. > > Results with the commit c229828ca6bc62d6c654: > > real 0m49.393s 0m49.632s 0m49.359s > user 0m0.004s 0m0.000s 0m0.004s > sys 0m0.996s 0m0.880s 0m0.892s > > > Results after reverting the commit c229828ca6bc62d6c654: > > real 0m35.320s 0m35.687s 0m35.920s > user 0m0.004s 0m0.004s 0m0.000s > sys 0m1.140s 0m1.208s 0m1.152s > > > I might do some more debugging on Monday. I wonder if you have any > hints or ideas. Hello, Petr, This is a slowpath, and that commit did fix a real bug, so I am OK with this modest slowdown. That said, if you have a workload where this is a problem, please try building with CONFIG_RCU_FAST_NO_HZ=n. The fact that this commit had any effect at all leads me to believe that you used CONFIG_RCU_FAST_NO_HZ=y. Thanx, Paul ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching 2013-11-04 17:02 ` Paul E. McKenney @ 2013-11-05 15:43 ` Petr Mladek 2013-11-05 16:25 ` Paul E. McKenney 0 siblings, 1 reply; 9+ messages in thread From: Petr Mladek @ 2013-11-05 15:43 UTC (permalink / raw) To: Paul E. McKenney Cc: Tibor Billes, Josh Triplett, Steven Rostedt, Jiri Kosina, linux-kernel [-- Attachment #1: Type: text/plain, Size: 1791 bytes --] Hello Paul, Paul E. McKenney píše v Po 04. 11. 2013 v 09:02 -0800: > On Fri, Nov 01, 2013 at 06:19:44PM +0100, Petr Mladek wrote: > > Hi, > > > > I am doing some clean up in x86 ftrace code. I check the performance by > > switching between different tracers and by enabling and disabling them. > > > > The operation has started to be much slower after rebasing on the > > kernel tip tree. Bisecting has shown that the difference was caused by > > the commit c229828ca6bc62d6c654 (rcu: Throttle > > rcu_try_advance_all_cbs() execution) > This is a slowpath, and that commit did fix a real bug, so I am OK with > this modest slowdown. > > That said, if you have a workload where this is a problem, please try > building with CONFIG_RCU_FAST_NO_HZ=n. The fact that this commit had any > effect at all leads me to believe that you used CONFIG_RCU_FAST_NO_HZ=y. Yes, I used CONFIG_RCU_FAST_NO_HZ=y. I am not aware of any other workload with this problem. I tried few benchmarks: dbench, unixbench, and aim. They did not show any considerable difference with and without the commit. If you are interested you might find more details in the attached logs. Just for record, I also checked how the ftrace test was affected by the commit under various system load. The speed difference was there if at least one CPU was idle. But the test was slower on idle system even without the patch. Hence this is not the only change that causes some difference. See the attached "ftrace" file for more details. I am still a bit curious why ftrace code is so special here and why it does not affect the other benchmarks. Anyway, I agree that ftrace change/start/stop operations are not time critical and the extra delay might be worth fixing the other bug. I am fine with it :-) Best Regards, Petr [-- Attachment #2: aim9 --] [-- Type: application/x-gmc-link, Size: 30205 bytes --] [-- Attachment #3: dbench --] [-- Type: application/x-gmc-link, Size: 6430 bytes --] [-- Attachment #4: ftrace --] [-- Type: text/plain, Size: 2066 bytes --] test: ftrace CPU: Intel(R) Core(TM)2 Duo CPU E8400 @ 3.00GHz RAM: 4GB Started using the command: time ./test-ftrace Where test-ftrace is: --- cut --- #!/bin/bash echo "Testing ftrace - begin" cd /sys/kernel/debug/tracing count=0 while test $count -lt 100 ; do for tracer in function nop ; do echo $tracer >current_tracer echo 1 >tracing_on echo 0 >tracing_on done count=$(($count + 1)) done cd - echo "Testing ftrace - end" --- cut --- and the load was generated using the script make-load: --- cut --- #!/bin/bash a=1 while true ; do a=$(($a+1)) done --- cut --- Now, results with no load on the system; with the commit c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() execution) real 0m49.393s 0m49.632s 0m49.359 user 0m0.004s 0m0.000s 0m0.004s sys 0m0.996s 0m0.880s 0m0.892s and with reverted c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() execution) real 0m35.320s 0m35.687s 0m35.920s user 0m0.004s 0m0.004s 0m0.000s sys 0m1.140s 0m1.208s 0m1.152s --- Results with 100% load on one CPU and no load on 2nd CPU (started the script make-load once) with c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() execution) real 0m44.964s 0m45.083s 0m45.171s user 0m0.000s 0m0.000s 0m0.004s sys 0m1.580s 0m1.612s 0m1.576s and with reverted c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() execution) real 0m30.816s 0m31.326s 0m31.191s user 0m0.004s 0m0.004s 0m0.008s sys 0m1.240s 0m1.248s 0m1.232s --- Results with 100% load on both CPUs (started script make-load twice) with c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() execution) real 0m20.294s 0m20.538s 0m20.470s user 0m0.004s 0m0.000s 0m0.000s sys 0m1.284s 0m1.388s 0m1.612s and with reverted c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() execution) real 0m20.305s 0m20.056s 0m20.259 user 0m0.000s 0m0.000s 0m0.000s sys 0m1.416s 0m1.452s 0m1.560s [-- Attachment #5: unixbench --] [-- Type: application/x-gmc-link, Size: 4541 bytes --] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching 2013-11-05 15:43 ` Petr Mladek @ 2013-11-05 16:25 ` Paul E. McKenney 0 siblings, 0 replies; 9+ messages in thread From: Paul E. McKenney @ 2013-11-05 16:25 UTC (permalink / raw) To: Petr Mladek Cc: Tibor Billes, Josh Triplett, Steven Rostedt, Jiri Kosina, linux-kernel On Tue, Nov 05, 2013 at 04:43:06PM +0100, Petr Mladek wrote: > Hello Paul, > > Paul E. McKenney píše v Po 04. 11. 2013 v 09:02 -0800: > > On Fri, Nov 01, 2013 at 06:19:44PM +0100, Petr Mladek wrote: > > > Hi, > > > > > > I am doing some clean up in x86 ftrace code. I check the performance by > > > switching between different tracers and by enabling and disabling them. > > > > > > The operation has started to be much slower after rebasing on the > > > kernel tip tree. Bisecting has shown that the difference was caused by > > > the commit c229828ca6bc62d6c654 (rcu: Throttle > > > rcu_try_advance_all_cbs() execution) > > > This is a slowpath, and that commit did fix a real bug, so I am OK with > > this modest slowdown. > > > > That said, if you have a workload where this is a problem, please try > > building with CONFIG_RCU_FAST_NO_HZ=n. The fact that this commit had any > > effect at all leads me to believe that you used CONFIG_RCU_FAST_NO_HZ=y. > > Yes, I used CONFIG_RCU_FAST_NO_HZ=y. > > I am not aware of any other workload with this problem. I tried few > benchmarks: dbench, unixbench, and aim. They did not show any > considerable difference with and without the commit. If you are > interested you might find more details in the attached logs. > > Just for record, I also checked how the ftrace test was affected by the > commit under various system load. The speed difference was there if at > least one CPU was idle. But the test was slower on idle system even > without the patch. Hence this is not the only change that causes some > difference. See the attached "ftrace" file for more details. Ah, the joys of energy efficiency! ;-) If the system is entirely non-idle, each CPU will respond to RCU in a timely fashion. However, RCU cannot be permitted to interrupt or in any way disturb an idle CPU, most especially on a battery-powered system. To do so would completely destroy energy efficiency and battery lifetime. Instead, idle CPUs leave evidence of their idleness in per-CPU variables, and RCU must check these variables for any CPUs that do not respond in a timely fashion. Of course, it would not do for RCU to be in a busy-waiting loop continuously checking these variables. Instead, RCU checks them after a three-jiffy delay, which can be tuned if desired using the rcutree.jiffies_till_first_fqs kernel boot parameter. You can even set it to zero if you like, which should speed up your ftrace test significantly on idle systems. You might also tune the rcutree.jiffies_till_next_fqs kernel boot parameter, which governs the time delay until the second and subsequent checks for a given RCU grace period. The reason that the change mostly affected idle systems is that CONFIG_RCU_FAST_NO_HZ=y (and thus the change to its code) affects the transitions to and from idle. If your system is never idle, then CONFIG_RCU_FAST_NO_HZ=y will have no effect whatsoever. > I am still a bit curious why ftrace code is so special here and why it > does not affect the other benchmarks. Anyway, I agree that ftrace > change/start/stop operations are not time critical and the extra delay > might be worth fixing the other bug. I am fine with it :-) The ftrace code makes heavy use of RCU updates when enabling and disabling things, which makes its performance quite sensitive to grace-period duration, and (as you saw) grace-period duration is increased somewhat by CONFIG_RCU_FAST_NO_HZ=y. This trade of increased energy efficiency for longer grace-period duration is the right trade for most systems. Other systems can use CONFIG_RCU_FAST_NO_HZ=n and/or tune the rcutree.jiffies_till_first_fqs and rcutree.jiffies_till_next_fqs kernel boot parameters. Hey, you asked! ;-) Thanx, Paul > Best Regards, > Petr > test: ftrace > CPU: Intel(R) Core(TM)2 Duo CPU E8400 @ 3.00GHz > RAM: 4GB > > Started using the command: > > time ./test-ftrace > > Where test-ftrace is: > > --- cut --- > #!/bin/bash > > echo "Testing ftrace - begin" > cd /sys/kernel/debug/tracing > > count=0 > while test $count -lt 100 ; do > for tracer in function nop ; do > echo $tracer >current_tracer > echo 1 >tracing_on > echo 0 >tracing_on > done > count=$(($count + 1)) > done > > cd - > echo "Testing ftrace - end" > --- cut --- > > and the load was generated using the script make-load: > > --- cut --- > #!/bin/bash > > a=1 > while true ; do > a=$(($a+1)) > done > --- cut --- > > Now, results with no load on the system; with the commit c229828ca6bc62d > (rcu: Throttle rcu_try_advance_all_cbs() execution) > > real 0m49.393s 0m49.632s 0m49.359 > user 0m0.004s 0m0.000s 0m0.004s > sys 0m0.996s 0m0.880s 0m0.892s > > and with reverted c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() > execution) > > real 0m35.320s 0m35.687s 0m35.920s > user 0m0.004s 0m0.004s 0m0.000s > sys 0m1.140s 0m1.208s 0m1.152s > > --- > > Results with 100% load on one CPU and no load on 2nd CPU (started the script > make-load once) with c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() > execution) > > real 0m44.964s 0m45.083s 0m45.171s > user 0m0.000s 0m0.000s 0m0.004s > sys 0m1.580s 0m1.612s 0m1.576s > > and with reverted c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() > execution) > > real 0m30.816s 0m31.326s 0m31.191s > user 0m0.004s 0m0.004s 0m0.008s > sys 0m1.240s 0m1.248s 0m1.232s > > --- > > Results with 100% load on both CPUs (started script make-load twice) > with c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() execution) > > real 0m20.294s 0m20.538s 0m20.470s > user 0m0.004s 0m0.000s 0m0.000s > sys 0m1.284s 0m1.388s 0m1.612s > > and with reverted c229828ca6bc62d (rcu: Throttle rcu_try_advance_all_cbs() > execution) > > real 0m20.305s 0m20.056s 0m20.259 > user 0m0.000s 0m0.000s 0m0.000s > sys 0m1.416s 0m1.452s 0m1.560s ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching 2013-11-01 17:19 rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching Petr Mladek 2013-11-04 17:02 ` Paul E. McKenney @ 2014-08-22 3:35 ` Fengguang Wu 2014-08-22 8:32 ` Petr Mládek 1 sibling, 1 reply; 9+ messages in thread From: Fengguang Wu @ 2014-08-22 3:35 UTC (permalink / raw) To: Petr Mladek Cc: Paul E. McKenney, Tibor Billes, Josh Triplett, Steven Rostedt, Jiri Kosina, linux-kernel, Wanlong Gao [-- Attachment #1: Type: text/plain, Size: 344 bytes --] Hi Petr, Sorry for picking up this old thread, but I noticed your attached ftrace test script and would like to ask for your permission to include it in https://git.kernel.org/cgit/linux/kernel/git/wfg/lkp-tests.git which is GPLv2. If you kindly agree, I'll run it actively for testing the upstream linux kernels. Thanks, Fengguang [-- Attachment #2: test-ftrace --] [-- Type: application/x-shellscript, Size: 318 bytes --] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching 2014-08-22 3:35 ` Fengguang Wu @ 2014-08-22 8:32 ` Petr Mládek 2014-08-22 11:43 ` Fengguang Wu 0 siblings, 1 reply; 9+ messages in thread From: Petr Mládek @ 2014-08-22 8:32 UTC (permalink / raw) To: Fengguang Wu Cc: Paul E. McKenney, Tibor Billes, Josh Triplett, Steven Rostedt, Jiri Kosina, linux-kernel, Wanlong Gao On Fri 2014-08-22 11:35:29, Fengguang Wu wrote: > Hi Petr, > > Sorry for picking up this old thread, but I noticed your attached > ftrace test script and would like to ask for your permission to > include it in > > https://git.kernel.org/cgit/linux/kernel/git/wfg/lkp-tests.git > > which is GPLv2. If you kindly agree, I'll run it actively for testing > the upstream linux kernels. Sure. Feel free to use the test script under GPLv2 license. Best Regards, Petr ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching 2014-08-22 8:32 ` Petr Mládek @ 2014-08-22 11:43 ` Fengguang Wu 2014-09-17 14:42 ` Steven Rostedt 0 siblings, 1 reply; 9+ messages in thread From: Fengguang Wu @ 2014-08-22 11:43 UTC (permalink / raw) To: Petr Mládek Cc: Paul E. McKenney, Tibor Billes, Josh Triplett, Steven Rostedt, Jiri Kosina, linux-kernel, Wanlong Gao On Fri, Aug 22, 2014 at 10:32:57AM +0200, Petr Mládek wrote: > On Fri 2014-08-22 11:35:29, Fengguang Wu wrote: > > Hi Petr, > > > > Sorry for picking up this old thread, but I noticed your attached > > ftrace test script and would like to ask for your permission to > > include it in > > > > https://git.kernel.org/cgit/linux/kernel/git/wfg/lkp-tests.git > > > > which is GPLv2. If you kindly agree, I'll run it actively for testing > > the upstream linux kernels. > > Sure. Feel free to use the test script under GPLv2 license. Great, thank you very much! Fengguang ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching 2014-08-22 11:43 ` Fengguang Wu @ 2014-09-17 14:42 ` Steven Rostedt 2014-09-18 12:45 ` Fengguang Wu 0 siblings, 1 reply; 9+ messages in thread From: Steven Rostedt @ 2014-09-17 14:42 UTC (permalink / raw) To: Fengguang Wu Cc: Petr Mládek, Paul E. McKenney, Tibor Billes, Josh Triplett, Jiri Kosina, linux-kernel, Wanlong Gao, Masami Hiramatsu On Fri, 22 Aug 2014 19:43:02 +0800 Fengguang Wu <fengguang.wu@intel.com> wrote: > On Fri, Aug 22, 2014 at 10:32:57AM +0200, Petr Mládek wrote: > > On Fri 2014-08-22 11:35:29, Fengguang Wu wrote: > > > Hi Petr, > > > > > > Sorry for picking up this old thread, but I noticed your attached > > > ftrace test script and would like to ask for your permission to > > > include it in > > > > > > https://git.kernel.org/cgit/linux/kernel/git/wfg/lkp-tests.git > > > > > > which is GPLv2. If you kindly agree, I'll run it actively for testing > > > the upstream linux kernels. > > > > Sure. Feel free to use the test script under GPLv2 license. > > Great, thank you very much! > > Fengguang Sorry for the very late reply, I've been on vacation and then had some medical issues. Note, I'm working with Masami to include lots of ftrace tests that will supersede this script. The tests will be included in tools/testing/selftests. Look for the subject "ftracetest". -- Steve ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching 2014-09-17 14:42 ` Steven Rostedt @ 2014-09-18 12:45 ` Fengguang Wu 0 siblings, 0 replies; 9+ messages in thread From: Fengguang Wu @ 2014-09-18 12:45 UTC (permalink / raw) To: Steven Rostedt Cc: Petr Mládek, Paul E. McKenney, Tibor Billes, Josh Triplett, Jiri Kosina, linux-kernel, Wanlong Gao, Masami Hiramatsu HI Steven, On Wed, Sep 17, 2014 at 10:42:51AM -0400, Steven Rostedt wrote: > On Fri, 22 Aug 2014 19:43:02 +0800 > Fengguang Wu <fengguang.wu@intel.com> wrote: > > > On Fri, Aug 22, 2014 at 10:32:57AM +0200, Petr Mládek wrote: > > > On Fri 2014-08-22 11:35:29, Fengguang Wu wrote: > > > > Hi Petr, > > > > > > > > Sorry for picking up this old thread, but I noticed your attached > > > > ftrace test script and would like to ask for your permission to > > > > include it in > > > > > > > > https://git.kernel.org/cgit/linux/kernel/git/wfg/lkp-tests.git > > > > > > > > which is GPLv2. If you kindly agree, I'll run it actively for testing > > > > the upstream linux kernels. > > > > > > Sure. Feel free to use the test script under GPLv2 license. > > > > Great, thank you very much! > > > > Fengguang > > Sorry for the very late reply, I've been on vacation and then had some > medical issues. > > Note, I'm working with Masami to include lots of ftrace tests that will > supersede this script. The tests will be included in > tools/testing/selftests. Look for the subject "ftracetest". Yes I just see the patches from Masami. We'll add them to the LKP test suites. Thank you very much for letting me know! Regards, Fengguang ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2014-09-18 12:45 UTC | newest] Thread overview: 9+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2013-11-01 17:19 rcu: Throttle rcu_try_advance_all_cbs() execution causes visible slowdown in ftrace switching Petr Mladek 2013-11-04 17:02 ` Paul E. McKenney 2013-11-05 15:43 ` Petr Mladek 2013-11-05 16:25 ` Paul E. McKenney 2014-08-22 3:35 ` Fengguang Wu 2014-08-22 8:32 ` Petr Mládek 2014-08-22 11:43 ` Fengguang Wu 2014-09-17 14:42 ` Steven Rostedt 2014-09-18 12:45 ` Fengguang Wu
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox