On Wed, Jul 11, 2012 at 12:49:24AM -0700, Paul E. McKenney wrote:
> On Tue, Jul 10, 2012 at 12:47:00PM +0800, Fengguang Wu wrote:
> > Hi Paul,
> > 
> > Fortunately this bug is bisectable and the first bad commit is:
> > 
> >         commit 9b2e4f1880b789be1f24f9684f7a54b90310b5c0
> >         Author: Paul E. McKenney <paul.mckenney@linaro.org>
> >         Date:   Fri Sep 30 12:10:22 2011 -0700
> > 
> >             rcu: Track idleness independent of idle tasks
> 
> OK, there is a problem in TINY_RCU's handling of dyntick-idle: it
> traces while in idle.  The confusion on my part was that in TREE_RCU,
> the nesting and dyntick-idle indication are different, while in
> TINY_RCU they are one and the same.
> 
> Does the following patch help?

Not exactly, but the error message is now changed to:

[    2.320411] Testing tracer wakeup: [    2.632565] ftrace-test (15) used greatest stack depth: 7284 bytes left
PASSED
[    2.634231] Testing tracer wakeup_rt: [    2.716312] ------------[ cut here ]------------
[    2.717208] WARNING: at /c/wfg/linux/kernel/rcutiny.c:92 rcu_idle_enter+0xf0/0x244()
[    2.718549] Hardware name: Bochs

[    2.719136] Modules linked in:
[    2.719754] 
[    2.720022] Pid: 0, comm: swapper Not tainted 3.5.0-rc6+ #55
[    2.720290] Call Trace:
[    2.720290]  [<c103704c>] warn_slowpath_common+0xfc/0x13b
[    2.720290]  [<c11057f5>] ? rcu_idle_enter+0xf0/0x244
[    2.720290]  [<c11057f5>] ? rcu_idle_enter+0xf0/0x244
[    2.720290]  [<c10370c9>] warn_slowpath_null+0x3e/0x4e
[    2.720290]  [<c11057f5>] rcu_idle_enter+0xf0/0x244
[    2.720290]  [<c100fbdb>] cpu_idle+0x159/0x220
[    2.720290]  [<c141615f>] rest_init+0x2db/0x2ef
[    2.720290]  [<c1415e84>] ? reciprocal_value+0x64/0x64
[    2.720290]  [<c171d456>] start_kernel+0x8eb/0x8ff
[    2.720290]  [<c171c62f>] ? repair_env_string+0xd3/0xd3
[    2.720290]  [<c171c342>] i386_start_kernel+0xf8/0x10b
[    2.720290] ---[ end trace 44593438a59a9533 ]---
[    2.732372] ------------[ cut here ]------------
[    2.733235] WARNING: at /c/wfg/linux/kernel/rcutiny.c:113 rcu_irq_exit+0x100/0x217()
[    2.734613] Hardware name: Bochs
[    2.735204] Modules linked in:
[    2.735817] Pid: 0, comm: swapper Tainted: G        W    3.5.0-rc6+ #55
[    2.736366] Call Trace:
[    2.736366]  [<c103704c>] warn_slowpath_common+0xfc/0x13b
[    2.736366]  [<c11055ee>] ? rcu_irq_exit+0x100/0x217
[    2.736366]  [<c11055ee>] ? rcu_irq_exit+0x100/0x217
[    2.736366]  [<c10370c9>] warn_slowpath_null+0x3e/0x4e
[    2.736366]  [<c11055ee>] rcu_irq_exit+0x100/0x217
[    2.736366]  [<c104697f>] irq_exit+0x117/0x14d
[    2.736366]  [<c1005d31>] do_IRQ+0xe5/0x106
[    2.736366]  [<c10b9fea>] ? trace_hardirqs_off_caller+0x97/0x167
[    2.736366]  [<c1045eb2>] ? local_bh_enable+0x3c/0x3c
[    2.736366]  [<c1437575>] common_interrupt+0x35/0x3c
[    2.736366]  [<c1045eb2>] ? local_bh_enable+0x3c/0x3c
[    2.736366]  [<c104007b>] ? do_wait+0x453/0x4f5
[    2.736366]  [<c104007b>] ? do_wait+0x453/0x4f5
[    2.736366]  [<c10b00e0>] ? do_timer+0xc1e/0xc77
[    2.736366]  [<c1044284>] ? arch_local_irq_enable+0x13/0x27
[    2.736366]  [<c1045f4f>] __do_softirq+0x9d/0x4fd
[    2.736366]  [<c1045eb2>] ? local_bh_enable+0x3c/0x3c
[    2.736366]  <IRQ>  [<c10468fa>] ? irq_exit+0x92/0x14d
[    2.736366]  [<c1005d31>] ? do_IRQ+0xe5/0x106
[    2.736366]  [<c10b9fea>] ? trace_hardirqs_off_caller+0x97/0x167
[    2.736366]  [<c1437575>] ? common_interrupt+0x35/0x3c
[    2.736366]  [<c10b00e0>] ? do_timer+0xc1e/0xc77
[    2.736366]  [<c1025c7b>] ? native_safe_halt+0x13/0x23
[    2.736366]  [<c100e52a>] ? default_idle+0xac/0x14a
[    2.736366]  [<c100fbef>] ? cpu_idle+0x16d/0x220
[    2.736366]  [<c141615f>] ? rest_init+0x2db/0x2ef
[    2.736366]  [<c1415e84>] ? reciprocal_value+0x64/0x64
[    2.736366]  [<c171d456>] ? start_kernel+0x8eb/0x8ff
[    2.736366]  [<c171c62f>] ? repair_env_string+0xd3/0xd3
[    2.736366]  [<c171c342>] ? i386_start_kernel+0xf8/0x10b
[    2.736366] ---[ end trace 44593438a59a9534 ]---
[    2.765933] ------------[ cut here ]------------
[    2.766811] WARNING: at /c/wfg/linux/kernel/rcutiny.c:149 rcu_idle_exit+0xfa/0x266()
[    2.768173] Hardware name: Bochs
[    2.768927] Modules linked in:
[    2.769514] Pid: 0, comm: swapper Tainted: G        W    3.5.0-rc6+ #55
[    2.769920] Call Trace:
[    2.769920]  [<c103704c>] warn_slowpath_common+0xfc/0x13b
[    2.769920]  [<c11033be>] ? rcu_idle_exit+0xfa/0x266
[    2.769920]  [<c11033be>] ? rcu_idle_exit+0xfa/0x266
[    2.769920]  [<c10370c9>] warn_slowpath_null+0x3e/0x4e
[    2.769920]  [<c11033be>] rcu_idle_exit+0xfa/0x266
[    2.769920]  [<c100fc02>] cpu_idle+0x180/0x220
[    2.769920]  [<c141615f>] rest_init+0x2db/0x2ef
[    2.769920]  [<c1415e84>] ? reciprocal_value+0x64/0x64
[    2.769920]  [<c171d456>] start_kernel+0x8eb/0x8ff
[    2.769920]  [<c171c62f>] ? repair_env_string+0xd3/0xd3
[    2.769920]  [<c171c342>] i386_start_kernel+0xf8/0x10b
[    2.769920] ---[ end trace 44593438a59a9535 ]---
[    2.988523] PASSED

The test is carried out on top of 2.5-rc6. The kvm command line is:

        kvm -cpu kvm64 -enable-kvm \
                -kernel $vmlinuz \
                -append "$APPEND BOOT_IMAGE=$BOOT_IMAGE" \
                $initrd \
                -m $mem \
                -smp 2 \
                -net nic,vlan=0,macaddr=$mac,model=e1000  \
                -net user,vlan=0,hostfwd=tcp::$port-:22 \
                -boot order=nc \
                -no-reboot \
                -watchdog i6300esb \
                $(qemu_drives) \
                -pidfile $pidfile \
                -serial file:$dmesg \
                $(test "$DISPLAY" = ":0" || echo -daemonize -nographic -monitor null)

Thanks,
Fengguang