Re: [tracing/rcu] WARNING: at kernel/lockdep.c:3537 check_flags()

[Fengguang Wu]

On Mon, Jun 24, 2013 at 09:47:22PM
 -0400, Steven Rostedt wrote:
> On Sun, 2013-06-23 at 12:19 +0800, Fengguang Wu wrote:
> > Greetings,
> > 
> > I find the below dmesg in upstream and linux-next.
> > 
> > [    2.456884] Testing tracer branch: 
> > [    2.458281]
 ------------[ cut here ]------------
> > [    2.459813] WARNING: at /c/kernel-tests/src/tip/kernel/lockdep.c:3537 check_flags+0xb7/0x1b0()
> 
> Hmm, I bet lockdep and the branch tracer probably don't play well
> together. They both are bullies, and want to beat up the same kid. The
> problem is, they want sole access to beat up that kid, and don't want
> help.
> 
> 
> > [    2.460000] Hardware name: Bochs
> > [    2.460000] Pid: 3, comm: ksoftirqd/0 Not tainted 3.9.0-rc4-03252-g8b473e1 #58
> > [    2.460000] Call Trace:
> > 
> > [    2.460000]  [<ffffffff81073cdf>] warn_slowpath_common+0xaf/0xd0
> > [    2.460000]  [<ffffffff81073dda>] warn_slowpath_null+0x1a/0x20
> > [    2.460000]  [<ffffffff810e14f7>] check_flags+0xb7/0x1b0
> > [    2.460000]  [<ffffffff810e2682>] lock_is_held+0x62/0xc0
> > [    2.460000]  [<ffffffff810c938c>] __might_sleep+0x3c/0x3b0
> > [    2.460000]  [<ffffffff81082404>] run_ksoftirqd+0xd4/0x130
> > [    2.460000]  [<ffffffff810bec5c>] smpboot_thread_fn+0x25c/0x2e0
> > [    2.460000]  [<ffffffff810bea00>] ? lg_global_unlock+0x40/0x40
> > [    2.460000]  [<ffffffff810b210b>] kthread+0xfb/0x110
> > [    2.460000]  [<ffffffff810b2010>] ? insert_kthread_work+0x120/0x120
> > [    2.460000]  [<ffffffff81825c7a>] ret_from_fork+0x7a/0xb0
> > [    2.460000]  [<ffffffff810b2010>] ? insert_kthread_work+0x120/0x120
> > [    2.460000]
 ---[ end trace 3af7e87d98c6254d ]---
> > 
> > Bisecting for "__might_sleep" and the first bad commit is
> > 
> > commit 965a002b4f1a458c5dcb334ec29f48a0046faa25
> > Author: Paul E. McKenney <paul.mckenney@xxxxxxxxxx>
> > Date:   Sat Jun 18 09:55:39 2011
 -0700
> > 
> >     rcu: Make TINY_RCU also use softirq for RCU_BOOST=n
> >     
> >     This patch #ifdefs TINY_RCU kthreads out of the kernel unless RCU_BOOST=y,
> >     thus eliminating context-switch overhead if RCU priority boosting has
> >     not been configured.
> >     
> >     Signed-off-by: Paul E. McKenney <paul.mckenney@xxxxxxxxxx>
> >     Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
> > 
> > But note that its parent commit 385680a9487d2f85382ad6d74e2a15837e47bfd9
> > is not really clean and has this dmesg instead:
> > 
> > [    2.592748] Testing tracer wakeup_rt: PASSED
> > [    2.936495] Testing tracer branch: 
> > [    2.940281]
 ------------[ cut here ]------------
> > [    2.941194] WARNING: at /c/wfg/mm/kernel/lockdep.c:3363 check_flags.part.31+0xaf/0x1c0()
> > [    2.942593] Hardware name: Bochs
> > [    2.943199] Pid: 0, comm: swapper Not tainted 3.1.0-rc8-00019-g385680a #99
> > [    2.944234] Call Trace:
> > [    2.944234]  <IRQ>  [<ffffffff81050b9e>] warn_slowpath_common+0x9e/0xd0
> > [    2.944234]  [<ffffffff81050caa>] warn_slowpath_null+0x1a/0x20
> > [    2.944234]  [<ffffffff8109fddf>] check_flags.part.31+0xaf/0x1c0
> > [    2.944234]  [<ffffffff810a49a9>] lock_acquire+0x119/0x230
> > [    2.944234]  [<ffffffff810657c7>] run_timer_softirq+0x217/0x8a0
> > [    2.944234]  [<ffffffff81065751>] ? run_timer_softirq+0x1a1/0x8a0
> > [    2.944234]  [<ffffffff810655a0>] ? ftrace_raw_output_itimer_expire+0x160/0x160
> > [    2.944234]  [<ffffffff8105c190>] __do_softirq+0x1c0/0x5c0
> > [    2.944234]  [<ffffffff815b8f7a>] call_softirq+0x1a/0x30
> > [    2.944234]  [<ffffffff81006465>] do_softirq+0x165/0x290
> > [    2.944234]  [<ffffffff8105c967>] irq_exit+0xb7/0x130
> > [    2.944234]  [<ffffffff810237d7>] smp_apic_timer_interrupt+0x77/0xb0
> > [    2.944234]  [<ffffffff815b8971>] apic_timer_interrupt+0x71/0x80
> > [    2.944234]  <EOI>  [<ffffffff810e1e75>] ? ftrace_likely_update+0xc5/0x230
> > [    2.944234]  [<ffffffff810a045d>] ? trace_hardirqs_off+0xd/0x10
> > [    2.944234]  [<ffffffff8102bdab>] ? native_safe_halt+0xb/0x10
> > [    2.944234]  [<ffffffff8100f893>] default_idle+0x7d3/0x810
> > [    2.944234]  [<ffffffff8100131c>] cpu_idle+0x14c/0x160
> > [    2.944234]  [<ffffffff815922f3>] rest_init+0xe7/0xf4
> > [    2.944234]  [<ffffffff8159220c>] ? csum_partial_copy_generic+0x16c/0x16c
> > [    2.944234]  [<ffffffff81c33f15>] start_kernel+0x4f4/0x4ff
> > [    2.944234]  [<ffffffff81c33000>] ? vsyscall_gtod_data+0xf80/0xf80
> > [    2.944234]  [<ffffffff81c33000>] ? vsyscall_gtod_data+0xf80/0xf80
> > [    2.944234]  [<ffffffff81c33169>] x86_64_start_reservations+0x166/0x16a
> > [    2.944234]  [<ffffffff81c333dd>] x86_64_start_kernel+0x270/0x27f
> > [    2.944234]
 ---[ end trace 6d450e935ee1897c ]---
> > [    2.944234] possible reason: unannotated irqs-on.
> > [    2.944234] irq event stamp: 10085
> > [    2.944234] hardirqs last  enabled at (10084): [<ffffffff815b6892>] _raw_spin_unlock_irq+0x32/0x80
> > [    2.944234] hardirqs last disabled at (10085): [<ffffffff810e1e37>] ftrace_likely_update+0x87/0x230
> 
> irqs were last disabled at ftrace_likely_update(), perhaps the branch
> tracer called something in the wrong place.
> 
> I took your config, and I'm unable to reproduce this. Does this only
> happen on virt boxes?

Sorry I don't run tests on real machines for now. The kvm command line
is something close to this:

qemu-system-x86_64
 -cpu kvm64
 -enable-kvm
 -kernel /tmp//kernel/x86_64-randconfig-c29-0622/c0a4b933aa6fb8bdc21cb854633ea07779cda2b1/vmlinuz-3.10.0-rc7-next-20130625-08594-gc0a4b93-23753
 -append 'hung_task_panic=1 rcutree.rcu_cpu_stall_timeout=100 log_buf_len=8M ignore_loglevel debug sched_debug apic=debug dynamic_printk sysrq_always_enabled panic=10  prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal  root=/dev/ram0 rw'
 -initrd /kernel-tests/initrd/quantal-core-x86_64.cgz
 -m 256M
 -smp 2
 -net nic,vlan=0,macaddr=00:00:00:00:00:00,model=virtio
 -net user,vlan=0,hostfwd=tcp::27849-:22
 -net nic,vlan=1,model=e1000
 -net user,vlan=1
 -boot order=nc
 -no-reboot
 -watchdog i6300esb
 -drive file=/fs/LABEL=KVM/diska-roam-23753,media=disk,if=virtio
 -drive file=/fs/LABEL=KVM/diskb-roam-23753,media=disk,if=virtio
 -drive file=/fs/LABEL=KVM/diskc-roam-23753,media=disk,if=virtio
 -drive file=/fs/LABEL=KVM/diskd-roam-23753,media=disk,if=virtio
 -drive file=/fs/LABEL=KVM/diske-roam-23753,media=disk,if=virtio
 -drive file=/fs/LABEL=KVM/diskf-roam-23753,media=disk,if=virtio
 -pidfile /dev/shm/kboot/pid-roam-lkp-23753
 -serial file:/dev/shm/kboot/serial-roam-lkp-23753
 -daemonize
 -display none
 -monitor null 

Thanks,
Fengguang
--
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/