On Tue, Mar 29, 2011 at 2:10 AM, Paul E. McKenney
<paulmck@xxxxxxxxxxxxxxxxxx> wrote:
> On Mon, Mar 28, 2011 at 06:46:48PM +0200, Sedat Dilek wrote:
>> On Mon, Mar 28, 2011 at 6:38 PM, Sedat Dilek <sedat.dilek@xxxxxxxxxxxxxx> wrote:
>> > On Mon, Mar 28, 2011 at 5:11 PM, Paul E. McKenney
>> > <paulmck@xxxxxxxxxxxxxxxxxx> wrote:
>> >> On Mon, Mar 28, 2011 at 06:24:36AM -0700, Paul E. McKenney wrote:
>> >>> On Mon, Mar 28, 2011 at 02:33:36PM +0200, Sedat Dilek wrote:
>
> [ . . . ]
>
>> >>> > Ah, before I forget...
>> >>> >
>> >>> > I used TREE_RCU (was the default before noticing RCU issue) for
>> >>> > finding the culprit commit.
>> >>> > If it is from your POV more helpful to switch to PREEMPT + PREEMPT_RCU
>> >>> > + RCU_BOOST, please let me *now* know.
>> >>> > ( Both RCU setups freaks up the system. )
>> >>>
>> >>> If TREE_RCU hits problems faster, it is probably best to stay with
>> >>> TREE_RCU.
>> >>
>> >> And of course, one exception to this advice is if TREE_RCU hangs so hard
>> >> and fast that you don't have time to get any diagnostics. ÂIf this is the
>> >> case, then TREE_PREEMPT_RCU might be more productive.
>> >>
>> >
>> > OK, that would somehow explain why I could not really get some debug
>> > infos when doing "my stress-test" and checking via:
>> >
>> > $ LC_ALL=C tail -f /sys/kernel/debug/rcu/rcudata
>> >
>> > Then I remembered I saw a snippet for a RCU torture script mentionned
>> > in the kernel-docs (see Documentation/RCU/torture.txt).
>> >
>> > 189 The following script may be used to torture RCU:
>> > 190
>> > 191 Â Â Â Â #!/bin/sh
>> > 192
>> > 193 Â Â Â Â modprobe rcutorture
>> > 194 Â Â Â Â sleep 100
>> > 195 Â Â Â Â rmmod rcutorture
>> > 196 Â Â Â Â dmesg | grep torture:
>> >
>> > So, I recompiled a new TREE_RC-based kernel and build with
>> > CONFIG_RCU_TORTURE_TEST=m.
>> >
>> > Unfortunately, the rmmod (I prefer modprobe -r -v) hangs... the
>> > messages in the logs look promising.
>> >
>> > - Sedat -
>> >
>>
>> Wrong attachment, correct attached.
>
> And one stupid problem located thus far. ÂI can make a (tortured) case
> for it resulting in the symptoms you see, but it does seem unlikely to
> happen repeatedly, as it would require a burst of CPU just at the wrong
> time. ÂBut who knows?
>
> In any case, I am still looking.
>
> Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â ÂThanx, Paul
>
> ------------------------------------------------------------------------
>
> Fix stupid typo.
>
> Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
>
> diff --git a/kernel/rcutree.c b/kernel/rcutree.c
> index 5477764..f311228 100644
> --- a/kernel/rcutree.c
> +++ b/kernel/rcutree.c
> @@ -1618,7 +1618,7 @@ static int rcu_node_kthread(void *arg)
> Â Â Â Â Â Â Â Ârnp->wakemask = 0;
> Â Â Â Â Â Â Â Âraw_spin_unlock_irqrestore(&rnp->lock, flags);
> Â Â Â Â Â Â Â Ârcu_initiate_boost(rnp);
> - Â Â Â Â Â Â Â for (cpu = rnp->grplo; cpu <= rnp->grphi; cpu++, mask <<= 1) {
> + Â Â Â Â Â Â Â for (cpu = rnp->grplo; cpu <= rnp->grphi; cpu++, mask >>= 1) {
> Â Â Â Â Â Â Â Â Â Â Â Âif ((mask & 0x1) == 0)
> Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Âcontinue;
> Â Â Â Â Â Â Â Â Â Â Â Âpreempt_disable();
>
I have tested this patch and the previous one you send:
(+) OK rcu-fix/rcu-further-lower-priority-in-rcu_yield.patch
(+) OK rcu-fix/Fix-stupid-typo.patch
As you suggested I switched to PREEMPT and RCU with rcu-boost:
# egrep 'RCU|PREEMPT|_HZ' /boot/config-2.6.38-next20110328-5-686-iniza
# RCU Subsystem
CONFIG_TREE_PREEMPT_RCU=y
CONFIG_PREEMPT_RCU=y
CONFIG_RCU_TRACE=y
CONFIG_RCU_FANOUT=32
# CONFIG_RCU_FANOUT_EXACT is not set
CONFIG_TREE_RCU_TRACE=y
CONFIG_RCU_BOOST=y
CONFIG_RCU_BOOST_PRIO=1
CONFIG_RCU_BOOST_DELAY=500
CONFIG_NO_HZ=y
# CONFIG_PREEMPT_NONE is not set
# CONFIG_PREEMPT_VOLUNTARY is not set
CONFIG_PREEMPT=y
# CONFIG_HZ_100 is not set
CONFIG_HZ_250=y
# CONFIG_HZ_300 is not set
# CONFIG_HZ_1000 is not set
CONFIG_HZ=250
CONFIG_DEBUG_PREEMPT=y
# CONFIG_SPARSE_RCU_POINTER is not set
CONFIG_RCU_TORTURE_TEST=m
CONFIG_RCU_CPU_STALL_TIMEOUT=60
CONFIG_RCU_CPU_STALL_VERBOSE=y
CONFIG_PREEMPT_TRACER=y
Unfortunately, the rcu-torture script hangs again on unloading the
rcu-torture-test module.
Attached are RCU-related messages in my logs.
( I tailed for rcudata changes - no logs. )
- Sedat -
Mar 29 04:21:20 tbox kernel: [ 132.160108] rcu-torture:--- Start of test: nreaders=2 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/1 test_boost_interval=7 test_boost_duration=4
Mar 29 04:25:08 tbox kernel: [ 360.352072] INFO: task rcu_torture_fak:1750 blocked for more than 120 seconds.
Mar 29 04:25:08 tbox kernel: [ 360.364505] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:25:08 tbox kernel: [ 360.377380] rcu_torture_fak D 00000036 0 1750 2 0x00000000
Mar 29 04:25:08 tbox kernel: [ 360.389888] f5169f08 00000046 10c2d7ee 00000036 c1467400 000036da 00000000 c1467400
Mar 29 04:25:08 tbox kernel: [ 360.405450] 00000000 00000036 f5971ce0 c108395c c129f22b 00000001 f5169ed0 c12a313a
Mar 29 04:25:08 tbox kernel: [ 360.417251] f6406400 f5169ed8 c1025e91 f5169f54 c129f230 1a975683 00000021 c1467400
Mar 29 04:25:08 tbox kernel: [ 360.429130] Call Trace:
Mar 29 04:25:08 tbox kernel: [ 360.440754] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:08 tbox kernel: [ 360.452377] [<c129f22b>] ? schedule+0x3e5/0x3fa
Mar 29 04:25:08 tbox kernel: [ 360.463904] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:08 tbox kernel: [ 360.475636] [<c1025e91>] ? need_resched+0x14/0x1e
Mar 29 04:25:08 tbox kernel: [ 360.487202] [<c129f230>] ? schedule+0x3ea/0x3fa
Mar 29 04:25:08 tbox kernel: [ 360.498801] [<c108397d>] ? trace_preempt_off+0xf/0x22
Mar 29 04:25:08 tbox kernel: [ 360.510305] [<c103a53b>] ? lock_timer_base.isra.29+0x1e/0x3c
Mar 29 04:25:08 tbox kernel: [ 360.521903] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:25:08 tbox kernel: [ 360.533342] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:08 tbox kernel: [ 360.544920] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:08 tbox kernel: [ 360.556383] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:25:08 tbox kernel: [ 360.567690] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:08 tbox kernel: [ 360.578785] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:25:08 tbox kernel: [ 360.589832] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:25:08 tbox kernel: [ 360.600831] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:25:08 tbox kernel: [ 360.611948] [<f875f93e>] ? rcu_torture_fqs+0xc6/0xc6 [rcutorture]
Mar 29 04:25:08 tbox kernel: [ 360.623083] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:25:08 tbox kernel: [ 360.634254] [<c1077004>] synchronize_rcu+0x38/0x3a
Mar 29 04:25:08 tbox kernel: [ 360.645301] [<c1043868>] ? find_ge_pid+0x2f/0x2f
Mar 29 04:25:08 tbox kernel: [ 360.656373] [<f875f9b1>] rcu_torture_fakewriter+0x73/0xd0 [rcutorture]
Mar 29 04:25:08 tbox kernel: [ 360.667452] [<c1045511>] kthread+0x62/0x67
Mar 29 04:25:08 tbox kernel: [ 360.678588] [<c10454af>] ? kthread_worker_fn+0x111/0x111
Mar 29 04:25:08 tbox kernel: [ 360.689635] [<c12a5cfe>] kernel_thread_helper+0x6/0xd
Mar 29 04:25:08 tbox kernel: [ 360.700677] INFO: task rcu_torture_fak:1751 blocked for more than 120 seconds.
Mar 29 04:25:08 tbox kernel: [ 360.711751] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:25:08 tbox kernel: [ 360.723000] rcu_torture_fak D 00000021 0 1751 2 0x00000000
Mar 29 04:25:08 tbox kernel: [ 360.734284] f5807f08 00000046 1b8afabc 00000021 c1467400 21ab5ecd 00000000 c1467400
Mar 29 04:25:08 tbox kernel: [ 360.745904] 00000000 00000021 f5970840 c108395c c129f22b 00000001 f5807ed0 c12a313a
Mar 29 04:25:08 tbox kernel: [ 360.757524] f6406400 f5807ed8 c1025e91 f5807f54 c129f230 1a975e7e 00000021 c1467400
Mar 29 04:25:08 tbox kernel: [ 360.769310] Call Trace:
Mar 29 04:25:08 tbox kernel: [ 360.780844] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:08 tbox kernel: [ 360.792587] [<c129f22b>] ? schedule+0x3e5/0x3fa
Mar 29 04:25:08 tbox kernel: [ 360.804259] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:08 tbox kernel: [ 360.816103] [<c1025e91>] ? need_resched+0x14/0x1e
Mar 29 04:25:08 tbox kernel: [ 360.827845] [<c129f230>] ? schedule+0x3ea/0x3fa
Mar 29 04:25:08 tbox kernel: [ 360.839621] [<c108397d>] ? trace_preempt_off+0xf/0x22
Mar 29 04:25:08 tbox kernel: [ 360.851319] [<c103a53b>] ? lock_timer_base.isra.29+0x1e/0x3c
Mar 29 04:25:08 tbox kernel: [ 360.863052] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:25:08 tbox kernel: [ 360.874618] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:08 tbox kernel: [ 360.886321] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:08 tbox kernel: [ 360.897896] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:25:08 tbox kernel: [ 360.909449] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:08 tbox kernel: [ 360.920917] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:25:08 tbox kernel: [ 360.932305] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:25:08 tbox kernel: [ 360.943525] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:25:08 tbox kernel: [ 360.954839] [<f875f93e>] ? rcu_torture_fqs+0xc6/0xc6 [rcutorture]
Mar 29 04:25:09 tbox kernel: [ 360.966148] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:25:09 tbox kernel: [ 360.977617] [<c1077004>] synchronize_rcu+0x38/0x3a
Mar 29 04:25:09 tbox kernel: [ 360.989076] [<c1043868>] ? find_ge_pid+0x2f/0x2f
Mar 29 04:25:09 tbox kernel: [ 361.000603] [<f875f9b1>] rcu_torture_fakewriter+0x73/0xd0 [rcutorture]
Mar 29 04:25:09 tbox kernel: [ 361.012020] [<c1045511>] kthread+0x62/0x67
Mar 29 04:25:09 tbox kernel: [ 361.023329] [<c10454af>] ? kthread_worker_fn+0x111/0x111
Mar 29 04:25:09 tbox kernel: [ 361.034680] [<c12a5cfe>] kernel_thread_helper+0x6/0xd
Mar 29 04:25:09 tbox kernel: [ 361.046110] INFO: task rcu_torture_fak:1752 blocked for more than 120 seconds.
Mar 29 04:25:09 tbox kernel: [ 361.057508] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:25:09 tbox kernel: [ 361.068706] rcu_torture_fak D 00000021 0 1752 2 0x00000000
Mar 29 04:25:09 tbox kernel: [ 361.079547] f59aff08 00000046 1c05091a 00000021 c1467400 2144d81f 00000000 c1467400
Mar 29 04:25:09 tbox kernel: [ 361.090601] 00000000 00000021 f5b2cc60 c108395c c129f22b 00000001 f59afed0 c12a313a
Mar 29 04:25:09 tbox kernel: [ 361.101522] f6406400 f59afed8 c1025e91 f59aff54 c129f230 1a973f63 00000021 c1467400
Mar 29 04:25:09 tbox kernel: [ 361.112488] Call Trace:
Mar 29 04:25:09 tbox kernel: [ 361.123082] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:09 tbox kernel: [ 361.133760] [<c129f22b>] ? schedule+0x3e5/0x3fa
Mar 29 04:25:09 tbox kernel: [ 361.144275] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:09 tbox kernel: [ 361.154858] [<c1025e91>] ? need_resched+0x14/0x1e
Mar 29 04:25:09 tbox kernel: [ 361.165231] [<c129f230>] ? schedule+0x3ea/0x3fa
Mar 29 04:25:09 tbox kernel: [ 361.175636] [<c108397d>] ? trace_preempt_off+0xf/0x22
Mar 29 04:25:09 tbox kernel: [ 361.185990] [<c103a53b>] ? lock_timer_base.isra.29+0x1e/0x3c
Mar 29 04:25:09 tbox kernel: [ 361.196475] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:25:09 tbox kernel: [ 361.206819] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:09 tbox kernel: [ 361.217327] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:09 tbox kernel: [ 361.227750] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:25:09 tbox kernel: [ 361.238216] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:09 tbox kernel: [ 361.248644] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:25:09 tbox kernel: [ 361.259051] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:25:09 tbox kernel: [ 361.269341] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:25:09 tbox kernel: [ 361.279737] [<f875f93e>] ? rcu_torture_fqs+0xc6/0xc6 [rcutorture]
Mar 29 04:25:09 tbox kernel: [ 361.290095] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:25:09 tbox kernel: [ 361.300570] [<c1077004>] synchronize_rcu+0x38/0x3a
Mar 29 04:25:09 tbox kernel: [ 361.310963] [<c1043868>] ? find_ge_pid+0x2f/0x2f
Mar 29 04:25:09 tbox kernel: [ 361.321416] [<f875f9b1>] rcu_torture_fakewriter+0x73/0xd0 [rcutorture]
Mar 29 04:25:09 tbox kernel: [ 361.331890] [<c1045511>] kthread+0x62/0x67
Mar 29 04:25:09 tbox kernel: [ 361.342365] [<c10454af>] ? kthread_worker_fn+0x111/0x111
Mar 29 04:25:09 tbox kernel: [ 361.352806] [<c12a5cfe>] kernel_thread_helper+0x6/0xd
Mar 29 04:25:09 tbox kernel: [ 361.363332] INFO: task rcu_torture_fak:1753 blocked for more than 120 seconds.
Mar 29 04:25:09 tbox kernel: [ 361.373899] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:25:09 tbox kernel: [ 361.384605] rcu_torture_fak D 00000021 0 1753 2 0x00000000
Mar 29 04:25:09 tbox kernel: [ 361.395327] f591bf08 00000046 3d298aff 00000021 c1467400 002590a2 00000000 c1467400
Mar 29 04:25:09 tbox kernel: [ 361.406361] 00000000 00000021 f5844840 c108395c c129f22b 00000001 f591bed0 c12a313a
Mar 29 04:25:09 tbox kernel: [ 361.417290] f6406400 f591bed8 c1025e91 f591bf54 c129f230 1a974f36 00000021 c1467400
Mar 29 04:25:09 tbox kernel: [ 361.428261] Call Trace:
Mar 29 04:25:09 tbox kernel: [ 361.438867] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:09 tbox kernel: [ 361.449542] [<c129f22b>] ? schedule+0x3e5/0x3fa
Mar 29 04:25:09 tbox kernel: [ 361.460061] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:09 tbox kernel: [ 361.470675] [<c1025e91>] ? need_resched+0x14/0x1e
Mar 29 04:25:09 tbox kernel: [ 361.481046] [<c129f230>] ? schedule+0x3ea/0x3fa
Mar 29 04:25:09 tbox kernel: [ 361.491448] [<c108397d>] ? trace_preempt_off+0xf/0x22
Mar 29 04:25:09 tbox kernel: [ 361.501801] [<c103a53b>] ? lock_timer_base.isra.29+0x1e/0x3c
Mar 29 04:25:09 tbox kernel: [ 361.512251] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:25:09 tbox kernel: [ 361.522588] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:09 tbox kernel: [ 361.533084] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:09 tbox kernel: [ 361.543495] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:25:09 tbox kernel: [ 361.553946] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:09 tbox kernel: [ 361.564368] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:25:09 tbox kernel: [ 361.574778] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:25:09 tbox kernel: [ 361.585055] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:25:09 tbox kernel: [ 361.595446] [<f875f93e>] ? rcu_torture_fqs+0xc6/0xc6 [rcutorture]
Mar 29 04:25:09 tbox kernel: [ 361.605792] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:25:09 tbox kernel: [ 361.616270] [<c1077004>] synchronize_rcu+0x38/0x3a
Mar 29 04:25:09 tbox kernel: [ 361.626652] [<c1043868>] ? find_ge_pid+0x2f/0x2f
Mar 29 04:25:09 tbox kernel: [ 361.637107] [<f875f9b1>] rcu_torture_fakewriter+0x73/0xd0 [rcutorture]
Mar 29 04:25:09 tbox kernel: [ 361.647577] [<c1045511>] kthread+0x62/0x67
Mar 29 04:25:09 tbox kernel: [ 361.658037] [<c10454af>] ? kthread_worker_fn+0x111/0x111
Mar 29 04:25:09 tbox kernel: [ 361.668459] [<c12a5cfe>] kernel_thread_helper+0x6/0xd
Mar 29 04:25:09 tbox kernel: [ 361.678968] INFO: task modprobe:1759 blocked for more than 120 seconds.
Mar 29 04:25:09 tbox kernel: [ 361.689455] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:25:09 tbox kernel: [ 361.700107] modprobe D 00000036 0 1759 1747 0x00000000
Mar 29 04:25:09 tbox kernel: [ 361.710781] f5995ea4 00000082 10c2f37d 00000036 c1467400 00000c21 00000000 c1467400
Mar 29 04:25:09 tbox kernel: [ 361.721757] 00000000 00000036 f5844420 ffffffff ffffffff c1027d65 10c2d7ee f6406444
Mar 29 04:25:09 tbox kernel: [ 361.732657] 002dab31 f5995e84 3d090000 00000000 f584444c 00001b8f 00000000 f5995e94
Mar 29 04:25:09 tbox kernel: [ 361.743604] Call Trace:
Mar 29 04:25:09 tbox kernel: [ 361.754185] [<c1027d65>] ? finish_task_switch+0x67/0x6d
Mar 29 04:25:09 tbox kernel: [ 361.764863] [<c10219ba>] ? wakeup_preempt_entity+0x36/0x53
Mar 29 04:25:09 tbox kernel: [ 361.775397] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:25:09 tbox kernel: [ 361.785917] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:25:09 tbox kernel: [ 361.796240] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:25:09 tbox kernel: [ 361.806599] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:25:09 tbox kernel: [ 361.816960] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:25:09 tbox kernel: [ 361.827308] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:25:09 tbox kernel: [ 361.837555] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:25:09 tbox kernel: [ 361.847902] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:25:09 tbox kernel: [ 361.858181] [<c1045576>] kthread_stop+0x60/0xaf
Mar 29 04:25:09 tbox kernel: [ 361.868503] [<f8760592>] rcu_torture_cleanup+0x1d5/0x318 [rcutorture]
Mar 29 04:25:09 tbox kernel: [ 361.878857] [<c10592bc>] sys_delete_module+0x198/0x1f5
Mar 29 04:25:09 tbox kernel: [ 361.889253] [<c10c1612>] ? vfs_write+0xa4/0xd7
Mar 29 04:25:09 tbox kernel: [ 361.899525] [<c11aade0>] ? tty_write_lock+0x3d/0x3d
Mar 29 04:25:09 tbox kernel: [ 361.909876] [<c10c17ca>] ? sys_write+0x53/0x5d
Mar 29 04:25:09 tbox kernel: [ 361.920083] [<c12a575f>] sysenter_do_call+0x12/0x28
Mar 29 04:27:09 tbox kernel: [ 481.928074] INFO: task rcu_torture_fak:1750 blocked for more than 120 seconds.
Mar 29 04:27:09 tbox kernel: [ 481.940037] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:27:09 tbox kernel: [ 481.953070] rcu_torture_fak D 00000036 0 1750 2 0x00000000
Mar 29 04:27:10 tbox kernel: [ 481.972056] f5169f08 00000046 10c2d7ee 00000036 c1467400 000036da 00000000 c1467400
Mar 29 04:27:10 tbox kernel: [ 481.984708] 00000000 00000036 f5971ce0 c108395c c129f22b 00000001 f5169ed0 c12a313a
Mar 29 04:27:10 tbox kernel: [ 481.996536] f6406400 f5169ed8 c1025e91 f5169f54 c129f230 1a975683 00000021 c1467400
Mar 29 04:27:10 tbox kernel: [ 482.008580] Call Trace:
Mar 29 04:27:10 tbox kernel: [ 482.020181] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:10 tbox kernel: [ 482.031882] [<c129f22b>] ? schedule+0x3e5/0x3fa
Mar 29 04:27:10 tbox kernel: [ 482.043546] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.055367] [<c1025e91>] ? need_resched+0x14/0x1e
Mar 29 04:27:10 tbox kernel: [ 482.067076] [<c129f230>] ? schedule+0x3ea/0x3fa
Mar 29 04:27:10 tbox kernel: [ 482.078839] [<c108397d>] ? trace_preempt_off+0xf/0x22
Mar 29 04:27:10 tbox kernel: [ 482.090503] [<c103a53b>] ? lock_timer_base.isra.29+0x1e/0x3c
Mar 29 04:27:10 tbox kernel: [ 482.102239] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:27:10 tbox kernel: [ 482.113842] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.125558] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:10 tbox kernel: [ 482.137128] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:27:10 tbox kernel: [ 482.148707] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.160239] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:27:10 tbox kernel: [ 482.171766] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:27:10 tbox kernel: [ 482.183180] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:27:10 tbox kernel: [ 482.194676] [<f875f93e>] ? rcu_torture_fqs+0xc6/0xc6 [rcutorture]
Mar 29 04:27:10 tbox kernel: [ 482.206123] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:27:10 tbox kernel: [ 482.217623] [<c1077004>] synchronize_rcu+0x38/0x3a
Mar 29 04:27:10 tbox kernel: [ 482.228876] [<c1043868>] ? find_ge_pid+0x2f/0x2f
Mar 29 04:27:10 tbox kernel: [ 482.240065] [<f875f9b1>] rcu_torture_fakewriter+0x73/0xd0 [rcutorture]
Mar 29 04:27:10 tbox kernel: [ 482.251134] [<c1045511>] kthread+0x62/0x67
Mar 29 04:27:10 tbox kernel: [ 482.262103] [<c10454af>] ? kthread_worker_fn+0x111/0x111
Mar 29 04:27:10 tbox kernel: [ 482.272901] [<c12a5cfe>] kernel_thread_helper+0x6/0xd
Mar 29 04:27:10 tbox kernel: [ 482.283635] INFO: task rcu_torture_fak:1751 blocked for more than 120 seconds.
Mar 29 04:27:10 tbox kernel: [ 482.294244] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:27:10 tbox kernel: [ 482.304837] rcu_torture_fak D 00000021 0 1751 2 0x00000000
Mar 29 04:27:10 tbox kernel: [ 482.315409] f5807f08 00000046 1b8afabc 00000021 c1467400 21ab5ecd 00000000 c1467400
Mar 29 04:27:10 tbox kernel: [ 482.326258] 00000000 00000021 f5970840 c108395c c129f22b 00000001 f5807ed0 c12a313a
Mar 29 04:27:10 tbox kernel: [ 482.337071] f6406400 f5807ed8 c1025e91 f5807f54 c129f230 1a975e7e 00000021 c1467400
Mar 29 04:27:10 tbox kernel: [ 482.348016] Call Trace:
Mar 29 04:27:10 tbox kernel: [ 482.358653] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:10 tbox kernel: [ 482.369453] [<c129f22b>] ? schedule+0x3e5/0x3fa
Mar 29 04:27:10 tbox kernel: [ 482.380116] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.390934] [<c1025e91>] ? need_resched+0x14/0x1e
Mar 29 04:27:10 tbox kernel: [ 482.401650] [<c129f230>] ? schedule+0x3ea/0x3fa
Mar 29 04:27:10 tbox kernel: [ 482.412396] [<c108397d>] ? trace_preempt_off+0xf/0x22
Mar 29 04:27:10 tbox kernel: [ 482.423046] [<c103a53b>] ? lock_timer_base.isra.29+0x1e/0x3c
Mar 29 04:27:10 tbox kernel: [ 482.433759] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:27:10 tbox kernel: [ 482.444321] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.455086] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:10 tbox kernel: [ 482.465806] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:27:10 tbox kernel: [ 482.476454] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.486994] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:27:10 tbox kernel: [ 482.497590] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:27:10 tbox kernel: [ 482.508130] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:27:10 tbox kernel: [ 482.518661] [<f875f93e>] ? rcu_torture_fqs+0xc6/0xc6 [rcutorture]
Mar 29 04:27:10 tbox kernel: [ 482.529095] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:27:10 tbox kernel: [ 482.539659] [<c1077004>] synchronize_rcu+0x38/0x3a
Mar 29 04:27:10 tbox kernel: [ 482.550091] [<c1043868>] ? find_ge_pid+0x2f/0x2f
Mar 29 04:27:10 tbox kernel: [ 482.560540] [<f875f9b1>] rcu_torture_fakewriter+0x73/0xd0 [rcutorture]
Mar 29 04:27:10 tbox kernel: [ 482.571002] [<c1045511>] kthread+0x62/0x67
Mar 29 04:27:10 tbox kernel: [ 482.581466] [<c10454af>] ? kthread_worker_fn+0x111/0x111
Mar 29 04:27:10 tbox kernel: [ 482.591845] [<c12a5cfe>] kernel_thread_helper+0x6/0xd
Mar 29 04:27:10 tbox kernel: [ 482.602246] INFO: task rcu_torture_fak:1752 blocked for more than 120 seconds.
Mar 29 04:27:10 tbox kernel: [ 482.612710] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:27:10 tbox kernel: [ 482.623331] rcu_torture_fak D 00000021 0 1752 2 0x00000000
Mar 29 04:27:10 tbox kernel: [ 482.634036] f59aff08 00000046 1c05091a 00000021 c1467400 2144d81f 00000000 c1467400
Mar 29 04:27:10 tbox kernel: [ 482.645198] 00000000 00000021 f5b2cc60 c108395c c129f22b 00000001 f59afed0 c12a313a
Mar 29 04:27:10 tbox kernel: [ 482.656175] f6406400 f59afed8 c1025e91 f59aff54 c129f230 1a973f63 00000021 c1467400
Mar 29 04:27:10 tbox kernel: [ 482.667124] Call Trace:
Mar 29 04:27:10 tbox kernel: [ 482.677703] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:10 tbox kernel: [ 482.688365] [<c129f22b>] ? schedule+0x3e5/0x3fa
Mar 29 04:27:10 tbox kernel: [ 482.698868] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.709440] [<c1025e91>] ? need_resched+0x14/0x1e
Mar 29 04:27:10 tbox kernel: [ 482.719793] [<c129f230>] ? schedule+0x3ea/0x3fa
Mar 29 04:27:10 tbox kernel: [ 482.730182] [<c108397d>] ? trace_preempt_off+0xf/0x22
Mar 29 04:27:10 tbox kernel: [ 482.740519] [<c103a53b>] ? lock_timer_base.isra.29+0x1e/0x3c
Mar 29 04:27:10 tbox kernel: [ 482.750947] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:27:10 tbox kernel: [ 482.761271] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.771756] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:10 tbox kernel: [ 482.782160] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:27:10 tbox kernel: [ 482.792602] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:10 tbox kernel: [ 482.803006] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:27:10 tbox kernel: [ 482.813393] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:27:10 tbox kernel: [ 482.823666] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:27:10 tbox kernel: [ 482.834058] [<f875f93e>] ? rcu_torture_fqs+0xc6/0xc6 [rcutorture]
Mar 29 04:27:10 tbox kernel: [ 482.844417] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:27:10 tbox kernel: [ 482.854887] [<c1077004>] synchronize_rcu+0x38/0x3a
Mar 29 04:27:10 tbox kernel: [ 482.865264] [<c1043868>] ? find_ge_pid+0x2f/0x2f
Mar 29 04:27:10 tbox kernel: [ 482.875699] [<f875f9b1>] rcu_torture_fakewriter+0x73/0xd0 [rcutorture]
Mar 29 04:27:10 tbox kernel: [ 482.886157] [<c1045511>] kthread+0x62/0x67
Mar 29 04:27:10 tbox kernel: [ 482.896608] [<c10454af>] ? kthread_worker_fn+0x111/0x111
Mar 29 04:27:10 tbox kernel: [ 482.907033] [<c12a5cfe>] kernel_thread_helper+0x6/0xd
Mar 29 04:27:10 tbox kernel: [ 482.917579] INFO: task rcu_torture_fak:1753 blocked for more than 120 seconds.
Mar 29 04:27:10 tbox kernel: [ 482.928135] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:27:10 tbox kernel: [ 482.938831] rcu_torture_fak D 00000021 0 1753 2 0x00000000
Mar 29 04:27:10 tbox kernel: [ 482.949547] f591bf08 00000046 3d298aff 00000021 c1467400 002590a2 00000000 c1467400
Mar 29 04:27:11 tbox kernel: [ 482.960568] 00000000 00000021 f5844840 c108395c c129f22b 00000001 f591bed0 c12a313a
Mar 29 04:27:11 tbox kernel: [ 482.971488] f6406400 f591bed8 c1025e91 f591bf54 c129f230 1a974f36 00000021 c1467400
Mar 29 04:27:11 tbox kernel: [ 482.982445] Call Trace:
Mar 29 04:27:11 tbox kernel: [ 482.993023] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:11 tbox kernel: [ 483.003687] [<c129f22b>] ? schedule+0x3e5/0x3fa
Mar 29 04:27:11 tbox kernel: [ 483.014180] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:11 tbox kernel: [ 483.024748] [<c1025e91>] ? need_resched+0x14/0x1e
Mar 29 04:27:11 tbox kernel: [ 483.035095] [<c129f230>] ? schedule+0x3ea/0x3fa
Mar 29 04:27:11 tbox kernel: [ 483.045485] [<c108397d>] ? trace_preempt_off+0xf/0x22
Mar 29 04:27:11 tbox kernel: [ 483.055817] [<c103a53b>] ? lock_timer_base.isra.29+0x1e/0x3c
Mar 29 04:27:11 tbox kernel: [ 483.066241] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:27:11 tbox kernel: [ 483.076562] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:11 tbox kernel: [ 483.087036] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:11 tbox kernel: [ 483.097426] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:27:11 tbox kernel: [ 483.107856] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:11 tbox kernel: [ 483.118256] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:27:11 tbox kernel: [ 483.128627] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:27:11 tbox kernel: [ 483.138884] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:27:11 tbox kernel: [ 483.149275] [<f875f93e>] ? rcu_torture_fqs+0xc6/0xc6 [rcutorture]
Mar 29 04:27:11 tbox kernel: [ 483.159611] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:27:11 tbox kernel: [ 483.170072] [<c1077004>] synchronize_rcu+0x38/0x3a
Mar 29 04:27:11 tbox kernel: [ 483.180444] [<c1043868>] ? find_ge_pid+0x2f/0x2f
Mar 29 04:27:11 tbox kernel: [ 483.190875] [<f875f9b1>] rcu_torture_fakewriter+0x73/0xd0 [rcutorture]
Mar 29 04:27:11 tbox kernel: [ 483.201327] [<c1045511>] kthread+0x62/0x67
Mar 29 04:27:11 tbox kernel: [ 483.211784] [<c10454af>] ? kthread_worker_fn+0x111/0x111
Mar 29 04:27:11 tbox kernel: [ 483.222207] [<c12a5cfe>] kernel_thread_helper+0x6/0xd
Mar 29 04:27:11 tbox kernel: [ 483.232717] INFO: task modprobe:1759 blocked for more than 120 seconds.
Mar 29 04:27:11 tbox kernel: [ 483.243213] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 29 04:27:11 tbox kernel: [ 483.253882] modprobe D 00000036 0 1759 1747 0x00000000
Mar 29 04:27:11 tbox kernel: [ 483.264562] f5995ea4 00000082 10c2f37d 00000036 c1467400 00000c21 00000000 c1467400
Mar 29 04:27:11 tbox kernel: [ 483.275540] 00000000 00000036 f5844420 ffffffff ffffffff c1027d65 10c2d7ee f6406444
Mar 29 04:27:11 tbox kernel: [ 483.286424] 002dab31 f5995e84 3d090000 00000000 f584444c 00001b8f 00000000 f5995e94
Mar 29 04:27:11 tbox kernel: [ 483.297363] Call Trace:
Mar 29 04:27:11 tbox kernel: [ 483.307928] [<c1027d65>] ? finish_task_switch+0x67/0x6d
Mar 29 04:27:11 tbox kernel: [ 483.318648] [<c10219ba>] ? wakeup_preempt_entity+0x36/0x53
Mar 29 04:27:11 tbox kernel: [ 483.329172] [<c129f514>] schedule_timeout+0x21/0xaa
Mar 29 04:27:11 tbox kernel: [ 483.339689] [<c108395c>] ? trace_preempt_on+0xf/0x21
Mar 29 04:27:11 tbox kernel: [ 483.350012] [<c129ed68>] ? wait_for_common+0x6f/0xca
Mar 29 04:27:11 tbox kernel: [ 483.360371] [<c12a313a>] ? sub_preempt_count.part.167+0x67/0x74
Mar 29 04:27:11 tbox kernel: [ 483.370729] [<c12a3188>] ? sub_preempt_count+0x41/0x43
Mar 29 04:27:11 tbox kernel: [ 483.381108] [<c129ed6f>] wait_for_common+0x76/0xca
Mar 29 04:27:11 tbox kernel: [ 483.391338] [<c102ca4a>] ? try_to_wake_up+0x181/0x181
Mar 29 04:27:11 tbox kernel: [ 483.401670] [<c129ee44>] wait_for_completion+0x12/0x14
Mar 29 04:27:11 tbox kernel: [ 483.411936] [<c1045576>] kthread_stop+0x60/0xaf
Mar 29 04:27:11 tbox kernel: [ 483.422248] [<f8760592>] rcu_torture_cleanup+0x1d5/0x318 [rcutorture]
Mar 29 04:27:11 tbox kernel: [ 483.432594] [<c10592bc>] sys_delete_module+0x198/0x1f5
Mar 29 04:27:11 tbox kernel: [ 483.442984] [<c10c1612>] ? vfs_write+0xa4/0xd7
Mar 29 04:27:11 tbox kernel: [ 483.453255] [<c11aade0>] ? tty_write_lock+0x3d/0x3d
Mar 29 04:27:11 tbox kernel: [ 483.463598] [<c10c17ca>] ? sys_write+0x53/0x5d
Mar 29 04:27:11 tbox kernel: [ 483.473787] [<c12a575f>] sysenter_do_call+0x12/0x28
