Re: soft lockup in sysvipc code.
Dave Jones wrote: > Haven't seen this before. > Tree based on v3.11-3104-gf357a82 > > BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] A combination of hard and soft locks is the solution to the problem, ultimately. > Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG > nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 > phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda > crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc > ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec > snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd > soundcore pcspkr usb_debug e1000e ptp pps_core Changing hardware results in some downtime, but has to be done every once in a while. > irq event stamp: 1143030 > hardirqs last enabled at (1143029): [] > restore_args+0x0/0x30 > hardirqs last disabled at (1143030): [] > apic_timer_interrupt+0x6a/0x80 > softirqs last enabled at (1143028): [] > __do_softirq+0x198/0x460 > softirqs last disabled at (1143023): [] irq_exit+0x135/0x150 > CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 Don't taint in a hurry; that'll result in breakages. > task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 Error: ti is too extreme. > RIP: 0010:[] [] > idr_find_slowpath+0x9b/0x150 > RSP: 0018:88022bd8dc88 EFLAGS: 0206 > RAX: 0006 RBX: 000a6c0a RCX: 0008 > RDX: 0008 RSI: 81c41040 RDI: 88022c014668 > RBP: 88022bd8dca0 R08: R09: > R10: 0001 R11: 0001 R12: 88023831a290 > R13: 0001 R14: 88022bd8dbe8 R15: 8802449d > FS: 7fcfcad2c740() GS:88024480() knlGS: > CS: 0010 DS: ES: CR0: 80050033 > CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 > DR0: DR1: DR2: > DR3: DR6: fffe0ff0 DR7: 0400 That's the lifecycle of the process. > Stack: > 0260 2dba 81c7e258 88022bd8dcf8 > 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 > 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 In the beginning, there was quite a bit of downtime: lately, it's becoming highly consistent. > Call Trace: > [] sysvipc_find_ipc+0x61/0x300 > [] sysvipc_proc_next+0x46/0xd0 > [] traverse.isra.7+0xc9/0x260 > [] ? lock_release_non_nested+0x308/0x350 > [] seq_read+0x3e1/0x450 > [] ? proc_reg_write+0x80/0x80 > [] proc_reg_read+0x3d/0x80 > [] do_loop_readv_writev+0x63/0x90 > [] do_readv_writev+0x21d/0x240 > [] ? local_clock+0x3f/0x50 > [] ? context_tracking_user_exit+0x46/0x1a0 > [] vfs_readv+0x35/0x60 > [] SyS_preadv+0xa2/0xd0 > [] tracesys+0xdd/0xe2 > Code: 7e 6e 41 8b 84 24 2c 08 00 00 83 eb 08 c1 e0 03 39 c3 0f 85 c1 00 00 00 > 89 d9 44 89 e8 d3 f8 0f b6 c0 48 83 c0 04 4d 8b 64 c4 08 80 b4 d6 ff 85 > c0 74 c4 80 3d f7 2f 9d 00 00 75 bb e8 6e b4 Sequential read after lock was released. vfs came before local clock and context tracking, so there seems to be an ordering issue. -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
On Sun, Sep 08, 2013 at 06:20:18PM -0700, Davidlohr Bueso wrote: > On Sat, 2013-09-07 at 11:11 +0200, Manfred Spraul wrote: > > Hi Dave, > > > > On 09/04/2013 11:50 PM, Dave Jones wrote: > > > Haven't seen this before. > > > Tree based on v3.11-3104-gf357a82 > > > > > > BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] > > > Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp > > > ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket > > > caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox > > > ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk > > > ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c > > > snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm > > > snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp > > > pps_core > > > irq event stamp: 1143030 > > > hardirqs last enabled at (1143029): [] > > > restore_args+0x0/0x30 > > > hardirqs last disabled at (1143030): [] > > > apic_timer_interrupt+0x6a/0x80 > > > softirqs last enabled at (1143028): [] > > > __do_softirq+0x198/0x460 > > > softirqs last disabled at (1143023): [] > > > irq_exit+0x135/0x150 > > > CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 > > > task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 > > > RIP: 0010:[] [] > > > idr_find_slowpath+0x9b/0x150 > > > RSP: 0018:88022bd8dc88 EFLAGS: 0206 > > > RAX: 0006 RBX: 000a6c0a RCX: 0008 > > > RDX: 0008 RSI: 81c41040 RDI: 88022c014668 > > > RBP: 88022bd8dca0 R08: R09: > > > R10: 0001 R11: 0001 R12: 88023831a290 > > > R13: 0001 R14: 88022bd8dbe8 R15: 8802449d > > > FS: 7fcfcad2c740() GS:88024480() > > > knlGS: > > > CS: 0010 DS: ES: CR0: 80050033 > > > CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 > > > DR0: DR1: DR2: > > > DR3: DR6: fffe0ff0 DR7: 0400 > > > Stack: > > > 0260 2dba 81c7e258 88022bd8dcf8 > > > 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 > > > 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 > > > Call Trace: > > > [] sysvipc_find_ipc+0x61/0x300 > > > [] sysvipc_proc_next+0x46/0xd0 > > > [] traverse.isra.7+0xc9/0x260 > > > [] ? lock_release_non_nested+0x308/0x350 > > > [] seq_read+0x3e1/0x450 > > > [] ? proc_reg_write+0x80/0x80 > > > [] proc_reg_read+0x3d/0x80 > > Do you have any details about load? > > > > I haven't seen it either - but I don't have a stress test that does > > #while true;cat /proc/sysvipc/*>/dev/null;done > > in parallel with create/remove/whatever operations. > > > > Davidlohr: Have you done any stress tests for the /proc interface? > > > > I don't. I tried reproducing the issue by a trivial multithreaded > program were each CPU does parallel reads to the > different /proc/sysvipc/ files, but no luck triggering any lockups. > > Dave, are you able to reproduce this on demand? Any chance of bisecting > this? I hit it 2-3 times last week. Tomorrow I'll try more focussed testing. Hopefully I can come up with a trinity invocation that will repro it quickly. I'm guessing this is just /proc/sysipc/* right ? Dave -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
On Sat, 2013-09-07 at 11:11 +0200, Manfred Spraul wrote: > Hi Dave, > > On 09/04/2013 11:50 PM, Dave Jones wrote: > > Haven't seen this before. > > Tree based on v3.11-3104-gf357a82 > > > > BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] > > Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp > > ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket > > caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox > > ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk > > ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c > > snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm > > snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core > > irq event stamp: 1143030 > > hardirqs last enabled at (1143029): [] > > restore_args+0x0/0x30 > > hardirqs last disabled at (1143030): [] > > apic_timer_interrupt+0x6a/0x80 > > softirqs last enabled at (1143028): [] > > __do_softirq+0x198/0x460 > > softirqs last disabled at (1143023): [] > > irq_exit+0x135/0x150 > > CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 > > task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 > > RIP: 0010:[] [] > > idr_find_slowpath+0x9b/0x150 > > RSP: 0018:88022bd8dc88 EFLAGS: 0206 > > RAX: 0006 RBX: 000a6c0a RCX: 0008 > > RDX: 0008 RSI: 81c41040 RDI: 88022c014668 > > RBP: 88022bd8dca0 R08: R09: > > R10: 0001 R11: 0001 R12: 88023831a290 > > R13: 0001 R14: 88022bd8dbe8 R15: 8802449d > > FS: 7fcfcad2c740() GS:88024480() knlGS: > > CS: 0010 DS: ES: CR0: 80050033 > > CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 > > DR0: DR1: DR2: > > DR3: DR6: fffe0ff0 DR7: 0400 > > Stack: > > 0260 2dba 81c7e258 88022bd8dcf8 > > 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 > > 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 > > Call Trace: > > [] sysvipc_find_ipc+0x61/0x300 > > [] sysvipc_proc_next+0x46/0xd0 > > [] traverse.isra.7+0xc9/0x260 > > [] ? lock_release_non_nested+0x308/0x350 > > [] seq_read+0x3e1/0x450 > > [] ? proc_reg_write+0x80/0x80 > > [] proc_reg_read+0x3d/0x80 > Do you have any details about load? > > I haven't seen it either - but I don't have a stress test that does > #while true;cat /proc/sysvipc/*>/dev/null;done > in parallel with create/remove/whatever operations. > > Davidlohr: Have you done any stress tests for the /proc interface? > I don't. I tried reproducing the issue by a trivial multithreaded program were each CPU does parallel reads to the different /proc/sysvipc/ files, but no luck triggering any lockups. Dave, are you able to reproduce this on demand? Any chance of bisecting this? Thanks, Davidlohr > -- > Manfred -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
On Sat, 2013-09-07 at 11:11 +0200, Manfred Spraul wrote: Hi Dave, On 09/04/2013 11:50 PM, Dave Jones wrote: Haven't seen this before. Tree based on v3.11-3104-gf357a82 BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core irq event stamp: 1143030 hardirqs last enabled at (1143029): [81715d5c] restore_args+0x0/0x30 hardirqs last disabled at (1143030): [8171f9aa] apic_timer_interrupt+0x6a/0x80 softirqs last enabled at (1143028): [8105a938] __do_softirq+0x198/0x460 softirqs last disabled at (1143023): [8105ae55] irq_exit+0x135/0x150 CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 RIP: 0010:[8131014b] [8131014b] idr_find_slowpath+0x9b/0x150 RSP: 0018:88022bd8dc88 EFLAGS: 0206 RAX: 0006 RBX: 000a6c0a RCX: 0008 RDX: 0008 RSI: 81c41040 RDI: 88022c014668 RBP: 88022bd8dca0 R08: R09: R10: 0001 R11: 0001 R12: 88023831a290 R13: 0001 R14: 88022bd8dbe8 R15: 8802449d FS: 7fcfcad2c740() GS:88024480() knlGS: CS: 0010 DS: ES: CR0: 80050033 CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 DR0: DR1: DR2: DR3: DR6: fffe0ff0 DR7: 0400 Stack: 0260 2dba 81c7e258 88022bd8dcf8 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 Call Trace: [812b1131] sysvipc_find_ipc+0x61/0x300 [812b1416] sysvipc_proc_next+0x46/0xd0 [811e13b9] traverse.isra.7+0xc9/0x260 [810c4078] ? lock_release_non_nested+0x308/0x350 [811e1b61] seq_read+0x3e1/0x450 [81228f10] ? proc_reg_write+0x80/0x80 [81228f4d] proc_reg_read+0x3d/0x80 Do you have any details about load? I haven't seen it either - but I don't have a stress test that does #while true;cat /proc/sysvipc/*/dev/null;done in parallel with create/remove/whatever operations. Davidlohr: Have you done any stress tests for the /proc interface? I don't. I tried reproducing the issue by a trivial multithreaded program were each CPU does parallel reads to the different /proc/sysvipc/ files, but no luck triggering any lockups. Dave, are you able to reproduce this on demand? Any chance of bisecting this? Thanks, Davidlohr -- Manfred -- To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
On Sun, Sep 08, 2013 at 06:20:18PM -0700, Davidlohr Bueso wrote: On Sat, 2013-09-07 at 11:11 +0200, Manfred Spraul wrote: Hi Dave, On 09/04/2013 11:50 PM, Dave Jones wrote: Haven't seen this before. Tree based on v3.11-3104-gf357a82 BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core irq event stamp: 1143030 hardirqs last enabled at (1143029): [81715d5c] restore_args+0x0/0x30 hardirqs last disabled at (1143030): [8171f9aa] apic_timer_interrupt+0x6a/0x80 softirqs last enabled at (1143028): [8105a938] __do_softirq+0x198/0x460 softirqs last disabled at (1143023): [8105ae55] irq_exit+0x135/0x150 CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 RIP: 0010:[8131014b] [8131014b] idr_find_slowpath+0x9b/0x150 RSP: 0018:88022bd8dc88 EFLAGS: 0206 RAX: 0006 RBX: 000a6c0a RCX: 0008 RDX: 0008 RSI: 81c41040 RDI: 88022c014668 RBP: 88022bd8dca0 R08: R09: R10: 0001 R11: 0001 R12: 88023831a290 R13: 0001 R14: 88022bd8dbe8 R15: 8802449d FS: 7fcfcad2c740() GS:88024480() knlGS: CS: 0010 DS: ES: CR0: 80050033 CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 DR0: DR1: DR2: DR3: DR6: fffe0ff0 DR7: 0400 Stack: 0260 2dba 81c7e258 88022bd8dcf8 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 Call Trace: [812b1131] sysvipc_find_ipc+0x61/0x300 [812b1416] sysvipc_proc_next+0x46/0xd0 [811e13b9] traverse.isra.7+0xc9/0x260 [810c4078] ? lock_release_non_nested+0x308/0x350 [811e1b61] seq_read+0x3e1/0x450 [81228f10] ? proc_reg_write+0x80/0x80 [81228f4d] proc_reg_read+0x3d/0x80 Do you have any details about load? I haven't seen it either - but I don't have a stress test that does #while true;cat /proc/sysvipc/*/dev/null;done in parallel with create/remove/whatever operations. Davidlohr: Have you done any stress tests for the /proc interface? I don't. I tried reproducing the issue by a trivial multithreaded program were each CPU does parallel reads to the different /proc/sysvipc/ files, but no luck triggering any lockups. Dave, are you able to reproduce this on demand? Any chance of bisecting this? I hit it 2-3 times last week. Tomorrow I'll try more focussed testing. Hopefully I can come up with a trinity invocation that will repro it quickly. I'm guessing this is just /proc/sysipc/* right ? Dave -- To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
Dave Jones wrote: Haven't seen this before. Tree based on v3.11-3104-gf357a82 BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] A combination of hard and soft locks is the solution to the problem, ultimately. Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core Changing hardware results in some downtime, but has to be done every once in a while. irq event stamp: 1143030 hardirqs last enabled at (1143029): [81715d5c] restore_args+0x0/0x30 hardirqs last disabled at (1143030): [8171f9aa] apic_timer_interrupt+0x6a/0x80 softirqs last enabled at (1143028): [8105a938] __do_softirq+0x198/0x460 softirqs last disabled at (1143023): [8105ae55] irq_exit+0x135/0x150 CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 Don't taint in a hurry; that'll result in breakages. task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 Error: ti is too extreme. RIP: 0010:[8131014b] [8131014b] idr_find_slowpath+0x9b/0x150 RSP: 0018:88022bd8dc88 EFLAGS: 0206 RAX: 0006 RBX: 000a6c0a RCX: 0008 RDX: 0008 RSI: 81c41040 RDI: 88022c014668 RBP: 88022bd8dca0 R08: R09: R10: 0001 R11: 0001 R12: 88023831a290 R13: 0001 R14: 88022bd8dbe8 R15: 8802449d FS: 7fcfcad2c740() GS:88024480() knlGS: CS: 0010 DS: ES: CR0: 80050033 CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 DR0: DR1: DR2: DR3: DR6: fffe0ff0 DR7: 0400 That's the lifecycle of the process. Stack: 0260 2dba 81c7e258 88022bd8dcf8 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 In the beginning, there was quite a bit of downtime: lately, it's becoming highly consistent. Call Trace: [812b1131] sysvipc_find_ipc+0x61/0x300 [812b1416] sysvipc_proc_next+0x46/0xd0 [811e13b9] traverse.isra.7+0xc9/0x260 [810c4078] ? lock_release_non_nested+0x308/0x350 [811e1b61] seq_read+0x3e1/0x450 [81228f10] ? proc_reg_write+0x80/0x80 [81228f4d] proc_reg_read+0x3d/0x80 [811ba3a3] do_loop_readv_writev+0x63/0x90 [811bbccd] do_readv_writev+0x21d/0x240 [810994af] ? local_clock+0x3f/0x50 [81152376] ? context_tracking_user_exit+0x46/0x1a0 [811bbd25] vfs_readv+0x35/0x60 [811bbff2] SyS_preadv+0xa2/0xd0 [8171ef54] tracesys+0xdd/0xe2 Code: 7e 6e 41 8b 84 24 2c 08 00 00 83 eb 08 c1 e0 03 39 c3 0f 85 c1 00 00 00 89 d9 44 89 e8 d3 f8 0f b6 c0 48 83 c0 04 4d 8b 64 c4 08 e8 80 b4 d6 ff 85 c0 74 c4 80 3d f7 2f 9d 00 00 75 bb e8 6e b4 Sequential read after lock was released. vfs came before local clock and context tracking, so there seems to be an ordering issue. -- To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
Hi Dave, On 09/04/2013 11:50 PM, Dave Jones wrote: Haven't seen this before. Tree based on v3.11-3104-gf357a82 BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core irq event stamp: 1143030 hardirqs last enabled at (1143029): [] restore_args+0x0/0x30 hardirqs last disabled at (1143030): [] apic_timer_interrupt+0x6a/0x80 softirqs last enabled at (1143028): [] __do_softirq+0x198/0x460 softirqs last disabled at (1143023): [] irq_exit+0x135/0x150 CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 RIP: 0010:[] [] idr_find_slowpath+0x9b/0x150 RSP: 0018:88022bd8dc88 EFLAGS: 0206 RAX: 0006 RBX: 000a6c0a RCX: 0008 RDX: 0008 RSI: 81c41040 RDI: 88022c014668 RBP: 88022bd8dca0 R08: R09: R10: 0001 R11: 0001 R12: 88023831a290 R13: 0001 R14: 88022bd8dbe8 R15: 8802449d FS: 7fcfcad2c740() GS:88024480() knlGS: CS: 0010 DS: ES: CR0: 80050033 CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 DR0: DR1: DR2: DR3: DR6: fffe0ff0 DR7: 0400 Stack: 0260 2dba 81c7e258 88022bd8dcf8 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 Call Trace: [] sysvipc_find_ipc+0x61/0x300 [] sysvipc_proc_next+0x46/0xd0 [] traverse.isra.7+0xc9/0x260 [] ? lock_release_non_nested+0x308/0x350 [] seq_read+0x3e1/0x450 [] ? proc_reg_write+0x80/0x80 [] proc_reg_read+0x3d/0x80 Do you have any details about load? I haven't seen it either - but I don't have a stress test that does #while true;cat /proc/sysvipc/*>/dev/null;done in parallel with create/remove/whatever operations. Davidlohr: Have you done any stress tests for the /proc interface? -- Manfred -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
Hi Dave, On 09/04/2013 11:50 PM, Dave Jones wrote: Haven't seen this before. Tree based on v3.11-3104-gf357a82 BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core irq event stamp: 1143030 hardirqs last enabled at (1143029): [81715d5c] restore_args+0x0/0x30 hardirqs last disabled at (1143030): [8171f9aa] apic_timer_interrupt+0x6a/0x80 softirqs last enabled at (1143028): [8105a938] __do_softirq+0x198/0x460 softirqs last disabled at (1143023): [8105ae55] irq_exit+0x135/0x150 CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 RIP: 0010:[8131014b] [8131014b] idr_find_slowpath+0x9b/0x150 RSP: 0018:88022bd8dc88 EFLAGS: 0206 RAX: 0006 RBX: 000a6c0a RCX: 0008 RDX: 0008 RSI: 81c41040 RDI: 88022c014668 RBP: 88022bd8dca0 R08: R09: R10: 0001 R11: 0001 R12: 88023831a290 R13: 0001 R14: 88022bd8dbe8 R15: 8802449d FS: 7fcfcad2c740() GS:88024480() knlGS: CS: 0010 DS: ES: CR0: 80050033 CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 DR0: DR1: DR2: DR3: DR6: fffe0ff0 DR7: 0400 Stack: 0260 2dba 81c7e258 88022bd8dcf8 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 Call Trace: [812b1131] sysvipc_find_ipc+0x61/0x300 [812b1416] sysvipc_proc_next+0x46/0xd0 [811e13b9] traverse.isra.7+0xc9/0x260 [810c4078] ? lock_release_non_nested+0x308/0x350 [811e1b61] seq_read+0x3e1/0x450 [81228f10] ? proc_reg_write+0x80/0x80 [81228f4d] proc_reg_read+0x3d/0x80 Do you have any details about load? I haven't seen it either - but I don't have a stress test that does #while true;cat /proc/sysvipc/*/dev/null;done in parallel with create/remove/whatever operations. Davidlohr: Have you done any stress tests for the /proc interface? -- Manfred -- To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
On Thu, Sep 5, 2013 at 5:50 AM, Dave Jones wrote: > Haven't seen this before. > Tree based on v3.11-3104-gf357a82 > > BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] Can't imagine how it could happen. In my understanding, "soft lockup" happens when code stuck at somewhere with preemption disabled. Look at the code, preemption disabled at: sysvipc_proc_next -> sysvipc_find_ipc -> ipc_lock_by_ptr enabled at: sysvipc_proc_next -> ipc_unlock or sysvipc_proc_stop -> ipc_unlock And I didn't find code may stuck in the path. I may miss something .. Regards, Lin Ming > Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG > nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 > phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda > crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc > ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec > snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd > soundcore pcspkr usb_debug e1000e ptp pps_core > irq event stamp: 1143030 > hardirqs last enabled at (1143029): [] > restore_args+0x0/0x30 > hardirqs last disabled at (1143030): [] > apic_timer_interrupt+0x6a/0x80 > softirqs last enabled at (1143028): [] > __do_softirq+0x198/0x460 > softirqs last disabled at (1143023): [] irq_exit+0x135/0x150 > CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 > task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 > RIP: 0010:[] [] > idr_find_slowpath+0x9b/0x150 > RSP: 0018:88022bd8dc88 EFLAGS: 0206 > RAX: 0006 RBX: 000a6c0a RCX: 0008 > RDX: 0008 RSI: 81c41040 RDI: 88022c014668 > RBP: 88022bd8dca0 R08: R09: > R10: 0001 R11: 0001 R12: 88023831a290 > R13: 0001 R14: 88022bd8dbe8 R15: 8802449d > FS: 7fcfcad2c740() GS:88024480() knlGS: > CS: 0010 DS: ES: CR0: 80050033 > CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 > DR0: DR1: DR2: > DR3: DR6: fffe0ff0 DR7: 0400 > Stack: > 0260 2dba 81c7e258 88022bd8dcf8 > 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 > 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 > Call Trace: > [] sysvipc_find_ipc+0x61/0x300 > [] sysvipc_proc_next+0x46/0xd0 > [] traverse.isra.7+0xc9/0x260 > [] ? lock_release_non_nested+0x308/0x350 > [] seq_read+0x3e1/0x450 > [] ? proc_reg_write+0x80/0x80 > [] proc_reg_read+0x3d/0x80 > [] do_loop_readv_writev+0x63/0x90 > [] do_readv_writev+0x21d/0x240 > [] ? local_clock+0x3f/0x50 > [] ? context_tracking_user_exit+0x46/0x1a0 > [] vfs_readv+0x35/0x60 > [] SyS_preadv+0xa2/0xd0 > [] tracesys+0xdd/0xe2 > Code: 7e 6e 41 8b 84 24 2c 08 00 00 83 eb 08 c1 e0 03 39 c3 0f 85 c1 00 00 00 > 89 d9 44 89 e8 d3 f8 0f b6 c0 48 83 c0 04 4d 8b 64 c4 08 80 b4 d6 ff 85 > c0 74 c4 80 3d f7 2f 9d 00 00 75 bb e8 6e b4 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: soft lockup in sysvipc code.
On Thu, Sep 5, 2013 at 5:50 AM, Dave Jones da...@redhat.com wrote: Haven't seen this before. Tree based on v3.11-3104-gf357a82 BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] Can't imagine how it could happen. In my understanding, soft lockup happens when code stuck at somewhere with preemption disabled. Look at the code, preemption disabled at: sysvipc_proc_next - sysvipc_find_ipc - ipc_lock_by_ptr enabled at: sysvipc_proc_next - ipc_unlock or sysvipc_proc_stop - ipc_unlock And I didn't find code may stuck in the path. I may miss something .. Regards, Lin Ming Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core irq event stamp: 1143030 hardirqs last enabled at (1143029): [81715d5c] restore_args+0x0/0x30 hardirqs last disabled at (1143030): [8171f9aa] apic_timer_interrupt+0x6a/0x80 softirqs last enabled at (1143028): [8105a938] __do_softirq+0x198/0x460 softirqs last disabled at (1143023): [8105ae55] irq_exit+0x135/0x150 CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 RIP: 0010:[8131014b] [8131014b] idr_find_slowpath+0x9b/0x150 RSP: 0018:88022bd8dc88 EFLAGS: 0206 RAX: 0006 RBX: 000a6c0a RCX: 0008 RDX: 0008 RSI: 81c41040 RDI: 88022c014668 RBP: 88022bd8dca0 R08: R09: R10: 0001 R11: 0001 R12: 88023831a290 R13: 0001 R14: 88022bd8dbe8 R15: 8802449d FS: 7fcfcad2c740() GS:88024480() knlGS: CS: 0010 DS: ES: CR0: 80050033 CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 DR0: DR1: DR2: DR3: DR6: fffe0ff0 DR7: 0400 Stack: 0260 2dba 81c7e258 88022bd8dcf8 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 Call Trace: [812b1131] sysvipc_find_ipc+0x61/0x300 [812b1416] sysvipc_proc_next+0x46/0xd0 [811e13b9] traverse.isra.7+0xc9/0x260 [810c4078] ? lock_release_non_nested+0x308/0x350 [811e1b61] seq_read+0x3e1/0x450 [81228f10] ? proc_reg_write+0x80/0x80 [81228f4d] proc_reg_read+0x3d/0x80 [811ba3a3] do_loop_readv_writev+0x63/0x90 [811bbccd] do_readv_writev+0x21d/0x240 [810994af] ? local_clock+0x3f/0x50 [81152376] ? context_tracking_user_exit+0x46/0x1a0 [811bbd25] vfs_readv+0x35/0x60 [811bbff2] SyS_preadv+0xa2/0xd0 [8171ef54] tracesys+0xdd/0xe2 Code: 7e 6e 41 8b 84 24 2c 08 00 00 83 eb 08 c1 e0 03 39 c3 0f 85 c1 00 00 00 89 d9 44 89 e8 d3 f8 0f b6 c0 48 83 c0 04 4d 8b 64 c4 08 e8 80 b4 d6 ff 85 c0 74 c4 80 3d f7 2f 9d 00 00 75 bb e8 6e b4 -- To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
soft lockup in sysvipc code.
Haven't seen this before. Tree based on v3.11-3104-gf357a82 BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core irq event stamp: 1143030 hardirqs last enabled at (1143029): [] restore_args+0x0/0x30 hardirqs last disabled at (1143030): [] apic_timer_interrupt+0x6a/0x80 softirqs last enabled at (1143028): [] __do_softirq+0x198/0x460 softirqs last disabled at (1143023): [] irq_exit+0x135/0x150 CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 RIP: 0010:[] [] idr_find_slowpath+0x9b/0x150 RSP: 0018:88022bd8dc88 EFLAGS: 0206 RAX: 0006 RBX: 000a6c0a RCX: 0008 RDX: 0008 RSI: 81c41040 RDI: 88022c014668 RBP: 88022bd8dca0 R08: R09: R10: 0001 R11: 0001 R12: 88023831a290 R13: 0001 R14: 88022bd8dbe8 R15: 8802449d FS: 7fcfcad2c740() GS:88024480() knlGS: CS: 0010 DS: ES: CR0: 80050033 CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 DR0: DR1: DR2: DR3: DR6: fffe0ff0 DR7: 0400 Stack: 0260 2dba 81c7e258 88022bd8dcf8 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 Call Trace: [] sysvipc_find_ipc+0x61/0x300 [] sysvipc_proc_next+0x46/0xd0 [] traverse.isra.7+0xc9/0x260 [] ? lock_release_non_nested+0x308/0x350 [] seq_read+0x3e1/0x450 [] ? proc_reg_write+0x80/0x80 [] proc_reg_read+0x3d/0x80 [] do_loop_readv_writev+0x63/0x90 [] do_readv_writev+0x21d/0x240 [] ? local_clock+0x3f/0x50 [] ? context_tracking_user_exit+0x46/0x1a0 [] vfs_readv+0x35/0x60 [] SyS_preadv+0xa2/0xd0 [] tracesys+0xdd/0xe2 Code: 7e 6e 41 8b 84 24 2c 08 00 00 83 eb 08 c1 e0 03 39 c3 0f 85 c1 00 00 00 89 d9 44 89 e8 d3 f8 0f b6 c0 48 83 c0 04 4d 8b 64 c4 08 80 b4 d6 ff 85 c0 74 c4 80 3d f7 2f 9d 00 00 75 bb e8 6e b4 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
soft lockup in sysvipc code.
Haven't seen this before. Tree based on v3.11-3104-gf357a82 BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:25479] Modules linked in: sctp snd_seq_dummy fuse dlci rfcomm tun bnep hidp ipt_ULOG nfnetlink can_raw can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs snd_hda_codec_realtek libcrc32c snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr usb_debug e1000e ptp pps_core irq event stamp: 1143030 hardirqs last enabled at (1143029): [81715d5c] restore_args+0x0/0x30 hardirqs last disabled at (1143030): [8171f9aa] apic_timer_interrupt+0x6a/0x80 softirqs last enabled at (1143028): [8105a938] __do_softirq+0x198/0x460 softirqs last disabled at (1143023): [8105ae55] irq_exit+0x135/0x150 CPU: 0 PID: 25479 Comm: trinity-child0 Not tainted 3.11.0+ #44 task: 88022c013f90 ti: 88022bd8c000 task.ti: 88022bd8c000 RIP: 0010:[8131014b] [8131014b] idr_find_slowpath+0x9b/0x150 RSP: 0018:88022bd8dc88 EFLAGS: 0206 RAX: 0006 RBX: 000a6c0a RCX: 0008 RDX: 0008 RSI: 81c41040 RDI: 88022c014668 RBP: 88022bd8dca0 R08: R09: R10: 0001 R11: 0001 R12: 88023831a290 R13: 0001 R14: 88022bd8dbe8 R15: 8802449d FS: 7fcfcad2c740() GS:88024480() knlGS: CS: 0010 DS: ES: CR0: 80050033 CR2: 7fcfc84cb968 CR3: 0001de93f000 CR4: 001407f0 DR0: DR1: DR2: DR3: DR6: fffe0ff0 DR7: 0400 Stack: 0260 2dba 81c7e258 88022bd8dcf8 812b1131 88022c013f90 8801d37174c0 88022bd8dd38 81c7e2f0 88022bd8dd38 8801e065cec8 880241d86ca8 Call Trace: [812b1131] sysvipc_find_ipc+0x61/0x300 [812b1416] sysvipc_proc_next+0x46/0xd0 [811e13b9] traverse.isra.7+0xc9/0x260 [810c4078] ? lock_release_non_nested+0x308/0x350 [811e1b61] seq_read+0x3e1/0x450 [81228f10] ? proc_reg_write+0x80/0x80 [81228f4d] proc_reg_read+0x3d/0x80 [811ba3a3] do_loop_readv_writev+0x63/0x90 [811bbccd] do_readv_writev+0x21d/0x240 [810994af] ? local_clock+0x3f/0x50 [81152376] ? context_tracking_user_exit+0x46/0x1a0 [811bbd25] vfs_readv+0x35/0x60 [811bbff2] SyS_preadv+0xa2/0xd0 [8171ef54] tracesys+0xdd/0xe2 Code: 7e 6e 41 8b 84 24 2c 08 00 00 83 eb 08 c1 e0 03 39 c3 0f 85 c1 00 00 00 89 d9 44 89 e8 d3 f8 0f b6 c0 48 83 c0 04 4d 8b 64 c4 08 e8 80 b4 d6 ff 85 c0 74 c4 80 3d f7 2f 9d 00 00 75 bb e8 6e b4 -- To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
