Re: Known and unfixed active data loss bug in MM + XFS with large folios since Dec 2021 (any kernel from 6.1 upwards)

Christian Theune
2024-10-11T07:27:41Z

Hi,

> On 10. Oct 2024, at 08:29, Christian Theune <ct@flyingcircus.io> wrote:
>
>
>> On 1. Oct 2024, at 02:56, Chris Mason <clm@meta.com> wrote:
>>
>> Not disagreeing with Linus at all, but given that you've got IO
>> throttling too, we might really just be waiting. It's hard to tell
>> because the hung task timeouts only give you information about one process.
>>
>> I've attached a minimal version of a script we use here to show all the
>> D state processes, it might help explain things. The only problem is
>> you have to actually ssh to the box and run it when you're stuck.
>>
>> The idea is to print the stack trace of every D state process, and then
>> also print out how often each unique stack trace shows up. When we're
>> deadlocked on something, there are normally a bunch of the same stack
>> (say waiting on writeback) and then one jerk sitting around in a
>> different stack who is causing all the trouble.
>
> I think I should be able to trigger this. I’ve seen around a 100 of those issues over the last week and the chance of it happening correlates with a certain workload that should be easy to trigger. Also, the condition remains for at around 5 minutes, so I should be able to trace it when I see the alert in an interactive session.
>
> I’ve verified I can run your script and I’ll get back to you in the next days.

I wasn’t able to create a reproducer after all so I’ve set up alerting.

I just caught one right away, but it unblocked quickly after I logged in:

The original message that triggered the alert was:

[Oct11 09:18] INFO: task nix-build:157920 blocked for more than 122 seconds.
[ +0.000937] Not tainted 6.11.0 #1-NixOS
[ +0.000540] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ +0.000902] task:nix-build state:D stack:0 pid:157920 tgid:157920 ppid:157919 flags:0x00000002
[ +0.001098] Call Trace:
[ +0.000306] <TASK>
[ +0.000279] __schedule+0x3a3/0x1300
[ +0.000478] schedule+0x27/0xf0
[ +0.000392] io_schedule+0x46/0x70
[ +0.000436] folio_wait_bit_common+0x13f/0x340
[ +0.000572] ? __pfx_wake_page_function+0x10/0x10
[ +0.000592] folio_wait_writeback+0x2b/0x80
[ +0.000466] truncate_inode_partial_folio+0x5e/0x1b0
[ +0.000586] truncate_inode_pages_range+0x1de/0x400
[ +0.000595] evict+0x29f/0x2c0
[ +0.000396] ? iput+0x6e/0x230
[ +0.000408] ? _atomic_dec_and_lock+0x39/0x50
[ +0.000542] do_unlinkat+0x2de/0x330
[ +0.000402] __x64_sys_unlink+0x3f/0x70
[ +0.000419] do_syscall_64+0xb7/0x200
[ +0.000407] entry_SYSCALL_64_after_hwframe+0x77/0x7f
[ +0.000556] RIP: 0033:0x7f2bb5d1056b
[ +0.000473] RSP: 002b:00007ffc013c8588 EFLAGS: 00000206 ORIG_RAX: 0000000000000057
[ +0.000942] RAX: ffffffffffffffda RBX: 000055963c267500 RCX: 00007f2bb5d1056b
[ +0.000859] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000055963c268c80
[ +0.000800] RBP: 000055963c267690 R08: 0000000000016020 R09: 0000000000000000
[ +0.000977] R10: 00000000000000f0 R11: 0000000000000206 R12: 00007ffc013c85c8
[ +0.000826] R13: 00007ffc013c85ac R14: 00007ffc013c8ed0 R15: 00005596441e42b0
[ +0.000833] </TASK>

Then after logging in I caught it once with walker.py - this was about a minute after the alert triggered I think. I’ll add timestamps to walker.py in the next instances:

157920 nix-build D
[<0>] folio_wait_bit_common+0x13f/0x340
[<0>] folio_wait_writeback+0x2b/0x80
[<0>] truncate_inode_partial_folio+0x5e/0x1b0
[<0>] truncate_inode_pages_range+0x1de/0x400
[<0>] evict+0x29f/0x2c0
[<0>] do_unlinkat+0x2de/0x330
[<0>] __x64_sys_unlink+0x3f/0x70
[<0>] do_syscall_64+0xb7/0x200
[<0>] entry_SYSCALL_64_after_hwframe+0x77/0x7f

-----
stack summary

1 hit:
[<0>] folio_wait_bit_common+0x13f/0x340
[<0>] folio_wait_writeback+0x2b/0x80
[<0>] truncate_inode_partial_folio+0x5e/0x1b0
[<0>] truncate_inode_pages_range+0x1de/0x400
[<0>] evict+0x29f/0x2c0
[<0>] do_unlinkat+0x2de/0x330
[<0>] __x64_sys_unlink+0x3f/0x70
[<0>] do_syscall_64+0xb7/0x200
[<0>] entry_SYSCALL_64_after_hwframe+0x77/0x7f

I tried once again after 1-2 seconds and got this:

157920 nix-build D
[<0>] xlog_wait_on_iclog+0x167/0x180 [xfs]
[<0>] xfs_log_force_seq+0x8d/0x150 [xfs]
[<0>] xfs_file_fsync+0x195/0x2a0 [xfs]
[<0>] __x64_sys_fdatasync+0x52/0x90
[<0>] do_syscall_64+0xb7/0x200
[<0>] entry_SYSCALL_64_after_hwframe+0x77/0x7f

-----
stack summary

1 hit:
[<0>] xlog_wait_on_iclog+0x167/0x180 [xfs]
[<0>] xfs_log_force_seq+0x8d/0x150 [xfs]
[<0>] xfs_file_fsync+0x195/0x2a0 [xfs]
[<0>] __x64_sys_fdatasync+0x52/0x90
[<0>] do_syscall_64+0xb7/0x200
[<0>] entry_SYSCALL_64_after_hwframe+0x77/0x7f

and after that the process was done and exited. The last traceback looks unlocked already.

I’m going to gather a few more instances during the day and will post them as a batch later.

Christian

--
Christian Theune · ct@flyingcircus.io · +49 345 219401 0
Flying Circus Internet Operations GmbH · https://flyingcircus.io
Leipziger Str. 70/71 · 06108 Halle (Saale) · Deutschland
HR Stendal HRB 21169 · Geschäftsführer: Christian Theune, Christian Zagrodnick