On Nov 16, 2007 3:15 PM, Kamalesh Babulal <kamalesh@linux.vnet.ibm.com> wrote:
[snip]
Definitely not a ppc problem.
Got nearly the same backtrace on 64bit x86:
[ 966.712167] BUG: soft lockup - CPU#3 stuck for 11s! [rpciod/3:605]
[ 966.718522] CPU 3:
[ 966.720589] Modules linked in: radeon drm nfsd exportfs ipv6
w83792d tuner tea5767 tda8290 tuner_xc2028 tda9887 tuner_simple mt20xx
tea5761 tvaudio msp3400 bttv ir_common compat_ioctl32 videobuf_dma_sg
videobuf_core btcx_risc tveeprom videodev usbhid v4l2_common
v4l1_compat hid sg i2c_nforce2 pata_amd
[ 966.748306] Pid: 605, comm: rpciod/3 Not tainted 2.6.24-rc2-mm1 #4
[ 966.754653] RIP: 0010:[<ffffffff805b0542>] [<ffffffff805b0542>]
_spin_lock_irqsave+0x12/0x30
[ 966.763424] RSP: 0018:ffff81007ef33e28 EFLAGS: 00000286
[ 966.768879] RAX: 0000000000000286 RBX: ffff81007ef33e60 RCX: 0000000000000000
[ 966.776204] RDX: 0000000000000001 RSI: 0000000000000003 RDI: ffff81011e107960
[ 966.783511] RBP: ffff81011cc6c588 R08: ffff8100db918130 R09: ffff81011cc6c540
[ 966.790837] R10: 0000000000000000 R11: ffffffff80266390 R12: ffff8100d2d693a8
[ 966.798170] R13: ffff81011cc6c588 R14: ffff8100d2d693a8 R15: ffffffff80302726
[ 966.805505] FS: 00007f9e739d96f0(0000) GS:ffff81011ff12700(0000)
knlGS:0000000000000000
[ 966.813805] CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
[ 966.819703] CR2: 0000000001b691d0 CR3: 0000000069861000 CR4: 00000000000006e0
[ 966.827039] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 966.834362] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 966.841687]
[ 966.841687] Call Trace:
[ 966.845728] [<ffffffff8022cf4d>] __wake_up+0x2d/0x70
[ 966.850900] [<ffffffff802f5e6e>] nfs_free_unlinkdata+0x1e/0x50
[ 966.857004] [<ffffffff80593f66>] rpc_release_calldata+0x26/0x50
[ 966.863161] [<ffffffff80594930>] rpc_async_schedule+0x0/0x10
[ 966.869078] [<ffffffff80245cec>] run_workqueue+0xcc/0x170
[ 966.874705] [<ffffffff802467a0>] worker_thread+0x0/0xb0
[ 966.880163] [<ffffffff802467a0>] worker_thread+0x0/0xb0
[ 966.885610] [<ffffffff8024680d>] worker_thread+0x6d/0xb0
[ 966.891148] [<ffffffff8024a140>] autoremove_wake_function+0x0/0x30
[ 966.897606] [<ffffffff802467a0>] worker_thread+0x0/0xb0
[ 966.903045] [<ffffffff802467a0>] worker_thread+0x0/0xb0
[ 966.908485] [<ffffffff80249d5b>] kthread+0x4b/0x80
[ 966.913484] [<ffffffff8020ca28>] child_rip+0xa/0x12
[ 966.918579] [<ffffffff80249d10>] kthread+0x0/0x80
[ 966.923498] [<ffffffff8020ca1e>] child_rip+0x0/0x12
[ 966.928584]
Sadly lockdep does not work for me, as it gets turned off early:
[ 39.851594] ---------------------------------
[ 39.855963] inconsistent {softirq-on-W} -> {in-softirq-W} usage.
[ 39.861981] swapper/0 [HC0[0]:SC1[1]:HE0:SE0] takes:
[ 39.866963] (&n->list_lock){-+..}, at: [<ffffffff802935c1>]
add_partial+0x31/0xa0
[ 39.874712] {softirq-on-W} state was registered at:
[ 39.879788] [<ffffffff80259fb8>] __lock_acquire+0x3e8/0x1140
[ 39.885763] [<ffffffff80259838>] debug_check_no_locks_freed+0x188/0x1a0
[ 39.892682] [<ffffffff8025ad65>] lock_acquire+0x55/0x70
[ 39.898840] [<ffffffff802935c1>] add_partial+0x31/0xa0
[ 39.904288] [<ffffffff805c76de>] _spin_lock+0x1e/0x30
[ 39.909650] [<ffffffff802935c1>] add_partial+0x31/0xa0
[ 39.915097] [<ffffffff80296f9c>] kmem_cache_open+0x1cc/0x330
[ 39.921066] [<ffffffff805c7984>] _spin_unlock_irq+0x24/0x30
[ 39.926946] [<ffffffff802974f4>] create_kmalloc_cache+0x64/0xf0
[ 39.933172] [<ffffffff80295640>] init_alloc_cpu_cpu+0x70/0x90
[ 39.939226] [<ffffffff8080ada5>] kmem_cache_init+0x65/0x1d0
[ 39.945289] [<ffffffff807f1b4e>] start_kernel+0x23e/0x350
[ 39.950996] [<ffffffff807f112d>] _sinittext+0x12d/0x140
[ 39.956529] [<ffffffffffffffff>] 0xffffffffffffffff
[ 39.961720] irq event stamp: 1207
[ 39.965048] hardirqs last enabled at (1206): [<ffffffff80259838>]
debug_check_no_locks_freed+0x188/0x1a0
[ 39.974701] hardirqs last disabled at (1207): [<ffffffff802952eb>]
__slab_free+0x3b/0x190
[ 39.982968] softirqs last enabled at (570): [<ffffffff8020cf0c>]
call_softirq+0x1c/0x30
[ 39.991148] softirqs last disabled at (1197): [<ffffffff8020cf0c>]
call_softirq+0x1c/0x30
[ 39.999415]
[ 39.999416] other info that might help us debug this:
[ 40.005990] no locks held by swapper/0.
[ 40.010018]
[ 40.010018] stack backtrace:
[ 40.014429]
[ 40.014429] Call Trace:
[ 40.018407] <IRQ> [<ffffffff8025847c>] print_usage_bug+0x18c/0x1a0
[ 40.024817] [<ffffffff802593ec>] mark_lock+0x64c/0x660
[ 40.030057] [<ffffffff80259f6e>] __lock_acquire+0x39e/0x1140
[ 40.035818] [<ffffffff80257717>] save_trace+0x37/0xa0
[ 40.040972] [<ffffffff802492cd>] __rcu_process_callbacks+0x8d/0x250
[ 40.047335] [<ffffffff8025ad65>] lock_acquire+0x55/0x70
[ 40.052663] [<ffffffff802935c1>] add_partial+0x31/0xa0
[ 40.057905] [<ffffffff802595d3>] trace_hardirqs_on+0x83/0x160
[ 40.063750] [<ffffffff805c76de>] _spin_lock+0x1e/0x30
[ 40.068905] [<ffffffff802935c1>] add_partial+0x31/0xa0
[ 40.074311] [<ffffffff802953b0>] __slab_free+0x100/0x190
[ 40.079724] [<ffffffff802492cd>] __rcu_process_callbacks+0x8d/0x250
[ 40.086088] [<ffffffff8023b79c>] tasklet_action+0x2c/0xc0
[ 40.091588] [<ffffffff802494b3>] rcu_process_callbacks+0x23/0x50
[ 40.097694] [<ffffffff8023b7ba>] tasklet_action+0x4a/0xc0
[ 40.103194] [<ffffffff8023b67a>] __do_softirq+0x7a/0x100
[ 40.108607] [<ffffffff8020cf0c>] call_softirq+0x1c/0x30
[ 40.113935] [<ffffffff8020f125>] do_softirq+0x55/0xb0
[ 40.119089] [<ffffffff8023b5f7>] irq_exit+0x97/0xa0
[ 40.124073] [<ffffffff8021bf2c>] smp_apic_timer_interrupt+0x7c/0xc0
[ 40.130434] [<ffffffff8020ac70>] default_idle+0x0/0x60
[ 40.135840] [<ffffffff8020ac70>] default_idle+0x0/0x60
[ 40.141080] [<ffffffff8020c9bb>] apic_timer_interrupt+0x6b/0x70
[ 40.147100] <EOI> [<ffffffff8020aca7>] default_idle+0x37/0x60
[ 40.153066] [<ffffffff8020aca5>] default_idle+0x35/0x60
[ 40.158393] [<ffffffff8020ad2f>] cpu_idle+0x5f/0x90
[ 40.163374]
[ 40.164888] INFO: lockdep is turned off.
Don't know who to bug about that.
Torsten
-
