From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757522Ab2AXVUe (ORCPT ); Tue, 24 Jan 2012 16:20:34 -0500 Received: from e34.co.us.ibm.com ([32.97.110.152]:45342 "EHLO e34.co.us.ibm.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1757363Ab2AXVUc (ORCPT ); Tue, 24 Jan 2012 16:20:32 -0500 Date: Tue, 24 Jan 2012 13:11:37 -0800 From: "Paul E. McKenney" To: Eric Dumazet Cc: Ingo Molnar , Linus Torvalds , linux-kernel@vger.kernel.org, =?iso-8859-1?Q?Fr=E9d=E9ric?= Weisbecker , Thomas Gleixner , Peter Zijlstra , Andrew Morton Subject: Re: [GIT PULL] RCU changes for v3.3 Message-ID: <20120124211137.GD2381@linux.vnet.ibm.com> Reply-To: paulmck@linux.vnet.ibm.com References: <20120105135432.GA31450@elte.hu> <1327422312.7231.22.camel@edumazet-HP-Compaq-6005-Pro-SFF-PC> <20120124165312.GG2531@linux.vnet.ibm.com> <1327425208.7231.26.camel@edumazet-HP-Compaq-6005-Pro-SFF-PC> <20120124194140.GB2381@linux.vnet.ibm.com> <1327435069.2767.1.camel@edumazet-laptop> MIME-Version: 1.0 Content-Type: text/plain; charset=iso-8859-1 Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: <1327435069.2767.1.camel@edumazet-laptop> User-Agent: Mutt/1.5.21 (2010-09-15) X-Content-Scanned: Fidelis XPS MAILER x-cbid: 12012421-1780-0000-0000-00000298F8A7 X-IBM-ISS-SpamDetectors: X-IBM-ISS-DetailInfo: BY=3.00000245; HX=3.00000181; KW=3.00000007; PH=3.00000001; SC=3.00000001; SDB=6.00107806; UDB=6.00027000; UTC=2012-01-24 21:20:29 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, Jan 24, 2012 at 08:57:49PM +0100, Eric Dumazet wrote: > Le mardi 24 janvier 2012 à 11:41 -0800, Paul E. McKenney a écrit : > > > Ah, I see... I need to find one of trace_power_start(), > > trace_power_frequency(), or trace_power_end(). I would have to guess > > that this is either the trace_power_start() or the trace_power_end() > > called from drivers/cpuidle/cpuidle.c lines 97 and 102. Those are > > within cpuidle_idle_call(), which are called from cpu_idle() in > > arch/x86/kernel/process_32.c and arch/x86/kernel/process_64.c, so this > > sounds plausible. > > > > And they are indeed busted -- RCU believes the CPU is idle at the point > > that cpuidle_idle_call() is invoked. > > > > A hacky patch is below. Here are some of my concerns with it: > > > > 1. Is there a configuration in which the scheduler clock gets > > turned off, but in which cpuidle_idle_call() always returns > > zero? If so, we either really need RCU to consider the entire > > inner loop to be idle (thus needing to snapshot the value of > > cpuidle_idle_call() in the outer loop) or we need explicit calls > > to rcu_sched_qs() and friends. > > > > Yes, we could momentarily exit RCU idleness mode, but I would > > need to think that one through... > > > > 2. I am not totally confident that I have the order of operations > > surrounding the call to pm_idle() correct. > > > > 3. This only addresses x86, and it looks like a few other architectures > > have this same problem. > > > > 4. Probably other things that I haven't thought of. > > > > That said, the patch does seem to compile, at least on my 32-bit > > laptop... > > > > Thanx, Paul > > > > ------------------------------------------------------------------------ > > > > idle: Avoid using RCU when RCU thinks the CPU is idle > > > > The x86 idle loops invoke cpuidle_idle_call() which uses tracing > > which uses RCU. Unfortunately, these idle loops have already > > told RCU to ignore this CPU when they call it. This patch hacks > > the idle loops to avoid this problem, but probably causing several > > other problems in the process. > > > > Not-yet-signed-off-by: Paul E. McKenney > > --- > > Hi Paul > > Just tested it on my x86_64 machine, but warnings are still here > > Thanks ! Gah!!! The mwait_idle() function itself (which is the default value of the pm_idle function pointer) uses tracing and thus RCU! What part of "don't use RCU from idle CPUs" was unclear, one wonders? Ah well, the good news is that we can now detect such abuse and fix it. But fixing it appears to require pushing rcu_idle_enter() and rcu_idle_exit() pairs down to the bottom of each and every idle loop and governor. So... The cpuidle_idle_call() function has an idle loop inside of itself, namely the ->enter() call for the desired target state. It does tracing on both sides of that call. Should the ->enter() calls actually avoid use of tracing, I could push the rcu_idle_enter() and rcu_idle_exit() down into cpuidle_idle_call(). We seem to have a ladder_governor and a menu_governor in 3.2, and these have states, which in turn have ->enter functions. Hmmm... Residual power dissipation is given in milliwatts. I could imagine some heartburn from many of the more aggressive embedded folks, given that they might prefer microwatts -- or maybe even nanowatts, for all I know. There are a bunch of states defined in drivers/idle/intel_idle.c, and these use intel_idle() as their ->enter() states. This one looks to have a nice place for rcu_idle_enter() and rcu_idle_exit(). But I also need to push rcu_idle_enter() and rcu_idle_exit() into any function that can be assigned to pm_idle(): default_idle(), poll_idle(), mwait_idle(), and amd_e400_idle(). OK, that is not all -that- bad, though this must also be done for a number of other architectures as well. OK, will post a patch. I will need testing -- clearly my testing on KVM is missing a few important code paths... Thanx, Paul > [ 61.111559] > [ 61.111563] =============================== > [ 61.111565] [ INFO: suspicious RCU usage. ] > [ 61.111567] 3.3.0-rc1+ #572 Not tainted > [ 61.111569] ------------------------------- > [ 61.111571] include/trace/events/power.h:102 suspicious rcu_dereference_check() usage! > [ 61.111573] > [ 61.111574] other info that might help us debug this: > [ 61.111575] > [ 61.111577] > [ 61.111577] rcu_scheduler_active = 1, debug_locks = 1 > [ 61.111579] RCU used illegally from extended quiescent state! > [ 61.111582] no locks held by swapper/0/0. > [ 61.111583] > [ 61.111584] stack backtrace: > [ 61.111587] Pid: 0, comm: swapper/0 Not tainted 3.3.0-rc1+ #572 > [ 61.111589] Call Trace: > [ 61.111598] [] lockdep_rcu_suspicious+0xca/0xf0 > [ 61.111604] [] mwait_idle+0x499/0x4c0 > [ 61.111609] [] cpu_idle+0x98/0xe0 > [ 61.111615] [] rest_init+0x133/0x144 > [ 61.111618] [] ? rest_init+0x79/0x144 > [ 61.111623] [] start_kernel+0x35b/0x366 > [ 61.111627] [] x86_64_start_reservations+0x131/0x135 > [ 61.111631] [] x86_64_start_kernel+0xf0/0xf7 > [ 61.111743] ------------[ cut here ]------------ > [ 61.111750] WARNING: at include/linux/rcupdate.h:242 __perf_event_overflow+0x27c/0x2c0() > [ 61.111754] Hardware name: ProLiant BL460c G6 > [ 61.111756] Modules linked in: ipmi_devintf nfsd exportfs hpilo ipmi_si bnx2x crc32c libcrc32c mdio [last unloaded: scsi_wait_scan] > [ 61.111770] Pid: 0, comm: swapper/0 Not tainted 3.3.0-rc1+ #572 > [ 61.111772] Call Trace: > [ 61.111777] [] warn_slowpath_common+0x7f/0xc0 > [ 61.111781] [] warn_slowpath_null+0x1a/0x20 > [ 61.111784] [] __perf_event_overflow+0x27c/0x2c0 > [ 61.111788] [] ? printk+0x41/0x43 > [ 61.111794] [] ? __module_text_address+0x16/0x80 > [ 61.111798] [] perf_swevent_overflow+0xa9/0xc0 > [ 61.111801] [] perf_swevent_event+0x6f/0x90 > [ 61.111804] [] perf_tp_event+0x76/0xf0 > [ 61.111809] [] perf_trace_power+0xbe/0xe0 > [ 61.111812] [] ? mwait_idle+0x40f/0x4c0 > [ 61.111815] [] mwait_idle+0x40f/0x4c0 > [ 61.111819] [] cpu_idle+0x98/0xe0 > [ 61.111822] [] rest_init+0x133/0x144 > [ 61.111825] [] ? rest_init+0x79/0x144 > [ 61.111828] [] start_kernel+0x35b/0x366 > [ 61.111831] [] x86_64_start_reservations+0x131/0x135 > [ 61.111834] [] x86_64_start_kernel+0xf0/0xf7 > [ 61.111837] ---[ end trace 18a36211154afbbb ]--- > [ 61.111839] ------------[ cut here ]------------ > [ 61.111843] WARNING: at include/linux/rcupdate.h:242 perf_output_begin+0x2f6/0x330() > [ 61.111845] Hardware name: ProLiant BL460c G6 > [ 61.111848] Modules linked in: ipmi_devintf nfsd exportfs hpilo ipmi_si bnx2x crc32c libcrc32c mdio [last unloaded: scsi_wait_scan] > [ 61.111859] Pid: 0, comm: swapper/0 Tainted: G W 3.3.0-rc1+ #572 > [ 61.111861] Call Trace: > [ 61.111864] [] warn_slowpath_common+0x7f/0xc0 > [ 61.111868] [] warn_slowpath_null+0x1a/0x20 > [ 61.111871] [] perf_output_begin+0x2f6/0x330 > [ 61.111875] [] ? sched_clock_cpu+0xc5/0x120 > [ 61.111879] [] ? trace_hardirqs_off+0xd/0x10 > [ 61.111882] [] ? local_clock+0x4f/0x60 > [ 61.111886] [] ? __perf_event_header__init_id+0xad/0xf0 > [ 61.111889] [] ? perf_prepare_sample+0x63/0x110 > [ 61.111892] [] __perf_event_overflow+0x18d/0x2c0 > [ 61.111895] [] ? __perf_event_overflow+0x145/0x2c0 > [ 61.111898] [] ? printk+0x41/0x43 > [ 61.111901] [] perf_swevent_overflow+0xa9/0xc0 > [ 61.111904] [] perf_swevent_event+0x6f/0x90 > [ 61.111907] [] perf_tp_event+0x76/0xf0 > [ 61.111911] [] perf_trace_power+0xbe/0xe0 > [ 61.111915] [] ? mwait_idle+0x40f/0x4c0 > [ 61.111918] [] mwait_idle+0x40f/0x4c0 > [ 61.111922] [] cpu_idle+0x98/0xe0 > [ 61.111926] [] rest_init+0x133/0x144 > [ 61.111929] [] ? rest_init+0x79/0x144 > [ 61.111933] [] start_kernel+0x35b/0x366 > [ 61.111937] [] x86_64_start_reservations+0x131/0x135 > [ 61.111940] [] x86_64_start_kernel+0xf0/0xf7 > [ 61.111943] ---[ end trace 18a36211154afbbc ]--- > [ 61.111946] > [ 61.111947] =============================== > [ 61.111949] [ INFO: suspicious RCU usage. ] > [ 61.111950] 3.3.0-rc1+ #572 Tainted: G W > [ 61.111952] ------------------------------- > [ 61.111954] kernel/events/ring_buffer.c:120 suspicious rcu_dereference_check() usage! > [ 61.111956] > [ 61.111957] other info that might help us debug this: > [ 61.111958] > [ 61.111960] > [ 61.111960] rcu_scheduler_active = 1, debug_locks = 1 > [ 61.111962] RCU used illegally from extended quiescent state! > [ 61.111964] 2 locks held by swapper/0/0: > [ 61.111966] #0: (rcu_read_lock){.+.+..}, at: [] __perf_event_overflow+0x145/0x2c0 > [ 61.111974] #1: (rcu_read_lock){.+.+..}, at: [] perf_output_begin+0x3f/0x330 > [ 61.111980] > [ 61.111980] stack backtrace: > [ 61.111982] Pid: 0, comm: swapper/0 Tainted: G W 3.3.0-rc1+ #572 > [ 61.111984] Call Trace: > [ 61.111987] [] lockdep_rcu_suspicious+0xca/0xf0 > [ 61.111990] [] perf_output_begin+0x268/0x330 > [ 61.111993] [] ? perf_output_begin+0x3f/0x330 > [ 61.111997] [] ? sched_clock_cpu+0xc5/0x120 > [ 61.111999] [] ? trace_hardirqs_off+0xd/0x10 > [ 61.112003] [] ? local_clock+0x4f/0x60 > [ 61.112006] [] ? __perf_event_header__init_id+0xad/0xf0 > [ 61.112009] [] ? perf_prepare_sample+0x63/0x110 > [ 61.112013] [] __perf_event_overflow+0x18d/0x2c0 > [ 61.112015] [] ? __perf_event_overflow+0x145/0x2c0 > [ 61.112019] [] ? printk+0x41/0x43 > [ 61.112022] [] perf_swevent_overflow+0xa9/0xc0 > [ 61.112024] [] perf_swevent_event+0x6f/0x90 > [ 61.112028] [] perf_tp_event+0x76/0xf0 > [ 61.112031] [] perf_trace_power+0xbe/0xe0 > [ 61.112034] [] ? mwait_idle+0x40f/0x4c0 > [ 61.112038] [] mwait_idle+0x40f/0x4c0 > [ 61.112041] [] cpu_idle+0x98/0xe0 > [ 61.112044] [] rest_init+0x133/0x144 > [ 61.112047] [] ? rest_init+0x79/0x144 > [ 61.112050] [] start_kernel+0x35b/0x366 > [ 61.112053] [] x86_64_start_reservations+0x131/0x135 > [ 61.112057] [] x86_64_start_kernel+0xf0/0xf7 > [ 61.112059] ------------[ cut here ]------------ > [ 61.112062] WARNING: at include/linux/rcupdate.h:248 perf_output_end+0x5b/0x70() > [ 61.112064] Hardware name: ProLiant BL460c G6 > [ 61.112065] Modules linked in: ipmi_devintf nfsd exportfs hpilo ipmi_si bnx2x crc32c libcrc32c mdio [last unloaded: scsi_wait_scan] > [ 61.112076] Pid: 0, comm: swapper/0 Tainted: G W 3.3.0-rc1+ #572 > [ 61.112078] Call Trace: > [ 61.112081] [] warn_slowpath_common+0x7f/0xc0 > [ 61.112085] [] warn_slowpath_null+0x1a/0x20 > [ 61.112088] [] perf_output_end+0x5b/0x70 > [ 61.112091] [] __perf_event_overflow+0x22c/0x2c0 > [ 61.112094] [] ? __perf_event_overflow+0x145/0x2c0 > [ 61.112097] [] perf_swevent_overflow+0xa9/0xc0 > [ 61.112101] [] perf_swevent_event+0x6f/0x90 > [ 61.112104] [] perf_tp_event+0x76/0xf0 > [ 61.112107] [] perf_trace_power+0xbe/0xe0 > [ 61.112110] [] ? mwait_idle+0x40f/0x4c0 > [ 61.112113] [] mwait_idle+0x40f/0x4c0 > [ 61.112116] [] cpu_idle+0x98/0xe0 > [ 61.112120] [] rest_init+0x133/0x144 > [ 61.112122] ------------[ cut here ]------------ > [ 61.112126] WARNING: at include/linux/rcupdate.h:248 perf_output_end+0x5b/0x70() > [ 61.112128] Hardware name: ProLiant BL460c G6 > [ 61.112129] Modules linked in: ipmi_devintf nfsd exportfs hpilo [] ? rest_init+0x79/0x144 > [ 61.112137] [] start_kernel+0x35b/0x366 > [ 61.112138] ipmi_si bnx2x [] x86_64_start_reservations+0x131/0x135 > [ 61.112143] crc32c libcrc32c mdio [last unloaded: scsi_wait_scan] > [ 61.112148] Pid: 0, comm: swapper/2 Tainted: G W 3.3.0-rc1+ #572 > [ 61.112150] [] x86_64_start_kernel+0xf0/0xf7 > [ 61.112152] ---[ end trace 18a36211154afbbd ]--- > [ 61.112153] ------------[ cut here ]------------ > [ 61.112155] WARNING: at include/linux/rcupdate.h:248 __perf_event_overflow+0x2a6/0x2c0() > [ 61.112156] Hardware name: ProLiant BL460c G6 > [ 61.112157] Modules linked in: ipmi_devintf nfsd exportfs hpilo ipmi_si bnx2x crc32c libcrc32c mdio [last unloaded: scsi_wait_scan] > [ 61.112165] Pid: 0, comm: swapper/0 Tainted: G W 3.3.0-rc1+ #572 > [ 61.112166] Call Trace: > [ 61.112168] [] warn_slowpath_common+0x7f/0xc0 > [ 61.112170] Call Trace: > [ 61.112172] [] warn_slowpath_null+0x1a/0x20 > [ 61.112176] [] warn_slowpath_common+0x7f/0xc0 > [ 61.112178] [] __perf_event_overflow+0x2a6/0x2c0 > [ 61.112182] [] warn_slowpath_null+0x1a/0x20 > [ 61.112184] [] ? __perf_event_overflow+0x145/0x2c0 > [ 61.112186] [] perf_swevent_overflow+0xa9/0xc0 > [ 61.112189] [] perf_output_end+0x5b/0x70 > [ 61.112191] [] perf_swevent_event+0x6f/0x90 > [ 61.112193] [] perf_tp_event+0x76/0xf0 > [ 61.112196] [] __perf_event_overflow+0x22c/0x2c0 > [ 61.112199] [] perf_trace_power+0xbe/0xe0 > [ 61.112202] [] ? mwait_idle+0x40f/0x4c0 > [ 61.112205] [] ? __perf_event_overflow+0x145/0x2c0 > [ 61.112207] [] mwait_idle+0x40f/0x4c0 > [ 61.112209] [] cpu_idle+0x98/0xe0 > [ 61.112212] [] rest_init+0x133/0x144 > [ 61.112214] [] perf_swevent_overflow+0xa9/0xc0 > [ 61.112217] [] perf_swevent_event+0x6f/0x90 > [ 61.112219] [] ? rest_init+0x79/0x144 > [ 61.112222] [] perf_tp_event+0x76/0xf0 > [ 61.112227] [] ? lapic_next_event+0x1d/0x30 > [ 61.112229] [] start_kernel+0x35b/0x366 > [ 61.112232] [] x86_64_start_reservations+0x131/0x135 > [ 61.112235] [] perf_trace_power+0xbe/0xe0 > [ 61.112238] [] x86_64_start_kernel+0xf0/0xf7 > [ 61.112239] ---[ end trace 18a36211154afbbe ]--- > [ 61.112242] [] ? mwait_idle+0x40f/0x4c0 > [ 61.112245] [] mwait_idle+0x40f/0x4c0 > [ 61.112248] [] cpu_idle+0x98/0xe0 > [ 61.112252] [] start_secondary+0x1df/0x1e3 > [ 61.112254] ---[ end trace 18a36211154afbbf ]--- > [ 61.114605] > [ 61.114608] =============================== > [ 61.114611] [ INFO: suspicious RCU usage. ] > [ 61.114614] 3.3.0-rc1+ #572 Tainted: G W > [ 61.114616] ------------------------------- > [ 61.114620] include/trace/events/power.h:127 suspicious rcu_dereference_check() usage! > [ 61.114625] > [ 61.114626] other info that might help us debug this: > [ 61.114628] > [ 61.114630] > [ 61.114630] rcu_scheduler_active = 1, debug_locks = 1 > [ 61.114633] RCU used illegally from extended quiescent state! > [ 61.114635] no locks held by swapper/2/0. > [ 61.114637] > [ 61.114638] stack backtrace: > [ 61.114641] Pid: 0, comm: swapper/2 Tainted: G W 3.3.0-rc1+ #572 > [ 61.114645] Call Trace: > [ 61.114650] [] lockdep_rcu_suspicious+0xca/0xf0 > [ 61.114655] [] mwait_idle+0x2ad/0x4c0 > [ 61.114660] [] cpu_idle+0x98/0xe0 > [ 61.114664] [] start_secondary+0x1df/0x1e3 > >