XFS filesystem hang

XFS filesystem hang

[Daniel Aberger - Profihost AG]

Hi,

one of our servers crashed / hung several times in the past days with
similar errors regarding XFS. Unfortunately we are unable to interprete
the call trace of dmesg to pinpoint the exact problem and I hope you
could help me to do so.

We already ran xfs_repair to ensure that there are no filesystem errors.

Here is an example dmesg output of recent crash of the mentioned server:

2019-01-12 06:06:35     INFO: task mysqld:1171 blocked for more than 120
seconds.
2019-01-12 06:06:35     Tainted: G 4.12.0+139-ph #1
2019-01-12 06:06:35     "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
2019-01-12 06:06:35     mysqld D 0 1171 1 0x00080000
2019-01-12 06:06:35     Call Trace:
2019-01-12 06:06:35     ? __schedule+0x3bc/0x820
2019-01-12 06:06:35     ? strlcpy+0x31/0x40
2019-01-12 06:06:35     ?
kernfs_path_from_node_locked+0x238/0x320schedule+0x32/0x80xlog_grant_head_wait+0xca/0x200xlog_grant_head_check+0x86/0xe0xfs_log_reserve+0xc7/0x1c0xfs_trans_reserve+0x169/0x1c0xfs_trans_alloc+0xb9/0x130xfs_vn_update_time+0x4e/0x130file_update_time+0xa7/0x100xfs_file_aio_write_checks+0x178/0x1a0
2019-01-12 06:06:35     ?
ktime_get+0x3e/0xa0xfs_file_dio_aio_write+0xb1/0x230xfs_file_write_iter+0xff/0x150aio_write+0xf6/0x150
2019-01-12 06:06:35     ? queue_unplugged+0x25/0xa0
2019-01-12 06:06:35     ? kmem_cache_alloc+0xf7/0x570
2019-01-12 06:06:35     ? do_io_submit+0x35c/0x690do_io_submit+0x35c/0x690
2019-01-12 06:06:35     ?
do_syscall_64+0x74/0x150do_syscall_64+0x74/0x150entry_SYSCALL_64_after_hwframe+0x3d/0xa2
2019-01-12 06:06:35     RIP: 0033:0x7f37aa6b6717
2019-01-12 06:06:35     RSP: 002b:00007f32953f4228 EFLAGS: 00000206
ORIG_RAX: 00000000000000d1
2019-01-12 06:06:35     RAX: ffffffffffffffda RBX: 00000000000040f6 RCX:
00007f37aa6b6717
2019-01-12 06:06:35     RDX: 00007f32953f4230 RSI: 0000000000000001 RDI:
00007f37aaef9000
2019-01-12 06:06:35     RBP: 00007f32953f4250 R08: 00007f32953f4230 R09:
0000000000000000
2019-01-12 06:06:35     R10: 0000000000010000 R11: 0000000000000206 R12:
00007f32953f4370
2019-01-12 06:06:35     R13: 00007f37a806d158 R14: 00007f32a5829b98 R15:
00007f379df26100

Thanks,

Daniel

Re: XFS filesystem hang

[Brian Foster]

On Thu, Jan 17, 2019 at 12:14:11PM +0100, Daniel Aberger - Profihost AG wrote:
> Hi,
> 
> one of our servers crashed / hung several times in the past days with
> similar errors regarding XFS. Unfortunately we are unable to interprete
> the call trace of dmesg to pinpoint the exact problem and I hope you
> could help me to do so.
> 
> We already ran xfs_repair to ensure that there are no filesystem errors.
> 
> Here is an example dmesg output of recent crash of the mentioned server:
> 
> 2019-01-12 06:06:35     INFO: task mysqld:1171 blocked for more than 120
> seconds.

This is not a crash but rather an indication from the kernel that this
task has been sitting here for at least a couple minutes. This doesn't
tell us whether the task will eventually recover or remain blocked
indefinitely.

> 2019-01-12 06:06:35     Tainted: G 4.12.0+139-ph #1
> 2019-01-12 06:06:35     "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> 2019-01-12 06:06:35     mysqld D 0 1171 1 0x00080000
> 2019-01-12 06:06:35     Call Trace:
> 2019-01-12 06:06:35     ? __schedule+0x3bc/0x820
> 2019-01-12 06:06:35     ? strlcpy+0x31/0x40
> 2019-01-12 06:06:35     ?
> kernfs_path_from_node_locked+0x238/0x320schedule+0x32/0x80xlog_grant_head_wait+0xca/0x200xlog_grant_head_check+0x86/0xe0xfs_log_reserve+0xc7/0x1c0xfs_trans_reserve+0x169/0x1c0xfs_trans_alloc+0xb9/0x130xfs_vn_update_time+0x4e/0x130file_update_time+0xa7/0x100xfs_file_aio_write_checks+0x178/0x1a0
> 2019-01-12 06:06:35     ?

I'm not sure how reliable the stack is, but fwiw it looks like this is
an aio that is waiting on transaction reservation to update a file time.
Transaction reservation is a normal blocking path because log space is a
finite resource. We certainly don't expect to block here for minutes,
but the fact that we don't know anything about your filesystem geometry,
mount options, underlying storage, workload, etc. will make it difficult
for anybody to surmise what the problem could be.

Please see the following url for what information to include when
reporting a problem:

http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F

I'd also suggest to include broader dmesg output and/or xfs_repair
output if there are multiple error reports that aren't exactly the same.

Brian

> ktime_get+0x3e/0xa0xfs_file_dio_aio_write+0xb1/0x230xfs_file_write_iter+0xff/0x150aio_write+0xf6/0x150
> 2019-01-12 06:06:35     ? queue_unplugged+0x25/0xa0
> 2019-01-12 06:06:35     ? kmem_cache_alloc+0xf7/0x570
> 2019-01-12 06:06:35     ? do_io_submit+0x35c/0x690do_io_submit+0x35c/0x690
> 2019-01-12 06:06:35     ?
> do_syscall_64+0x74/0x150do_syscall_64+0x74/0x150entry_SYSCALL_64_after_hwframe+0x3d/0xa2
> 2019-01-12 06:06:35     RIP: 0033:0x7f37aa6b6717
> 2019-01-12 06:06:35     RSP: 002b:00007f32953f4228 EFLAGS: 00000206
> ORIG_RAX: 00000000000000d1
> 2019-01-12 06:06:35     RAX: ffffffffffffffda RBX: 00000000000040f6 RCX:
> 00007f37aa6b6717
> 2019-01-12 06:06:35     RDX: 00007f32953f4230 RSI: 0000000000000001 RDI:
> 00007f37aaef9000
> 2019-01-12 06:06:35     RBP: 00007f32953f4250 R08: 00007f32953f4230 R09:
> 0000000000000000
> 2019-01-12 06:06:35     R10: 0000000000010000 R11: 0000000000000206 R12:
> 00007f32953f4370
> 2019-01-12 06:06:35     R13: 00007f37a806d158 R14: 00007f32a5829b98 R15:
> 00007f379df26100
> 
> Thanks,
> 
> Daniel

Re: XFS filesystem hang

[Daniel Aberger - Profihost AG]

Am 17.01.19 um 13:34 schrieb Brian Foster:
> On Thu, Jan 17, 2019 at 12:14:11PM +0100, Daniel Aberger - Profihost AG wrote:
>> Hi,
>>
>> one of our servers crashed / hung several times in the past days with
>> similar errors regarding XFS. Unfortunately we are unable to interprete
>> the call trace of dmesg to pinpoint the exact problem and I hope you
>> could help me to do so.
>>
>> We already ran xfs_repair to ensure that there are no filesystem errors.
>>
>> Here is an example dmesg output of recent crash of the mentioned server:
>>
>> 2019-01-12 06:06:35     INFO: task mysqld:1171 blocked for more than 120
>> seconds.
> 
> This is not a crash but rather an indication from the kernel that this
> task has been sitting here for at least a couple minutes. This doesn't
> tell us whether the task will eventually recover or remain blocked
> indefinitely.
> 

Yes, you're right. Well I was referring to it as a crash since the
system does not respond to any inputs anymore and we have to perform a
REISUB to reboot it.

>> 2019-01-12 06:06:35     Tainted: G 4.12.0+139-ph #1
>> 2019-01-12 06:06:35     "echo 0 >
>> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> 2019-01-12 06:06:35     mysqld D 0 1171 1 0x00080000
>> 2019-01-12 06:06:35     Call Trace:
>> 2019-01-12 06:06:35     ? __schedule+0x3bc/0x820
>> 2019-01-12 06:06:35     ? strlcpy+0x31/0x40
>> 2019-01-12 06:06:35     ?
>> kernfs_path_from_node_locked+0x238/0x320schedule+0x32/0x80xlog_grant_head_wait+0xca/0x200xlog_grant_head_check+0x86/0xe0xfs_log_reserve+0xc7/0x1c0xfs_trans_reserve+0x169/0x1c0xfs_trans_alloc+0xb9/0x130xfs_vn_update_time+0x4e/0x130file_update_time+0xa7/0x100xfs_file_aio_write_checks+0x178/0x1a0
>> 2019-01-12 06:06:35     ?
> 
> I'm not sure how reliable the stack is, but fwiw it looks like this is
> an aio that is waiting on transaction reservation to update a file time.
> Transaction reservation is a normal blocking path because log space is a
> finite resource. We certainly don't expect to block here for minutes,
> but the fact that we don't know anything about your filesystem geometry,
> mount options, underlying storage, workload, etc. will make it difficult
> for anybody to surmise what the problem could be.
> 
> Please see the following url for what information to include when
> reporting a problem:
> 
> http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F
> 
> I'd also suggest to include broader dmesg output and/or xfs_repair
> output if there are multiple error reports that aren't exactly the same.
> 

I'm sorry, I missed this page on my search for an FAQ somehow.


* Kernel Version: Linux 4.12.0+139-ph #1 SMP Tue Jan 1 21:46:16 UTC 2019
x86_64 GNU/Linux

* xfsprogs version: 4.9.0

* Single CPU, Xeon E5-1650 v3, 6 cores, 12 threads

* /proc/meminfo, /proc/mounts, /proc/partitions and xfs_info can be
found here: https://pastebin.com/cZiTrUDL

* full dmesg output of problem mentioned in the first mail:
https://pastebin.com/pLaz18L1

* a couple of more dmesg outputs from the same system with similar
behaviour:
 * https://pastebin.com/hWDbwcCr
 * https://pastebin.com/HAqs4yQc

* Raid Controller: Adaptec ASR8805
 * Logical Device 0 is a RAID6 with 5 SSDs (Samsung MZ7KM480), /dev/sda
 * Logical Device 1 is a single backup HDD (Seagate ST2000NX0253) for
internal backups, /dev/sdb

* Output of xfs_repair: https://pastebin.com/JzVMqrLh

The problem seems to happen randomly. There does not have to be high
load on our storage devices. This makes it pretty hard to find an exact
cause.


- Daniel

> Brian
> 
>> ktime_get+0x3e/0xa0xfs_file_dio_aio_write+0xb1/0x230xfs_file_write_iter+0xff/0x150aio_write+0xf6/0x150
>> 2019-01-12 06:06:35     ? queue_unplugged+0x25/0xa0
>> 2019-01-12 06:06:35     ? kmem_cache_alloc+0xf7/0x570
>> 2019-01-12 06:06:35     ? do_io_submit+0x35c/0x690do_io_submit+0x35c/0x690
>> 2019-01-12 06:06:35     ?
>> do_syscall_64+0x74/0x150do_syscall_64+0x74/0x150entry_SYSCALL_64_after_hwframe+0x3d/0xa2
>> 2019-01-12 06:06:35     RIP: 0033:0x7f37aa6b6717
>> 2019-01-12 06:06:35     RSP: 002b:00007f32953f4228 EFLAGS: 00000206
>> ORIG_RAX: 00000000000000d1
>> 2019-01-12 06:06:35     RAX: ffffffffffffffda RBX: 00000000000040f6 RCX:
>> 00007f37aa6b6717
>> 2019-01-12 06:06:35     RDX: 00007f32953f4230 RSI: 0000000000000001 RDI:
>> 00007f37aaef9000
>> 2019-01-12 06:06:35     RBP: 00007f32953f4250 R08: 00007f32953f4230 R09:
>> 0000000000000000
>> 2019-01-12 06:06:35     R10: 0000000000010000 R11: 0000000000000206 R12:
>> 00007f32953f4370
>> 2019-01-12 06:06:35     R13: 00007f37a806d158 R14: 00007f32a5829b98 R15:
>> 00007f379df26100
>>
>> Thanks,
>>
>> Daniel

Re: XFS filesystem hang

[Dave Chinner]

On Thu, Jan 17, 2019 at 02:50:23PM +0100, Daniel Aberger - Profihost AG wrote:
> Am 17.01.19 um 13:34 schrieb Brian Foster:
> > On Thu, Jan 17, 2019 at 12:14:11PM +0100, Daniel Aberger - Profihost AG wrote:
> >> Hi,
> >>
> >> one of our servers crashed / hung several times in the past days with
> >> similar errors regarding XFS. Unfortunately we are unable to interprete
> >> the call trace of dmesg to pinpoint the exact problem and I hope you
> >> could help me to do so.
> >>
> >> We already ran xfs_repair to ensure that there are no filesystem errors.
> >>
> >> Here is an example dmesg output of recent crash of the mentioned server:
> >>
> >> 2019-01-12 06:06:35     INFO: task mysqld:1171 blocked for more than 120
> >> seconds.
> > 
> > This is not a crash but rather an indication from the kernel that this
> > task has been sitting here for at least a couple minutes. This doesn't
> > tell us whether the task will eventually recover or remain blocked
> > indefinitely.
> > 
> 
> Yes, you're right. Well I was referring to it as a crash since the
> system does not respond to any inputs anymore and we have to perform a
> REISUB to reboot it.
> 
> >> 2019-01-12 06:06:35     Tainted: G 4.12.0+139-ph #1
> >> 2019-01-12 06:06:35     "echo 0 >
> >> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> 2019-01-12 06:06:35     mysqld D 0 1171 1 0x00080000
> >> 2019-01-12 06:06:35     Call Trace:
> >> 2019-01-12 06:06:35     ? __schedule+0x3bc/0x820
> >> 2019-01-12 06:06:35     ? strlcpy+0x31/0x40
> >> 2019-01-12 06:06:35     ?
> >> kernfs_path_from_node_locked+0x238/0x320schedule+0x32/0x80xlog_grant_head_wait+0xca/0x200xlog_grant_head_check+0x86/0xe0xfs_log_reserve+0xc7/0x1c0xfs_trans_reserve+0x169/0x1c0xfs_trans_alloc+0xb9/0x130xfs_vn_update_time+0x4e/0x130file_update_time+0xa7/0x100xfs_file_aio_write_checks+0x178/0x1a0
> >> 2019-01-12 06:06:35     ?
> > 
> > I'm not sure how reliable the stack is, but fwiw it looks like this is
> > an aio that is waiting on transaction reservation to update a file time.
> > Transaction reservation is a normal blocking path because log space is a
> > finite resource. We certainly don't expect to block here for minutes,
> > but the fact that we don't know anything about your filesystem geometry,
> > mount options, underlying storage, workload, etc. will make it difficult
> > for anybody to surmise what the problem could be.
> > 
> > Please see the following url for what information to include when
> > reporting a problem:
> > 
> > http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F
> > 
> > I'd also suggest to include broader dmesg output and/or xfs_repair
> > output if there are multiple error reports that aren't exactly the same.
> > 
> 
> I'm sorry, I missed this page on my search for an FAQ somehow.
> 
> 
> * Kernel Version: Linux 4.12.0+139-ph #1 SMP Tue Jan 1 21:46:16 UTC 2019
> x86_64 GNU/Linux

Is that an unmodified distro kernel or one you've patched and built
yourself?

> * xfsprogs version: 4.9.0
> 
> * Single CPU, Xeon E5-1650 v3, 6 cores, 12 threads
> 
> * /proc/meminfo, /proc/mounts, /proc/partitions and xfs_info can be
> found here: https://pastebin.com/cZiTrUDL

Just  notes as I browse it.
- lots of free memory.
- xfs-info: 1.3TB, 32 ags, ~700MB log w/sunit =64fsbs
  sunit=64 fsbs, swidth=192fsbs (RAID?)
- mount options: noatime, sunit=512,sunit=1536, usrquota
- /dev/sda3 mounted on /
- /dev/sda3 also mounted on /home/tmp (bind mount of something?)

> * full dmesg output of problem mentioned in the first mail:
> https://pastebin.com/pLaz18L1

No smoking gun.

> * a couple of more dmesg outputs from the same system with similar
> behaviour:
>  * https://pastebin.com/hWDbwcCr
>  * https://pastebin.com/HAqs4yQc

Ok, so mysqld seems to be the problem child here.

> * Raid Controller: Adaptec ASR8805
>  * Logical Device 0 is a RAID6 with 5 SSDs (Samsung MZ7KM480), /dev/sda

Ok, so RAID6 on a RADI controller with 1GB cache and a small random
write workload?

>  * Logical Device 1 is a single backup HDD (Seagate ST2000NX0253) for
> internal backups, /dev/sdb
> 
> * Output of xfs_repair: https://pastebin.com/JzVMqrLh

Nothing wrong at all. So this looks like it's either a log space
accounting leak (i.e. XFS bug) or something else....

> The problem seems to happen randomly. There does not have to be high
> load on our storage devices. This makes it pretty hard to find an exact
> cause.

... which makes me suspect "something else".

I note that nothing is stalled on reads from the device - it's all
stalled on journal space (i.e. write operations). I've seen similar
things before where the RAID controller is configured as a writeback
cache and the workload just keeps dumping lots of small random writes
into the RAID cache until it fills. Databases do lots of small
writes.

This looks like the device is lightly loaded because writing into
the cache is really fast. Right up until it fills and then has to
dump hundreds of thousands of small writes to disk, which on RAID 6
each require read-modify-raid-recalc-write cycles to run. This is
really slow, and why RAID6 is generally a poor choice for database
workloads.

i.e. when the RAID cache fills, new writes stalls waiting for a RAID
cache flush - they run at slower than disk speed because they have
to first wait for the RAID controller to comple.

It is is only noticed when the filesystem journal stalls
because it's run out of space and is trying to dump a large amount
of small metadata writes to the device to free up journal space. The
journal space won't be freed up until the metadata that pins the
tail of the log has been successfully written. When there's
thousands of metadata IOs needed (a 700MB log can hold several
hundred thousand dirty metadata objects in memory!) to move th elog
forward, and the RAID cache is full, it will take a /long time/ and
the filesystem will be stalled until that completes.

I've seen spinning disk RAID setups like this stall for hours while
large RAID caches flush. SSDs should be a lot faster, but we're
still potentially talking about having to do millions of IOs and the
RAID controller will be CPU bound on parity recalculatoins.  So this
/may/ just be a result of the storage configuration and have nothing
to do with XFS at all.

Which leads me to ask: what is your RAID cache setup - write-thru,
write-back, etc?

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: XFS filesystem hang

[Daniel Aberger - Profihost AG]

Am 17.01.19 um 23:05 schrieb Dave Chinner:
> On Thu, Jan 17, 2019 at 02:50:23PM +0100, Daniel Aberger - Profihost AG wrote:
>> Am 17.01.19 um 13:34 schrieb Brian Foster:
>>> On Thu, Jan 17, 2019 at 12:14:11PM +0100, Daniel Aberger - Profihost AG wrote:
>>>> Hi,
>>>>
>>>> one of our servers crashed / hung several times in the past days with
>>>> similar errors regarding XFS. Unfortunately we are unable to interprete
>>>> the call trace of dmesg to pinpoint the exact problem and I hope you
>>>> could help me to do so.
>>>>
>>>> We already ran xfs_repair to ensure that there are no filesystem errors.
>>>>
>>>> Here is an example dmesg output of recent crash of the mentioned server:
>>>>
>>>> 2019-01-12 06:06:35     INFO: task mysqld:1171 blocked for more than 120
>>>> seconds.
>>>
>>> This is not a crash but rather an indication from the kernel that this
>>> task has been sitting here for at least a couple minutes. This doesn't
>>> tell us whether the task will eventually recover or remain blocked
>>> indefinitely.
>>>
>>
>> Yes, you're right. Well I was referring to it as a crash since the
>> system does not respond to any inputs anymore and we have to perform a
>> REISUB to reboot it.
>>
>>>> 2019-01-12 06:06:35     Tainted: G 4.12.0+139-ph #1
>>>> 2019-01-12 06:06:35     "echo 0 >
>>>> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>>> 2019-01-12 06:06:35     mysqld D 0 1171 1 0x00080000
>>>> 2019-01-12 06:06:35     Call Trace:
>>>> 2019-01-12 06:06:35     ? __schedule+0x3bc/0x820
>>>> 2019-01-12 06:06:35     ? strlcpy+0x31/0x40
>>>> 2019-01-12 06:06:35     ?
>>>> kernfs_path_from_node_locked+0x238/0x320schedule+0x32/0x80xlog_grant_head_wait+0xca/0x200xlog_grant_head_check+0x86/0xe0xfs_log_reserve+0xc7/0x1c0xfs_trans_reserve+0x169/0x1c0xfs_trans_alloc+0xb9/0x130xfs_vn_update_time+0x4e/0x130file_update_time+0xa7/0x100xfs_file_aio_write_checks+0x178/0x1a0
>>>> 2019-01-12 06:06:35     ?
>>>
>>> I'm not sure how reliable the stack is, but fwiw it looks like this is
>>> an aio that is waiting on transaction reservation to update a file time.
>>> Transaction reservation is a normal blocking path because log space is a
>>> finite resource. We certainly don't expect to block here for minutes,
>>> but the fact that we don't know anything about your filesystem geometry,
>>> mount options, underlying storage, workload, etc. will make it difficult
>>> for anybody to surmise what the problem could be.
>>>
>>> Please see the following url for what information to include when
>>> reporting a problem:
>>>
>>> http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F
>>>
>>> I'd also suggest to include broader dmesg output and/or xfs_repair
>>> output if there are multiple error reports that aren't exactly the same.
>>>
>>
>> I'm sorry, I missed this page on my search for an FAQ somehow.
>>
>>
>> * Kernel Version: Linux 4.12.0+139-ph #1 SMP Tue Jan 1 21:46:16 UTC 2019
>> x86_64 GNU/Linux
> 
> Is that an unmodified distro kernel or one you've patched and built
> yourself?

Unmodified regarding XFS and any subsystems related to XFS, as I was
being told.

> 
>> * xfsprogs version: 4.9.0
>>
>> * Single CPU, Xeon E5-1650 v3, 6 cores, 12 threads
>>
>> * /proc/meminfo, /proc/mounts, /proc/partitions and xfs_info can be
>> found here: https://pastebin.com/cZiTrUDL
> 
> Just  notes as I browse it.
> - lots of free memory.
> - xfs-info: 1.3TB, 32 ags, ~700MB log w/sunit =64fsbs
>   sunit=64 fsbs, swidth=192fsbs (RAID?)
> - mount options: noatime, sunit=512,sunit=1536, usrquota
> - /dev/sda3 mounted on /
> - /dev/sda3 also mounted on /home/tmp (bind mount of something?)
> 
>> * full dmesg output of problem mentioned in the first mail:
>> https://pastebin.com/pLaz18L1
> 
> No smoking gun.
> 
>> * a couple of more dmesg outputs from the same system with similar
>> behaviour:
>>  * https://pastebin.com/hWDbwcCr
>>  * https://pastebin.com/HAqs4yQc
> 
> Ok, so mysqld seems to be the problem child here.
> 

Our MySQL workload on this server is very small except for this time of
the day because our local backup to /backup happens during this time.
The highest IO happens during the night when our local backup is being
written. The timestamps of these two outputs suggest that the "mysql
dump" phase might just have been started. Unfortunately we only keep the
log of the last job, so I can't confirm that.

I might be able to dig up one or two more dmesg outputs for when these
hangs happen and no backup job is running.

>> * Raid Controller: Adaptec ASR8805
>>  * Logical Device 0 is a RAID6 with 5 SSDs (Samsung MZ7KM480), /dev/sda
> 
> Ok, so RAID6 on a RADI controller with 1GB cache and a small random
> write workload?
> 
>>  * Logical Device 1 is a single backup HDD (Seagate ST2000NX0253) for
>> internal backups, /dev/sdb
>>
>> * Output of xfs_repair: https://pastebin.com/JzVMqrLh
> 
> Nothing wrong at all. So this looks like it's either a log space
> accounting leak (i.e. XFS bug) or something else....
> 
>> The problem seems to happen randomly. There does not have to be high
>> load on our storage devices. This makes it pretty hard to find an exact
>> cause.
> 
> ... which makes me suspect "something else".
> 
> I note that nothing is stalled on reads from the device - it's all
> stalled on journal space (i.e. write operations). I've seen similar
> things before where the RAID controller is configured as a writeback
> cache and the workload just keeps dumping lots of small random writes
> into the RAID cache until it fills. Databases do lots of small
> writes.
> 
> This looks like the device is lightly loaded because writing into
> the cache is really fast. Right up until it fills and then has to
> dump hundreds of thousands of small writes to disk, which on RAID 6
> each require read-modify-raid-recalc-write cycles to run. This is
> really slow, and why RAID6 is generally a poor choice for database
> workloads.
> 
> i.e. when the RAID cache fills, new writes stalls waiting for a RAID
> cache flush - they run at slower than disk speed because they have
> to first wait for the RAID controller to comple.
> 
> It is is only noticed when the filesystem journal stalls
> because it's run out of space and is trying to dump a large amount
> of small metadata writes to the device to free up journal space. The
> journal space won't be freed up until the metadata that pins the
> tail of the log has been successfully written. When there's
> thousands of metadata IOs needed (a 700MB log can hold several
> hundred thousand dirty metadata objects in memory!) to move th elog
> forward, and the RAID cache is full, it will take a /long time/ and
> the filesystem will be stalled until that completes.
> 
> I've seen spinning disk RAID setups like this stall for hours while
> large RAID caches flush. SSDs should be a lot faster, but we're
> still potentially talking about having to do millions of IOs and the
> RAID controller will be CPU bound on parity recalculatoins.  So this
> /may/ just be a result of the storage configuration and have nothing
> to do with XFS at all.
> 
> Which leads me to ask: what is your RAID cache setup - write-thru,
> write-back, etc?
> 

Our RAID6 cache configuration:

   Read-cache setting                       : Disabled
   Read-cache status                        : Off
   Write-cache setting                      : Disabled
   Write-cache status                       : Off

Full Configuration: https://pastebin.com/PdGatDY4


- Daniel

Re: XFS filesystem hang

[Dave Chinner]

On Fri, Jan 18, 2019 at 03:48:46PM +0100, Daniel Aberger - Profihost AG wrote:
> Am 17.01.19 um 23:05 schrieb Dave Chinner:
> > On Thu, Jan 17, 2019 at 02:50:23PM +0100, Daniel Aberger - Profihost AG wrote:
> >> * Kernel Version: Linux 4.12.0+139-ph #1 SMP Tue Jan 1 21:46:16 UTC 2019
> >> x86_64 GNU/Linux
> > 
> > Is that an unmodified distro kernel or one you've patched and built
> > yourself?
> 
> Unmodified regarding XFS and any subsystems related to XFS, as I was
> being told.

That doesn't answer my question - has the kernel been patched (and
what with) or is it a completely unmodified upstream kernel?

> >> * /proc/meminfo, /proc/mounts, /proc/partitions and xfs_info can be
> >> found here: https://pastebin.com/cZiTrUDL
> > 
> > Just  notes as I browse it.
> > - lots of free memory.
> > - xfs-info: 1.3TB, 32 ags, ~700MB log w/sunit =64fsbs
> >   sunit=64 fsbs, swidth=192fsbs (RAID?)
> > - mount options: noatime, sunit=512,sunit=1536, usrquota
> > - /dev/sda3 mounted on /
> > - /dev/sda3 also mounted on /home/tmp (bind mount of something?)
> > 
> >> * full dmesg output of problem mentioned in the first mail:
> >> https://pastebin.com/pLaz18L1
> > 
> > No smoking gun.
> > 
> >> * a couple of more dmesg outputs from the same system with similar
> >> behaviour:
> >>  * https://pastebin.com/hWDbwcCr
> >>  * https://pastebin.com/HAqs4yQc
> > 
> > Ok, so mysqld seems to be the problem child here.
> > 
> 
> Our MySQL workload on this server is very small except for this time of
> the day because our local backup to /backup happens during this time.
> The highest IO happens during the night when our local backup is being
> written. The timestamps of these two outputs suggest that the "mysql
> dump" phase might just have been started. Unfortunately we only keep the
> log of the last job, so I can't confirm that.

Ok, so you've just started loading up the btrfs volume that is also
attached to the same raid controller, which does have raid caches
enabled....

I wonder if that has anything to do with it?

Best would be to capture iostat output for both luns (as per the
FAQ) when the problem workload starts.

> > Which leads me to ask: what is your RAID cache setup - write-thru,
> > write-back, etc?
> > 
> 
> Our RAID6 cache configuration:
> 
>    Read-cache setting                       : Disabled
>    Read-cache status                        : Off
>    Write-cache setting                      : Disabled
>    Write-cache status                       : Off

Ok, so read caching is turned off, which means it likely won't even
be caching stripes between modifications. May not be very efficient,
but hard to say if it's the problem or not.

> Full Configuration: https://pastebin.com/PdGatDY4

Yeah, caching is enabled on the backup btrfs lun, so there may be
interaction issues. Is the backup device idle (or stalling) at the
same time that the XFS messages are being issued?

CHeers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: XFS filesystem hang

[Daniel Aberger - Profihost AG]

Am 19.01.19 um 01:19 schrieb Dave Chinner:
> On Fri, Jan 18, 2019 at 03:48:46PM +0100, Daniel Aberger - Profihost AG wrote:
>> Am 17.01.19 um 23:05 schrieb Dave Chinner:
>>> On Thu, Jan 17, 2019 at 02:50:23PM +0100, Daniel Aberger - Profihost AG wrote:
>>>> * Kernel Version: Linux 4.12.0+139-ph #1 SMP Tue Jan 1 21:46:16 UTC 2019
>>>> x86_64 GNU/Linux
>>>
>>> Is that an unmodified distro kernel or one you've patched and built
>>> yourself?
>>
>> Unmodified regarding XFS and any subsystems related to XFS, as I was
>> being told.
> 
> That doesn't answer my question - has the kernel been patched (and
> what with) or is it a completely unmodified upstream kernel?
> 

The kernel we were running was OpenSUSE SLE15 based on commit
6c5c7489089608d89b7ce310bca44812e2b0a4a5.

https://github.com/openSUSE/kernel


>>>> * /proc/meminfo, /proc/mounts, /proc/partitions and xfs_info can be
>>>> found here: https://pastebin.com/cZiTrUDL
>>>
>>> Just  notes as I browse it.
>>> - lots of free memory.
>>> - xfs-info: 1.3TB, 32 ags, ~700MB log w/sunit =64fsbs
>>>   sunit=64 fsbs, swidth=192fsbs (RAID?)
>>> - mount options: noatime, sunit=512,sunit=1536, usrquota
>>> - /dev/sda3 mounted on /
>>> - /dev/sda3 also mounted on /home/tmp (bind mount of something?)
>>>
>>>> * full dmesg output of problem mentioned in the first mail:
>>>> https://pastebin.com/pLaz18L1
>>>
>>> No smoking gun.
>>>
>>>> * a couple of more dmesg outputs from the same system with similar
>>>> behaviour:
>>>>  * https://pastebin.com/hWDbwcCr
>>>>  * https://pastebin.com/HAqs4yQc
>>>
>>> Ok, so mysqld seems to be the problem child here.
>>>
>>
>> Our MySQL workload on this server is very small except for this time of
>> the day because our local backup to /backup happens during this time.
>> The highest IO happens during the night when our local backup is being
>> written. The timestamps of these two outputs suggest that the "mysql
>> dump" phase might just have been started. Unfortunately we only keep the
>> log of the last job, so I can't confirm that.
> 
> Ok, so you've just started loading up the btrfs volume that is also
> attached to the same raid controller, which does have raid caches
> enabled....
> 
> I wonder if that has anything to do with it?
> 

Do you suggest to change any caching options?

> Best would be to capture iostat output for both luns (as per the
> FAQ) when the problem workload starts.
> 

What I can give you so far is two I/O activity screenshots of Grafana of
two of the dmesg outputs above.

https://imgur.com/a/3lL776U


>>> Which leads me to ask: what is your RAID cache setup - write-thru,
>>> write-back, etc?
>>>
>>
>> Our RAID6 cache configuration:
>>
>>    Read-cache setting                       : Disabled
>>    Read-cache status                        : Off
>>    Write-cache setting                      : Disabled
>>    Write-cache status                       : Off
> 
> Ok, so read caching is turned off, which means it likely won't even
> be caching stripes between modifications. May not be very efficient,
> but hard to say if it's the problem or not.
> 
>> Full Configuration: https://pastebin.com/PdGatDY4
> 
> Yeah, caching is enabled on the backup btrfs lun, so there may be
> interaction issues. Is the backup device idle (or stalling) at the
> same time that the XFS messages are being issued?

In 2 out of 3 cases it happened while the backup job was running, which
starts at 0:10 am and finishes roughly between 2:30 and 3:30 am on this
particular machine. So it wasn't idle.

The MySQL dumping phase takes about 20 to 25 minutes and happens at the
end of the backup job.

Re: XFS filesystem hang

[Stefan Priebe - Profihost AG]

Dear dave,

we're still seeing the issue below. I verified that we see this also on:
1.) systems without any raid or controller (pure qemu/kvm with ceph rbd
backend)

2.) systems where no btrs is running nor any backup jobs

To me this looks like a xfs lockup. I found the same trace here:
"https://access.redhat.com/solutions/2964341"

but do not have any access to this subscriber content.

Greets,
Stefan

Am 21.01.19 um 15:59 schrieb Daniel Aberger - Profihost AG:
> Am 19.01.19 um 01:19 schrieb Dave Chinner:
>> On Fri, Jan 18, 2019 at 03:48:46PM +0100, Daniel Aberger - Profihost AG wrote:
>>> Am 17.01.19 um 23:05 schrieb Dave Chinner:
>>>> On Thu, Jan 17, 2019 at 02:50:23PM +0100, Daniel Aberger - Profihost AG wrote:
>>>>> * Kernel Version: Linux 4.12.0+139-ph #1 SMP Tue Jan 1 21:46:16 UTC 2019
>>>>> x86_64 GNU/Linux
>>>>
>>>> Is that an unmodified distro kernel or one you've patched and built
>>>> yourself?
>>>
>>> Unmodified regarding XFS and any subsystems related to XFS, as I was
>>> being told.
>>
>> That doesn't answer my question - has the kernel been patched (and
>> what with) or is it a completely unmodified upstream kernel?
>>
> 
> The kernel we were running was OpenSUSE SLE15 based on commit
> 6c5c7489089608d89b7ce310bca44812e2b0a4a5.
> 
> https://github.com/openSUSE/kernel
> 
> 
>>>>> * /proc/meminfo, /proc/mounts, /proc/partitions and xfs_info can be
>>>>> found here: https://pastebin.com/cZiTrUDL
>>>>
>>>> Just  notes as I browse it.
>>>> - lots of free memory.
>>>> - xfs-info: 1.3TB, 32 ags, ~700MB log w/sunit =64fsbs
>>>>   sunit=64 fsbs, swidth=192fsbs (RAID?)
>>>> - mount options: noatime, sunit=512,sunit=1536, usrquota
>>>> - /dev/sda3 mounted on /
>>>> - /dev/sda3 also mounted on /home/tmp (bind mount of something?)
>>>>
>>>>> * full dmesg output of problem mentioned in the first mail:
>>>>> https://pastebin.com/pLaz18L1
>>>>
>>>> No smoking gun.
>>>>
>>>>> * a couple of more dmesg outputs from the same system with similar
>>>>> behaviour:
>>>>>  * https://pastebin.com/hWDbwcCr
>>>>>  * https://pastebin.com/HAqs4yQc
>>>>
>>>> Ok, so mysqld seems to be the problem child here.
>>>>
>>>
>>> Our MySQL workload on this server is very small except for this time of
>>> the day because our local backup to /backup happens during this time.
>>> The highest IO happens during the night when our local backup is being
>>> written. The timestamps of these two outputs suggest that the "mysql
>>> dump" phase might just have been started. Unfortunately we only keep the
>>> log of the last job, so I can't confirm that.
>>
>> Ok, so you've just started loading up the btrfs volume that is also
>> attached to the same raid controller, which does have raid caches
>> enabled....
>>
>> I wonder if that has anything to do with it?
>>
> 
> Do you suggest to change any caching options?
> 
>> Best would be to capture iostat output for both luns (as per the
>> FAQ) when the problem workload starts.
>>
> 
> What I can give you so far is two I/O activity screenshots of Grafana of
> two of the dmesg outputs above.
> 
> https://imgur.com/a/3lL776U
> 
> 
>>>> Which leads me to ask: what is your RAID cache setup - write-thru,
>>>> write-back, etc?
>>>>
>>>
>>> Our RAID6 cache configuration:
>>>
>>>    Read-cache setting                       : Disabled
>>>    Read-cache status                        : Off
>>>    Write-cache setting                      : Disabled
>>>    Write-cache status                       : Off
>>
>> Ok, so read caching is turned off, which means it likely won't even
>> be caching stripes between modifications. May not be very efficient,
>> but hard to say if it's the problem or not.
>>
>>> Full Configuration: https://pastebin.com/PdGatDY4
>>
>> Yeah, caching is enabled on the backup btrfs lun, so there may be
>> interaction issues. Is the backup device idle (or stalling) at the
>> same time that the XFS messages are being issued?
> 
> In 2 out of 3 cases it happened while the backup job was running, which
> starts at 0:10 am and finishes roughly between 2:30 and 3:30 am on this
> particular machine. So it wasn't idle.
> 
> The MySQL dumping phase takes about 20 to 25 minutes and happens at the
> end of the backup job.
>