Re: storage, libaio, or XFS problem? 3.4.26

Stan Hoeppner
2014-08-26T17:19:50Z

On Tue, 26 Aug 2014 17:53:45 +1000, Dave Chinner <david@fromorbit.com>
wrote:
> On Tue, Aug 26, 2014 at 01:18:50AM -0500, Stan Hoeppner wrote:
>> Had some controller issues but believe we had those ironed out before
>> this
>> recent breakage. I had reformatted both 48TB LUNs on this test box
with
>> -f
>> and defaults, and fired up the test app again. Throughput was
fantastic
>> with no dropped application buffers for ~30 minutes, and IO times were
>> 1.x
>> ms max, suggesting all the writes were acked by controller cache. The
>> app
>> was running perfectly. Then it hanged and spit out an internal error
>> msg:
>>
>>
>> Failed to reopen file /mnt/VOL1/sg-04/str-0015/f-0000000005
>>
>> I have many call traces in dmesg, most are XFS, pasted below. I found
no
>> SCSI I/O errors in dmesg. Application is submitting writes via libaio
>> and
>> using O_DIRECT, writing to preallocated files. I don't see any errors
in
>> the storage controller log and everything seems to check out there.
>> Using
>> noop elevator, mpt2sas, no multipathing. The application process is
hung
>> in d state and kill -9 won't get rid of it. I can't unmount the hosed
up
>> filesystem. Any ideas?
>>
>> # ls -la /mnt/VOL1
>> ls: cannot access /mnt/VOL1: Input/output error
>>
>> # dd if=/mnt/VOL1 of=/dev/null bs=1M count=16
>> dd: opening `/mnt/VOL1': Input/output error
>>
>> # dd if=/dev/sdd of=/dev/null bs=1M count=16
>> 16+0 records in
>> 16+0 records out
>> 16777216 bytes (17 MB) copied, 1.10989 s, 15.1 MB/s
>>
>> # ls -la /mnt/
>> ls: cannot access /mnt/VOL1: Input/output error
>> total 8
>> drwxrwxrwt 6 root root 120 Aug 25 17:59 .
>> drwxr-xr-x 21 root root 4096 Jul 15 09:39 ..
>> drwxrwxrwt 3 root root 80 Aug 25 16:52 initramfs
>> drwxr-xr-x 3 root root 4096 Apr 24 04:57 scratch
>> drwxrwxrwx 5 root root 58 Aug 25 22:06 VOL0
>> d????????? ? ? ? ? ? VOL1
>
> That's an inode we failed to stat() - most likely because of the IO
> error. Has the filesystem shut down? the IO error shoul dhave had
> some kind of output in dmesg associated with it from XFS....

Sorry, I omitted the XFS logging preceding the first call trace:

Aug 25 18:02:50 Anguish-ssu-1 kernel: [ 4280.310304] SGI XFS with security
attributes, large block/inode numbers, no debug enabled
Aug 25 18:02:50 Anguish-ssu-1 kernel: [ 4280.311101] XFS (sdc): Mounting
Filesystem
Aug 25 18:02:51 Anguish-ssu-1 kernel: [ 4280.501405] XFS (sdc): Starting
recovery (logdev: internal)
Aug 25 18:02:53 Anguish-ssu-1 kernel: [ 4282.766547] XFS (sdc): Failed to
recover EFIs
Aug 25 18:02:53 Anguish-ssu-1 kernel: [ 4282.766549] XFS (sdc): log mount
finish failed
Aug 25 18:04:50 Anguish-ssu-1 kernel: [ 4399.471829] XFS (sdc): Mounting
Filesystem
Aug 25 18:04:50 Anguish-ssu-1 kernel: [ 4399.620805] XFS (sdc): Ending
clean mount
Aug 25 18:04:56 Anguish-ssu-1 kernel: [ 4405.613778] XFS (sdd): Mounting
Filesystem
Aug 25 18:04:56 Anguish-ssu-1 kernel: [ 4405.835412] XFS (sdd): Ending
clean mount
Aug 25 23:05:39 Anguish-ssu-1 kernel: [22409.328839] XFS (sdd):
xfs_do_force_shutdown(0x8) called from line 3732 of file fs/xfs/xfs_bmap.c.
Return address = 0xffffffffa01cc9a6
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.307128] XFS (sdd): failed to
update timestamps for inode 0x2a000000a4
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.307484] XFS (sdd): failed to
update timestamps for inode 0x29000000a4
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.307487] XFS (sdd): failed to
update timestamps for inode 0x20000009f
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.307499] XFS (sdd): failed to
update timestamps for inode 0x29000000a4
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.307693] XFS (sdd): failed to
update timestamps for inode 0x20000009f
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.368106] XFS (sdd): failed to
update timestamps for inode 0xf000000a4
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.369785] XFS (sdd): failed to
update timestamps for inode 0xf000000a4
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.605835] XFS (sdd): failed to
update timestamps for inode 0x2810f413c
Aug 25 23:05:49 Anguish-ssu-1 kernel: [22419.606169] XFS (sdd): failed to
update timestamps for inode 0x60000009f

Again, when the app locked up I was assuming we had more controller
issues, and I expected to find SCSI I/O errors preceding the XFS errors.
But there are none. The controllers check out, no errors logged on them.
Diags pass, etc. When NOT using AIO for submission, just parallel
O_DIRECT, the big rig is sustaining ~2.5GB/s write throughput across 14
arrays at the application level with ~4200 write threads submitting IOs
concurrently, with no problems, no errors. ~1/3rd of these write threads
are slow writers, each submitting a 32KB IO to a file every few seconds.
Fast and medium rate streams fill the cache, thus these slow writer streams
generate RMWs. This is why the throughput is relatively low for 168
effective spindles which are capable of streaming writes in the ~16GB/s
neighborhood. My little test rig is submitting from 602 threads in
parallel, 301 threads each to one of two filesystems each on a 12+1 RAID5
LUN. Both boxes have the same problem described here, but only when
submitting with AIO. I don't have logs for the big box, but I did see some
of the same collateral damage on it, specifically the garbage when doing an
'ls -la' on the mount points. This obviously due to the XFS forced
shutdown.

>> [22635.102013] INFO: task kworker/7:0:45 blocked for more than 120
>> seconds.
>> [22635.102016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
>> disables
>> this message.
>> [22635.102018] kworker/7:0 D ffff8840666c0b08 0 45 2
>> 0x00000000
>> [22635.102021] ffff8840666e7bd0 0000000000000046 ffff883f7c02d000
>> ffff8840666f5180
>> [22635.102026] ffff8840666e7b80 0000000000000206 00000000000122c0
>> 00000000000122c0
>> [22635.102030] ffff8840666e7fd8 ffff8840666e6000 00000000000122c0
>> ffff8840666e6000
>> [22635.102033] Call Trace:
>> [22635.102041] [<ffffffff814f5fd7>] schedule+0x64/0x66
>> [22635.102044] [<ffffffff814f66ec>]
rwsem_down_failed_common+0xdb/0x10d
>> [22635.102047] [<ffffffff814f6731>] rwsem_down_write_failed+0x13/0x15
>> [22635.102051] [<ffffffff81261913>]
>> call_rwsem_down_write_failed+0x13/0x20
>> [22635.102055] [<ffffffff814f6a92>] ?
>> _raw_spin_unlock_irqrestore+0x30/0x3d
>> [22635.102058] [<ffffffff814f5458>] ? down_write+0x25/0x27
>> [22635.102070] [<ffffffffa01b35e4>] xfs_ilock+0x4f/0xb4 [xfs]
>> [22635.102077] [<ffffffffa01b5ab0>]
>> xfs_iomap_write_unwritten+0x1b3/0x32e
>> [xfs]
>> [22635.102080] [<ffffffff814f6a92>] ?
>> _raw_spin_unlock_irqrestore+0x30/0x3d
>> [22635.102084] [<ffffffffa01ab3d2>] ? xfs_setfilesize+0x128/0x128
[xfs]
>> [22635.102088] [<ffffffff810bc602>] ? mempool_free+0x73/0x78
>> [22635.102093] [<ffffffffa01ab3d2>] ? xfs_setfilesize+0x128/0x128
[xfs]
>> [22635.102098] [<ffffffffa01ab45b>] xfs_end_io+0x89/0xb4 [xfs]
>> [22635.102102] [<ffffffff81047321>] process_one_work+0x204/0x327
>> [22635.102105] [<ffffffff8104757f>] worker_thread+0x13b/0x25a
>> [22635.102108] [<ffffffff81047444>] ? process_one_work+0x327/0x327
>> [22635.102111] [<ffffffff8104af6f>] kthread+0x89/0x91
>> [22635.102115] [<ffffffff814fdbd4>] kernel_thread_helper+0x4/0x10
>> [22635.102118] [<ffffffff8104aee6>] ? __init_kthread_worker+0x3c/0x3c
>> [22635.102120] [<ffffffff814fdbd0>] ? gs_change+0xb/0xb
>
> That's stuck on a an inode lock. That reminds of a problem we had in
> RHEL6 with highly concurrent direct IO. The rwsems were buggy, and
> XFS was tripping over the bug and hanging just like this. If the
> filesystem is not shutting down and causing that IO error due to a
> shutdown state, then it's entirely possible we've got another rwsem
> issue. Now I've just got to go find the RHEL 6 problem again. Ah:

Definitely highly concurrent direct io here. Filesystem *is* shutting
down. Again, this only happens when submitting via AIO.

> 91af708 rwsem: Test for no active locks in __rwsem_do_wake undo code
>
> But that was fixed in 2.6.34 (rhel 6 was based on 2.6.32), so I
> doubt that is your problem. However, it smells almost exactly the
> same - it took about an hour of highly concurrent direct IO to SSDs
> to trigger, and Lachlan ended up finding the right incantation of
> lock debug code inside the xfs mrlock implementation to prove that
> it was an rwsem bug and not an XFS locking issue.

FWIW I'm seeing it after about ~30 minutes on the small box. I don't know
how quickly it occurred on the big rig.

> Are you able to take crash dumps from this machine so you can dig
> around inside the XFS inode and rwsem states when the system locks
> up like this?

The kernel isn't completely crashing. I am able to CTRL+Z out of the hung
application back to a prompt, and open additional SSH shells. But when
these errors occur, something in the kernel does become goofy, as the load
average spikes to the stratosphere, even though there is no CPU burn nor IO
wait. Once the app crashes the box is 100% idle. Do keep in mind as we
troubleshoot this that the boxen are in a machine room 520 miles from my
location. So I can't push magic key sequences on the console. I don't
have KVM access. Through I might be able to get it if needed, haven't
asked.

> One thing in the RH bug that was suggested as a simply test to
> determine if there's a problem with the rwsems is to edit the kernel
> configin arch/x86/Kconfig:
>
> Change:
>
> config RWSEM_GENERIC_SPINLOCK
> def_bool !X86_ADD
>
> config RWSEM_XCHGADD_ALGORITHM
> def_bool X86_ADD
>
> to:
>
> config RWSEM_GENERIC_SPINLOCK
> def_bool y
>
> config RWSEM_XCHGADD_ALGORITHM
> def_bool n

These aren't truly lab systems in all respects. I don't have the
permission/access to change the kernel config and recompile. There is a
"process" for that and a different group owns that process. If this is
necessary to troubleshoot this then I'll see if I can push it through.

> I haven't cheked if this still works on a 3.4 kernel, but it will
> change the rwsem implementation to the generic, spinlock based
> implementation rather than the super-special, highly optimised
> x86 specific implementation. If that makes the problem go away,
> then we've got another rwsem bug on our hands. If it doesn't, then I
> can probably get you the mrlock debug code lachlan wrote and we can
> see if XFS is doing something wrong...

Thanks for the detailed explanation. Given the new information I've
provided, what is my next step?

Thanks,