block layer softlockup

[Dave Jones <davej@redhat.com>]

On Fri, Jun 28, 2013 at 01:54:37PM +1000, Dave Chinner wrote:
 > On Thu, Jun 27, 2013 at 04:54:53PM -1000, Linus Torvalds wrote:
 > > On Thu, Jun 27, 2013 at 3:18 PM, Dave Chinner <david@fromorbit.com> wrote:
 > > >
 > > > Right, that will be what is happening - the entire system will go
 > > > unresponsive when a sync call happens, so it's entirely possible
 > > > to see the soft lockups on inode_sb_list_add()/inode_sb_list_del()
 > > > trying to get the lock because of the way ticket spinlocks work...
 > > 
 > > So what made it all start happening now? I don't recall us having had
 > > these kinds of issues before..
 > 
 > Not sure - it's a sudden surprise for me, too. Then again, I haven't
 > been looking at sync from a performance or lock contention point of
 > view any time recently.  The algorithm that wait_sb_inodes() is
 > effectively unchanged since at least 2009, so it's probably a case
 > of it having been protected from contention by some external factor
 > we've fixed/removed recently.  Perhaps the bdi-flusher thread
 > replacement in -rc1 has changed the timing sufficiently that it no
 > longer serialises concurrent sync calls as much....

This mornings new trace reminded me of this last sentence. Related ?

BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child1:7219]
Modules linked in: lec sctp dlci 8021q garp mpoa dccp_ipv4 dccp bridge stp tun snd_seq_dummy fuse bnep rfcomm nfnetlink scsi_transport_iscsi hidp ipt_ULOG can_raw can_bcm af_key af_rxrpc rose ipx p8023 p8022 atm llc2 pppoe pppox ppp_generic slhc bluetooth rds af_802154 appletalk nfc psnap phonet llc rfkill netrom x25 ax25 irda can caif_socket caif crc_ccitt coretemp hwmon kvm_intel kvm snd_hda_codec_realtek crc32c_intel ghash_clmulni_intel snd_hda_codec_hdmi microcode pcspkr snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device usb_debug snd_pcm e1000e snd_page_alloc snd_timer snd ptp pps_core soundcore xfs libcrc32c
irq event stamp: 3181543
hardirqs last  enabled at (3181542): [<ffffffff816edc60>] restore_args+0x0/0x30
hardirqs last disabled at (3181543): [<ffffffff816f676a>] apic_timer_interrupt+0x6a/0x80
softirqs last  enabled at (1794686): [<ffffffff810542e4>] __do_softirq+0x194/0x440
softirqs last disabled at (1794689): [<ffffffff8105474d>] irq_exit+0xcd/0xe0
CPU: 0 PID: 7219 Comm: trinity-child1 Not tainted 3.10.0+ #38
task: ffff8801d3a0ca40 ti: ffff88022e07e000 task.ti: ffff88022e07e000
RIP: 0010:[<ffffffff816ed037>]  [<ffffffff816ed037>] _raw_spin_unlock_irqrestore+0x67/0x80
RSP: 0018:ffff880244803db0  EFLAGS: 00000286
RAX: ffff8801d3a0ca40 RBX: ffffffff816edc60 RCX: 0000000000000002
RDX: 0000000000004730 RSI: ffff8801d3a0d1c0 RDI: ffff8801d3a0ca40
RBP: ffff880244803dc0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000001 R12: ffff880244803d28
R13: ffffffff816f676f R14: ffff880244803dc0 R15: ffff88023d1307f8
FS:  00007f00e7ab6740(0000) GS:ffff880244800000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000002f18000 CR3: 000000022d31b000 CR4: 00000000001407f0
DR0: 0000000000ad9000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
 ffff88023e21a680 0000000000000000 ffff880244803df0 ffffffff812da4c1
 ffff88023e21a680 0000000000000000 0000000000000000 0000000000000000
 ffff880244803e00 ffffffff812da4e0 ffff880244803e60 ffffffff8149ba13
Call Trace:
 <IRQ> 

 [<ffffffff812da4c1>] blk_end_bidi_request+0x51/0x60
 [<ffffffff812da4e0>] blk_end_request+0x10/0x20
 [<ffffffff8149ba13>] scsi_io_completion+0xf3/0x6e0
 [<ffffffff81491a60>] scsi_finish_command+0xb0/0x110
 [<ffffffff8149b81f>] scsi_softirq_done+0x12f/0x160
 [<ffffffff812e1e08>] blk_done_softirq+0x88/0xa0
 [<ffffffff8105424f>] __do_softirq+0xff/0x440
 [<ffffffff8105474d>] irq_exit+0xcd/0xe0
 [<ffffffff816f760b>] smp_apic_timer_interrupt+0x6b/0x9b
 [<ffffffff816f676f>] apic_timer_interrupt+0x6f/0x80
 <EOI> 

 [<ffffffff816edc60>] ? retint_restore_args+0xe/0xe
 [<ffffffff812ff465>] ? idr_find_slowpath+0x115/0x150
 [<ffffffff812ff475>] ? idr_find_slowpath+0x125/0x150
 [<ffffffff8108ceb0>] ? scheduler_tick_max_deferment+0x60/0x60
 [<ffffffff816f1765>] ? add_preempt_count+0xa5/0xf0
 [<ffffffff810fc8ea>] rcu_lockdep_current_cpu_online+0x3a/0xa0
 [<ffffffff812ff475>] idr_find_slowpath+0x125/0x150
 [<ffffffff812a3879>] ipcget+0x89/0x380
 [<ffffffff810b76e5>] ? trace_hardirqs_on_caller+0x115/0x1e0
 [<ffffffff812a4f76>] SyS_msgget+0x56/0x60
 [<ffffffff812a4560>] ? rcu_read_lock+0x80/0x80
 [<ffffffff812a43a0>] ? sysvipc_msg_proc_show+0xd0/0xd0
 [<ffffffff816f5d14>] tracesys+0xdd/0xe2
 [<ffffffffa00000b4>] ? libcrc32c_mod_fini+0x48/0xf94 [libcrc32c]
Code: 00 e8 9e 47 00 00 65 48 8b 04 25 f0 b9 00 00 48 8b 80 38 e0 ff ff a8 08 75 13 5b 41 5c 5d c3 0f 1f 44 00 00 e8 7b a7 9c ff 53 9d <eb> cf 0f 1f 80 00 00 00 00 e8 bb ea ff ff eb df 66 0f 1f 84 00 


My read of this is that block layer was taking a *long* time to do something,
and prevented the msgget from progressing within the watchdog cutoff time.

Plausible ?

	Dave