Re: [RFC PATCH 1/1] rcu: Use rcu_gp_kthread_wake() to wake up kthreads

[Paul E. McKenney]

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@xxxxxxxxxxxxxxxxxx> 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@xxxxxxxxx> 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@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/