lkml.org 
[lkml]   [2009]   [Nov]   [11]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    SubjectRe: Hard lockup with timer events
    From
    Date
    On Thu, 2009-10-29 at 20:15 +0100, Soeren Sandmann wrote:
    > Hi,
    >
    > This program
    >
    > http://www.daimi.au.dk/~sandmann/lockup.c
    >
    > locks up hard for me on a Pentium 4 in 32 bit mode, with the hrtimer
    > patches applied (-tip for example).
    >
    > What the program does is spawn a thread that just spins, and then 400
    > threads that each create a performance counter of type
    > PERF_COUNT_SW_CPU_CLOCK and a sample period of 1000000 and a
    > sample_type of
    >
    > PERF_SAMPLE_IP | PERF_SAMPLE_TID | PERF_SAMPLE_CALLCHAIN
    >
    > These threads then map the event buffer and read it continuously.
    >
    > It does not apparently lock up if SAMPLE_CALLCHAIN is removed; also I
    > cannot get it to lock up on Core 2 Duo in either 32 or 64 bit mode.

    My dual-core opteron running a 64bit kernel is decidedly unhappy about
    it too... no console, no ping, but a constant stream of softlockup msgs
    might give a clue, will poke at it.

    [ 327.635584] hrtimer: interrupt too slow, forcing clock min delta to 51117 ns
    [ 391.916984] BUG: soft lockup - CPU#1 stuck for 61s! [lockup:2313]
    [ 391.916984] Modules linked in: nfsd exportfs autofs4 nfs lockd nfs_acl auth_rpcgss sunrpc cpufreq_ondemand kvm_amd kvm uinput sr_mod floppy cdrom pcspkr sg serio_raw button shpchp [last unloaded: scsi_wait_scan]
    [ 391.916984] irq event stamp: 211957
    [ 391.916984] hardirqs last enabled at (211956): [<ffffffff813660c0>] restore_args+0x0/0x30
    [ 391.916984] hardirqs last disabled at (211957): [<ffffffff81002bd7>] save_args+0x67/0x70
    [ 391.916984] softirqs last enabled at (1222): [<ffffffff8104b8fc>] __do_softirq+0x21e/0x22e
    [ 391.916984] softirqs last disabled at (1303): [<ffffffff81003d7c>] call_softirq+0x1c/0x3e
    [ 391.916984] CPU 1
    [ 391.916984] Modules linked in: nfsd exportfs autofs4 nfs lockd nfs_acl auth_rpcgss sunrpc cpufreq_ondemand kvm_amd kvm uinput sr_mod floppy cdrom pcspkr sg serio_raw button shpchp [last unloaded: scsi_wait_scan]
    [ 391.916984] Pid: 2313, comm: lockup Not tainted 2.6.32-rc6-tip+ #6 To Be Filled By O.E.M.
    [ 391.916984] RIP: 0010:[<ffffffff810751f4>] [<ffffffff810751f4>] lock_release+0x1ac/0x1b9
    [ 391.916984] RSP: 0000:ffff880005e03850 EFLAGS: 00000246
    [ 391.916984] RAX: ffff88007ce966c0 RBX: ffff880005e03880 RCX: 0000000000000001
    [ 391.916984] RDX: 0000004c527a1a29 RSI: ffffffff810654a1 RDI: 0000000000000001
    [ 391.916984] RBP: ffffffff81003753 R08: ffff88007ebb36c0 R09: 03c01e08c8078259
    [ 391.916984] R10: 0000000000000000 R11: ffff88007efe58a0 R12: ffff880005e037d0
    [ 391.916984] R13: ffffffff815774d0 R14: ffff88007ce966c0 R15: ffffffff8136b547
    [ 391.916984] FS: 00007f9da116d710(0000) GS:ffff880005e00000(0000) knlGS:00000000f75b26c0
    [ 391.916984] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
    [ 391.916984] CR2: 00007f9db408b000 CR3: 000000007ce46000 CR4: 00000000000006e0
    [ 391.916984] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
    [ 391.916984] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    [ 391.916984] Process lockup (pid: 2313, threadinfo ffff88007eeac000, task ffff88007ce966c0)
    [ 391.916984] Stack:
    [ 391.916984] ffff88007ebb36c0 ffff88007efe5800 ffff88007f996980 0000000000000000
    [ 391.916984] <0> ffff88007ebb36c0 ffff88007efe5880 ffff880005e038d0 ffffffff812fb3e6
    [ 391.916984] <0> ffffffff812fb16e ffff88007f9ee000 ffff88007efe58a0 ffff88007fa88740
    [ 391.916984] Call Trace:
    [ 391.916984] <IRQ>
    [ 391.916984] [<ffffffff812fb3e6>] ? dev_queue_xmit+0x401/0x43a
    [ 391.916984] [<ffffffff812fb16e>] ? dev_queue_xmit+0x189/0x43a
    [ 391.916984] [<ffffffff8131af48>] ? ip_finish_output+0x26e/0x2b7
    [ 391.916984] [<ffffffff81008eaf>] ? native_sched_clock+0x37/0x71
    [ 391.916984] [<ffffffff8131b025>] ? ip_output+0x94/0x9d
    [ 391.916984] [<ffffffff8131867e>] ? ip_local_out+0x65/0x67
    [ 391.916984] [<ffffffff8131a891>] ? ip_queue_xmit+0x2f5/0x36e
    [ 391.916984] [<ffffffff810718c2>] ? mark_held_locks+0x4d/0x6b
    [ 391.916984] [<ffffffff810f0f37>] ? __kmalloc+0xc6/0x152
    [ 391.916984] [<ffffffff8132bf14>] ? tcp_transmit_skb+0x63a/0x679
    [ 391.916984] [<ffffffff8132c139>] ? tcp_send_ack+0x116/0x11a
    [ 391.916984] [<ffffffff81329421>] ? __tcp_ack_snd_check+0x6a/0x82
    [ 391.916984] [<ffffffff8132a0fd>] ? tcp_rcv_established+0x7f5/0x940
    [ 391.916984] [<ffffffff81330b6e>] ? tcp_v4_do_rcv+0x36/0x1dc
    [ 391.916984] [<ffffffff81365640>] ? _spin_lock_nested+0x70/0x78
    [ 391.916984] [<ffffffff81331147>] ? tcp_v4_rcv+0x433/0x63e
    [ 391.916984] [<ffffffff8131633b>] ? ip_local_deliver+0x6c/0x1b5
    [ 391.916984] [<ffffffff813163bd>] ? ip_local_deliver+0xee/0x1b5
    [ 391.916984] [<ffffffff8131633b>] ? ip_local_deliver+0x6c/0x1b5
    [ 391.916984] [<ffffffff81316296>] ? ip_rcv+0x5a2/0x5db
    [ 391.916984] [<ffffffff812f9b8c>] ? netif_receive_skb+0x311/0x36f
    [ 391.916984] [<ffffffff812f9a0c>] ? netif_receive_skb+0x191/0x36f
    [ 391.916984] [<ffffffff81279488>] ? e1000_clean_rx_irq+0x372/0x438
    [ 391.916984] [<ffffffff8127bfdc>] ? e1000_clean+0x317/0x49f
    [ 391.916984] [<ffffffff810bf640>] ? perf_output_end+0x65/0x7e
    [ 391.916984] [<ffffffff812fa425>] ? net_rx_action+0xdc/0x283
    [ 391.916984] [<ffffffff812fa57f>] ? net_rx_action+0x236/0x283
    [ 391.916984] [<ffffffff810654a1>] ? cpu_clock+0x2d/0x3f
    [ 391.916984] [<ffffffff8104b81d>] ? __do_softirq+0x13f/0x22e
    [ 391.916984] [<ffffffff81070059>] ? lock_release_holdtime+0x102/0x107
    [ 391.916984] [<ffffffff81003d7c>] ? call_softirq+0x1c/0x3e
    [ 391.916984] [<ffffffff81005391>] ? do_softirq+0x3d/0x88
    [ 391.916984] [<ffffffff8104b2fe>] ? irq_exit+0x4a/0x92
    [ 391.916984] [<ffffffff8136b4aa>] ? do_IRQ+0xb2/0xc9
    [ 391.916984] [<ffffffff81366013>] ? ret_from_intr+0x0/0xf
    [ 391.916984] <EOI>
    [ 391.916984] Code: e8 89 ad ff ff eb 0e 4c 89 ea 4c 89 e6 48 89 df e8 e5 fb ff ff 65 48 8b 04 25 00 b5 00 00 c7 80 84 07 00 00 00 00 00 00 41 57 9d <41> 58 5b 41 5c 41 5d 41 5e 41 5f c9 c3 55 65 48 8b 04 25 00 b5
    [ 391.916984] Call Trace:
    [ 391.916984] <IRQ> [<ffffffff812fb3e6>] ? dev_queue_xmit+0x401/0x43a
    [ 391.916984] [<ffffffff812fb16e>] ? dev_queue_xmit+0x189/0x43a
    [ 391.916984] [<ffffffff8131af48>] ? ip_finish_output+0x26e/0x2b7
    [ 391.916984] [<ffffffff81008eaf>] ? native_sched_clock+0x37/0x71
    [ 391.916984] [<ffffffff8131b025>] ? ip_output+0x94/0x9d
    [ 391.916984] [<ffffffff8131867e>] ? ip_local_out+0x65/0x67
    [ 391.916984] [<ffffffff8131a891>] ? ip_queue_xmit+0x2f5/0x36e
    [ 391.916984] [<ffffffff810718c2>] ? mark_held_locks+0x4d/0x6b
    [ 391.916984] [<ffffffff810f0f37>] ? __kmalloc+0xc6/0x152
    [ 391.916984] [<ffffffff8132bf14>] ? tcp_transmit_skb+0x63a/0x679
    [ 391.916984] [<ffffffff8132c139>] ? tcp_send_ack+0x116/0x11a
    [ 391.916984] [<ffffffff81329421>] ? __tcp_ack_snd_check+0x6a/0x82
    [ 391.916984] [<ffffffff8132a0fd>] ? tcp_rcv_established+0x7f5/0x940
    [ 391.916984] [<ffffffff81330b6e>] ? tcp_v4_do_rcv+0x36/0x1dc
    [ 391.916984] [<ffffffff81365640>] ? _spin_lock_nested+0x70/0x78
    [ 391.916984] [<ffffffff81331147>] ? tcp_v4_rcv+0x433/0x63e
    [ 391.916984] [<ffffffff8131633b>] ? ip_local_deliver+0x6c/0x1b5
    [ 391.916984] [<ffffffff813163bd>] ? ip_local_deliver+0xee/0x1b5
    [ 391.916984] [<ffffffff8131633b>] ? ip_local_deliver+0x6c/0x1b5
    [ 391.916984] [<ffffffff81316296>] ? ip_rcv+0x5a2/0x5db
    [ 391.916984] [<ffffffff812f9b8c>] ? netif_receive_skb+0x311/0x36f
    [ 391.916984] [<ffffffff812f9a0c>] ? netif_receive_skb+0x191/0x36f
    [ 391.916984] [<ffffffff81279488>] ? e1000_clean_rx_irq+0x372/0x438
    [ 391.916984] [<ffffffff8127bfdc>] ? e1000_clean+0x317/0x49f
    [ 391.916984] [<ffffffff810bf640>] ? perf_output_end+0x65/0x7e
    [ 391.916984] [<ffffffff812fa425>] ? net_rx_action+0xdc/0x283
    [ 391.916984] [<ffffffff812fa57f>] ? net_rx_action+0x236/0x283
    [ 391.916984] [<ffffffff810654a1>] ? cpu_clock+0x2d/0x3f
    [ 391.916984] [<ffffffff8104b81d>] ? __do_softirq+0x13f/0x22e
    [ 391.916984] [<ffffffff81070059>] ? lock_release_holdtime+0x102/0x107
    [ 391.916984] [<ffffffff81003d7c>] ? call_softirq+0x1c/0x3e
    [ 391.916984] [<ffffffff81005391>] ? do_softirq+0x3d/0x88
    [ 391.916984] [<ffffffff8104b2fe>] ? irq_exit+0x4a/0x92
    [ 391.916984] [<ffffffff8136b4aa>] ? do_IRQ+0xb2/0xc9
    [ 391.916984] [<ffffffff81366013>] ? ret_from_intr+0x0/0xf
    [ 391.916984] <EOI>
    [ 392.990186] BUG: soft lockup - CPU#0 stuck for 61s! [distccd:1734]
    [ 392.990186] Modules linked in: nfsd exportfs autofs4 nfs lockd nfs_acl auth_rpcgss sunrpc cpufreq_ondemand kvm_amd kvm uinput sr_mod floppy cdrom pcspkr sg serio_raw button shpchp [last unloaded: scsi_wait_scan]
    [ 392.990186] irq event stamp: 970145
    [ 392.990186] hardirqs last enabled at (970144): [<ffffffff813660c0>] restore_args+0x0/0x30
    [ 392.990186] hardirqs last disabled at (970145): [<ffffffff81002bd7>] save_args+0x67/0x70
    [ 392.990186] softirqs last enabled at (105208): [<ffffffff8104b8fc>] __do_softirq+0x21e/0x22e
    [ 392.990186] softirqs last disabled at (105334): [<ffffffff813656d5>] _spin_lock_bh+0x18/0x7b
    [ 392.990186] CPU 0
    [ 392.990186] Modules linked in: nfsd exportfs autofs4 nfs lockd nfs_acl auth_rpcgss sunrpc cpufreq_ondemand kvm_amd kvm uinput sr_mod floppy cdrom pcspkr sg serio_raw button shpchp [last unloaded: scsi_wait_scan]
    [ 392.990186] Pid: 1734, comm: distccd Not tainted 2.6.32-rc6-tip+ #6 To Be Filled By O.E.M.
    [ 392.990186] RIP: 0010:[<ffffffff811c54af>] [<ffffffff811c54af>] delay_tsc+0x2e/0xcf
    [ 392.990186] RSP: 0018:ffff88007e18dd38 EFLAGS: 00000202
    [ 392.990186] RAX: 0000000000000000 RBX: ffff88007e18dd68 RCX: ffffffff81330fc9
    [ 392.990186] RDX: ffffffff811c54c5 RSI: 0000000000000001 RDI: 0000000000000001
    [ 392.990186] RBP: ffffffff8100374e R08: ffff88007e18a780 R09: 000000000000020f
    [ 392.990186] R10: ffffffff815b8010 R11: 0000000000000202 R12: 000000000000027d
    [ 392.990186] R13: 00000000001d2ec0 R14: ffff88007e18c000 R15: ffff88007e18dfd8
    [ 392.990186] FS: 00007f9db3992710(0000) GS:ffff880005c00000(0063) knlGS:00000000f75b26c0
    [ 392.990186] CS: 0010 DS: 002b ES: 002b CR0: 000000008005003b
    [ 392.990186] CR2: 00007f9db4126000 CR3: 000000007e072000 CR4: 00000000000006f0
    [ 392.990186] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
    [ 392.990186] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    [ 392.990186] Process distccd (pid: 1734, threadinfo ffff88007e18c000, task ffff88007e18a780)
    [ 392.990186] Stack:
    [ 392.990186] 0000000000000001 000000000ba09c7e ffff88007efb5500 0000000000000001
    [ 392.990186] <0> ffff88007e18a780 ffff88007e18ac50 ffff88007e18dd78 ffffffff811c53af
    [ 392.990186] <0> ffff88007e18ddb8 ffffffff811c96c5 000000008eaa23f8 ffff88007efb5518
    [ 392.990186] Call Trace:
    [ 392.990186] [<ffffffff811c53af>] ? __delay+0xf/0x11
    [ 392.990186] [<ffffffff811c96c5>] ? _raw_spin_lock+0xde/0x147
    [ 392.990186] [<ffffffff81365723>] ? _spin_lock_bh+0x66/0x7b
    [ 392.990186] [<ffffffff812eda05>] ? lock_sock_nested+0x28/0xf0
    [ 392.990186] [<ffffffff812eda05>] ? lock_sock_nested+0x28/0xf0
    [ 392.990186] [<ffffffff81320f8d>] ? do_tcp_setsockopt+0x9e/0x361
    [ 392.990186] [<ffffffff810f6fc5>] ? fget+0x0/0x131
    [ 392.990186] [<ffffffff8132126f>] ? compat_tcp_setsockopt+0x1f/0x21
    [ 392.990186] [<ffffffff812ecd48>] ? compat_sock_common_setsockopt+0x1d/0x25
    [ 392.990186] [<ffffffff8130a551>] ? compat_sys_setsockopt+0x1d0/0x204
    [ 392.990186] [<ffffffff8102b3e8>] ? sysretl_from_sys_call+0x2b/0x34
    [ 392.990186] [<ffffffff8130a6bf>] ? compat_sys_socketcall+0x13a/0x190
    [ 392.990186] [<ffffffff8102b398>] ? cstar_dispatch+0x7/0x2c
    [ 392.990186] Code: e5 41 57 41 56 41 55 41 54 53 48 83 ec 08 0f 1f 44 00 00 49 89 fc bf 01 00 00 00 e8 e7 38 1a 00 e8 83 4e 00 00 41 89 c6 0f ae f0 <66> 66 90 0f 31 89 c3 65 4c 8b 3c 25 08 b5 00 00 0f ae f0 66 66
    [ 392.990186] Call Trace:
    [ 392.990186] [<ffffffff811c54a9>] ? delay_tsc+0x28/0xcf
    [ 392.990186] [<ffffffff811c53af>] ? __delay+0xf/0x11
    [ 392.990186] [<ffffffff811c96c5>] ? _raw_spin_lock+0xde/0x147
    [ 392.990186] [<ffffffff81365723>] ? _spin_lock_bh+0x66/0x7b
    [ 392.990186] [<ffffffff812eda05>] ? lock_sock_nested+0x28/0xf0
    [ 392.990186] [<ffffffff812eda05>] ? lock_sock_nested+0x28/0xf0
    [ 392.990186] [<ffffffff81320f8d>] ? do_tcp_setsockopt+0x9e/0x361
    [ 392.990186] [<ffffffff810f6fc5>] ? fget+0x0/0x131
    [ 392.990186] [<ffffffff8132126f>] ? compat_tcp_setsockopt+0x1f/0x21
    [ 392.990186] [<ffffffff812ecd48>] ? compat_sock_common_setsockopt+0x1d/0x25
    [ 392.990186] [<ffffffff8130a551>] ? compat_sys_setsockopt+0x1d0/0x204
    [ 392.990186] [<ffffffff8102b3e8>] ? sysretl_from_sys_call+0x2b/0x34
    [ 392.990186] [<ffffffff8130a6bf>] ? compat_sys_socketcall+0x13a/0x190
    [ 392.990186] [<ffffffff8102b398>] ? cstar_dispatch+0x7/0x2c


    \
     
     \ /
      Last update: 2009-11-11 14:51    [W:0.035 / U:0.444 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site