linux-kernel - rcu_dyntick and suspicious RCU usage

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

Hash Suite for Android: free password hash cracker in your pocket

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-ID: <20120709135637.GA26040@localhost>
Date:	Mon, 9 Jul 2012 21:56:37 +0800
From:	wfg@...ux.intel.com
To:	"Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>
Cc:	Josh Triplett <josh@...htriplett.org>,
	Lai Jiangshan <laijs@...fujitsu.com>,
	LKML <linux-kernel@...r.kernel.org>
Subject: rcu_dyntick and suspicious RCU usage

Hi Paul,

I kicked off boot testing for dozens of randconfigs and got some few
runtime errors. Here is one of them. It's very reproducible in kvm,
and obviously only triggers on the attached config.

[    5.335062] Testing event rcu_dyntick: [    5.336515] 
[    5.336953] ===============================
[    5.338124] [ INFO: suspicious RCU usage. ]
[    5.338573] 3.5.0-rc6+ #3 Not tainted
[    5.338573] -------------------------------
[    5.338573] /c/kernel-tests/net/include/trace/events/rcu.h:275 suspicious rcu_dereference_check() usage!
[    5.338573] 
[    5.338573] other info that might help us debug this:
[    5.338573] 
[    5.338573] 
[    5.338573] RCU used illegally from idle CPU!
[    5.338573] rcu_scheduler_active = 1, debug_locks = 0
[    5.338573] RCU used illegally from extended quiescent state!
[    5.338573] no locks held by swapper/0.
[    5.338573] 
[    5.338573] stack backtrace:
[    5.338573] Pid: 0, comm: swapper Not tainted 3.5.0-rc6+ #3
[    5.338573] Call Trace:

[    5.338573] 
[    5.338573]  [<c10bb3a2>] lockdep_rcu_suspicious+0x1de/0x1f4
[    5.338573]  [<c1102a0e>] trace_rcu_dyntick+0xd9/0x167
[    5.338573]  [<c1105329>] rcu_idle_enter_common+0x84/0x22d
[    5.338573]  [<c10b9fea>] ? trace_hardirqs_off_caller+0x97/0x167
[    5.338573]  [<c110585c>] rcu_idle_enter+0x16d/0x274
[    5.338573]  [<c100fbdb>] cpu_idle+0x159/0x220
[    5.338573]  [<c141616f>] rest_init+0x2db/0x2ef
[    5.338573]  [<c1415e94>] ? reciprocal_value+0x64/0x64
[    5.338573]  [<c1721456>] start_kernel+0x8eb/0x8ff
[    5.338573]  [<c172062f>] ? repair_env_string+0xd3/0xd3
[    5.338573]  [<c1720342>] i386_start_kernel+0xf8/0x10b
[    5.372219] OK
[    5.372708] Testing event rcu_prep_idle: OK

And I find the somehow disordered output (the timestamp at the end of
line and the blank line etc.) is indeed a very stable pattern. For
example, here is another trace:

[    4.573142] Testing event rcu_dyntick: [    4.574028] 
[    4.574307] ===============================
[    4.575072] [ INFO: suspicious RCU usage. ]
[    4.575832] 3.5.0-rc5+ #15 Not tainted
[    4.576475] -------------------------------
[    4.576896] /c/kernel-tests/net/include/trace/events/rcu.h:275 suspicious rcu_dereference_check() usage!
[    4.576896] 
[    4.576896] other info that might help us debug this:
[    4.576896] 
[    4.576896] 
[    4.576896] RCU used illegally from idle CPU!
[    4.576896] rcu_scheduler_active = 1, debug_locks = 0
[    4.576896] RCU used illegally from extended quiescent state!
[    4.576896] no locks held by swapper/0.
[    4.576896] 
[    4.576896] stack backtrace:
[    4.576896] Pid: 0, comm: swapper Not tainted 3.5.0-rc5+ #15
[    4.576896] Call Trace:

[    4.576896] 
[    4.576896]  [<c10bb3a2>] lockdep_rcu_suspicious+0x1de/0x1f4
[    4.576896]  [<c1102a0e>] trace_rcu_dyntick+0xd9/0x167
[    4.576896]  [<c1105329>] rcu_idle_enter_common+0x84/0x22d
[    4.576896]  [<c10b9fea>] ? trace_hardirqs_off_caller+0x97/0x167
[    4.576896]  [<c110585c>] rcu_idle_enter+0x16d/0x274
[    4.576896]  [<c100fbdb>] cpu_idle+0x159/0x220
[    4.576896]  [<c1415fbf>] rest_init+0x2db/0x2ef
[    4.576896]  [<c1415ce4>] ? reciprocal_value+0x64/0x64
[    4.576896]  [<c1721456>] start_kernel+0x8eb/0x8ff
[    4.576896]  [<c172062f>] ? repair_env_string+0xd3/0xd3
[    4.576896]  [<c1720342>] i386_start_kernel+0xf8/0x10b
[    4.596538] OK
[    4.596920] Testing event rcu_prep_idle: OK


Thanks,
Fengguang

Download attachment "dmesg-kvm-xgwo-6794-2012-07-09-08-16-05" of type "application/octet-stream" (39439 bytes)

View attachment "config-3.5.0-rc6+" of type "text/plain" (56946 bytes)