| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Fri, 25 Jul 2014 16:15:35 -0700 From: "Paul E. McKenney" <paulmck@...ux.vnet.ibm.com> To: Pranith Kumar <bobby.prani@...il.com> Cc: Josh Triplett <josh@...htriplett.org>, Steven Rostedt <rostedt@...dmis.org>, Mathieu Desnoyers <mathieu.desnoyers@...icios.com>, Lai Jiangshan <laijs@...fujitsu.com>, "open list:READ-COPY UPDATE..." <linux-kernel@...r.kernel.org> Subject: Re: [RFC PATCH 1/1] rcu: Use rcu_gp_kthread_wake() to wake up kthreads On Fri, Jul 25, 2014 at 06:23:41PM -0400, Pranith Kumar wrote: > On Fri, Jul 25, 2014 at 11:02 AM, Paul E. McKenney > <paulmck@...ux.vnet.ibm.com> wrote: > > On Fri, Jul 25, 2014 at 02:24:34AM -0400, Pranith Kumar wrote: > >> On Fri, Jul 25, 2014 at 1:06 AM, Pranith Kumar <bobby.prani@...il.com> wrote: > >> > >> > > >> > In rcu_report_qs_rsp(), I added a pr_info() call testing if any of the above > >> > conditions is true, in which case we can avoid calling wake_up(). It turns out > >> > that quite a few actually are. Most of the cases where we can avoid is condition 2 > >> > above and condition 1 also occurs quite often. Condition 3 never happens. > >> > > >> > >> A little more data. On an idle system there are about 2000 unnecessary > >> wake_up() calls every 5 minutes with the most common trace being the > >> follows: > >> > >> [Fri Jul 25 02:05:49 2014] [<ffffffff8109f7c5>] rcu_report_qs_rnp+0x285/0x2c0 > >> [Fri Jul 25 02:05:49 2014] [<ffffffff81838c09>] ? schedule_timeout+0x159/0x270 > >> [Fri Jul 25 02:05:49 2014] [<ffffffff8109fa21>] force_qs_rnp+0x111/0x190 > >> [Fri Jul 25 02:05:49 2014] [<ffffffff810a02c0>] ? synchronize_rcu_bh+0x50/0x50 > >> [Fri Jul 25 02:05:49 2014] [<ffffffff810a2e5f>] rcu_gp_kthread+0x85f/0xa70 > >> [Fri Jul 25 02:05:49 2014] [<ffffffff81086060>] ? __wake_up_sync+0x20/0x20 > >> [Fri Jul 25 02:05:49 2014] [<ffffffff810a2600>] ? rcu_barrier+0x20/0x20 > >> [Fri Jul 25 02:05:49 2014] [<ffffffff8106b4fb>] kthread+0xdb/0x100 > >> [<ffffffff8106b420>]?kthread_create_on_node+0x180/0x180 > >> [Fri Jul 25 02:05:49 2014] [<ffffffff81839dac>] ret_from_fork+0x7c/0xb0 > >> [<ffffffff8106b420>] ?kthread_create_on_node+0x180/0x180 > >> > >> With rcutorture, there are about 2000 unnecessary wake_ups() every 3 > >> minutes with the most common trace being: > >> > >> [Fri Jul 25 02:18:30 2014] [<ffffffff8109f7c5>] rcu_report_qs_rnp+0x285/0x2c0 > >> [Fri Jul 25 02:18:30 2014] [<ffffffff81078b15>] ? __update_cpu_load+0xe5/0x140 > >> [<ffffffffa09dc230>] ?rcu_read_delay+0x50/0x80 [rcutorture] > >> [<ffffffff810a3728>]rcu_process_callbacks+0x6b8/0x7e0 > > > > Good to see the numbers!!! > > > > But to evaluate this analytically, we should compare the overhead of the > > wake_up() with the overhead of the extra checks in rcu_gp_kthread_wake(), > > and then compare the number of unnecessary wake_up()s to the number of > > calls to rcu_gp_kthread_wake() added by this patch. This means that we > > need more numbers. > > > > For example, suppose that the extra checks cost 10ns on average, and that > > a unnecessary wake_up() costs 1us on average, to that each wake_up() > > is on average 100 times more expensive than the extra checks. Then it > > makes sense to ask whether the saved wake_up() save more time than the > > extra tests cost. Turning the arithmetic crank says that if more than 1% > > of the wake_up()s are unnecessary, we should add the checks. > > > > This means that if there are fewer than 200,000 grace periods in each > > of the time periods, then your patch really would provide performance > > benefits. I bet that there are -way- fewer than 200,000 grace periods in > > each of the time periods, but why don't you build with RCU_TRACE and look > > at the "rcugp" file in RCU's debugfs hierarchy? Or just periodically > > print out the rcu_state ->completed field? > > > > I put some debugging code to see how many unnecessary wake ups were > being generated in rcu_report_qs_rsp(). I ran both with and without > rcutorture running. Here are the results > > Without rcutorture: > > [ 14.839214] Total:2000, unnecessary:2000, case1:1741, case2:2000, case3:0 > [ 224.284633] Total:4000, unnecessary:4000, case1:3652, case2:4000, case3:0 > [ 244.159021] Total:6000, unnecessary:6000, case1:5539, case2:6000, case3:0 > [ 260.522175] Total:8000, unnecessary:8000, case1:7447, case2:8000, case3:0 > [ 268.293058] Total:10000, unnecessary:10000, case1:9317, case2:10000, case3:0 > [ 275.962033] Total:12000, unnecessary:12000, case1:11159, case2:12000, case3:0 > [ 287.411032] Total:14000, unnecessary:14000, case1:13008, case2:14000, case3:0 > [ 304.868334] Total:16000, unnecessary:16000, case1:14885, case2:16000, case3:0 > [ 318.090930] Total:18000, unnecessary:18000, case1:16747, case2:18000, case3:0 > [ 333.423876] Total:20000, unnecessary:20000, case1:18631, case2:20000, case3:0 > [ 346.775399] Total:22000, unnecessary:22000, case1:20502, case2:22000, case3:0 > [ 362.867751] Total:24000, unnecessary:24000, case1:22386, case2:24000, case3:0 > [ 376.777817] Total:26000, unnecessary:26000, case1:24251, case2:26000, case3:0 > [ 391.839994] Total:28000, unnecessary:28000, case1:26118, case2:28000, case3:0 > [ 406.559406] Total:30000, unnecessary:30000, case1:27983, case2:30000, case3:0 > [ 419.973867] Total:32000, unnecessary:32000, case1:29855, case2:32000, case3:0 > [ 435.080002] Total:34000, unnecessary:34000, case1:31740, case2:34000, case3:0 > [ 449.077018] Total:36000, unnecessary:36000, case1:33588, case2:36000, case3:0 > [ 464.418942] Total:38000, unnecessary:38000, case1:35460, case2:38000, case3:0 > [ 478.654755] Total:40000, unnecessary:40000, case1:37326, case2:40000, case3:0 > [ 494.650198] Total:42000, unnecessary:42000, case1:39232, case2:42000, case3:0 > [ 508.594240] Total:44000, unnecessary:44000, case1:41134, case2:44000, case3:0 > [ 524.273907] Total:46000, unnecessary:46000, case1:43039, case2:46000, case3:0 > [ 537.227731] Total:48000, unnecessary:48000, case1:44916, case2:48000, case3:0 > [ 552.963362] Total:50000, unnecessary:50000, case1:46805, case2:50000, case3:0 > [ 567.333075] Total:52000, unnecessary:52000, case1:48662, case2:52000, case3:0 > [ 581.811693] Total:54000, unnecessary:54000, case1:50550, case2:54000, case3:0 > [ 596.404233] Total:56000, unnecessary:56000, case1:52417, case2:56000, case3:0 > [ 610.249344] Total:58000, unnecessary:58000, case1:54309, case2:58000, case3:0 > [ 625.682220] Total:60000, unnecessary:60000, case1:56190, case2:60000, case3:0 > [ 640.784361] Total:62000, unnecessary:62000, case1:58069, case2:62000, case3:0 > [ 656.142299] Total:64000, unnecessary:64000, case1:59953, case2:64000, case3:0 > [ 670.026376] Total:66000, unnecessary:66000, case1:61827, case2:66000, case3:0 > [ 685.972862] Total:68000, unnecessary:68000, case1:63696, case2:68000, case3:0 > > > > With rcutorture, the last lines(time makes the line wrap, so removed it): > > Total:182000, unnecessary:182000, case1:171241, case2:182000, case3:0 > Total:184000, unnecessary:184000, case1:173127, case2:184000, case3:0 > Total:186000, unnecessary:186000, case1:174992, case2:186000, case3:0 > Total:188000, unnecessary:188000, case1:176870, case2:188000, case3:0 > Total:190000, unnecessary:190000, case1:178721, case2:190000, case3:0 > Total:192000, unnecessary:192000, case1:180606, case2:192000, case3:0 > Total:194000, unnecessary:194000, case1:182466, case2:194000, case3:0 > Total:196000, unnecessary:196000, case1:184330, case2:196000, case3:0 > Total:198000, unnecessary:198000, case1:186195, case2:198000, case3:0 > Total:200000, unnecessary:200000, case1:188056, case2:200000, case3:0 > Total:202000, unnecessary:202000, case1:189938, case2:202000, case3:0 > Total:204000, unnecessary:204000, case1:190740, case2:204000, case3:0 > Total:206000, unnecessary:206000, case1:190755, case2:206000, case3:0 > Total:208000, unnecessary:208000, case1:190768, case2:208000, case3:0 > Total:210000, unnecessary:210000, case1:190782, case2:210000, case3:0 > Total:212000, unnecessary:212000, case1:190796, case2:212000, case3:0 > Total:214000, unnecessary:214000, case1:190812, case2:214000, case3:0 > Total:216000, unnecessary:216000, case1:190827, case2:216000, case3:0 > Total:218000, unnecessary:218000, case1:190850, case2:218000, case3:0 > Total:220000, unnecessary:220000, case1:190862, case2:220000, case3:0 > Total:222000, unnecessary:222000, case1:190878, case2:222000, case3:0 > Total:224000, unnecessary:224000, case1:190893, case2:224000, case3:0 > Total:226000, unnecessary:226000, case1:190906, case2:226000, case3:0 > Total:228000, unnecessary:228000, case1:190918, case2:228000, case3:0 > Total:230000, unnecessary:230000, case1:190930, case2:230000, case3:0 > Total:232000, unnecessary:232000, case1:190940, case2:232000, case3:0 > Total:234000, unnecessary:234000, case1:190953, case2:234000, case3:0 > Total:236000, unnecessary:236000, case1:190965, case2:236000, case3:0 > Total:238000, unnecessary:238000, case1:190975, case2:238000, case3:0 > Total:240000, unnecessary:240000, case1:190989, case2:240000, case3:0 > Total:242000, unnecessary:242000, case1:191008, case2:242000, case3:0 > Total:244000, unnecessary:244000, case1:191019, case2:244000, case3:0 > Total:246000, unnecessary:246000, case1:192344, case2:246000, case3:0 > Total:248000, unnecessary:248000, case1:194221, case2:248000, case3:0 > Total:250000, unnecessary:250000, case1:196099, case2:250000, case3:0 > Total:252000, unnecessary:252000, case1:198015, case2:252000, case3:0 > Total:254000, unnecessary:254000, case1:199913, case2:254000, case3:0 > Total:256000, unnecessary:256000, case1:201784, case2:256000, case3:0 > > > Here total is the total number of times we enter th function rcu_report_qs_rsp() > and unnecessary is the times we call wake_up() unnecessarily. > case1, 2, 3 are the cases I listed above. > > Note that the frequency has gone way up than before, I am not sure why that is. > > *ALL* the wakeups seem to be unnecessary from that location. And the > main reason is that gp_flags is 0. > > My rcugp file has the following: > > completed=257515 gpnum=257516 age=1 max=1684 > > Thoughts? Hard to believe in the rcutorture case. My guess was that rcutorture was doing about 9000 wakeups, 2000 of which were unnecessary. Which would of course still tilt things very much in favor of your patch. I am not surprised in the mostly-idle case, as the RCU grace-period kthread would most likely be the one ending the grace period, which would therefore almost always be a self-wakeup. Any chance of a peek at your debugging code? Thanx, Paul -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@...r.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists