Kernels 4.15..5.0.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

Kernels 4.15..5.0.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Zygo Blaxell]

[-- Attachment #1: Type: text/plain, Size: 2819 bytes --]

When filesystems are mounted flushoncommit, I get this warning roughly
every 30 seconds:

	[ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
	[ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
	[ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
	[ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
	[ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
	[ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
	[ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
	[ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
	[ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
	[ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
	[ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
	[ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
	[ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
	[ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
	[ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
	[ 4575.190094] Call Trace:
	[ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
	[ 4575.192115]  ? start_transaction+0x91/0x4d0
	[ 4575.193197]  transaction_kthread+0x146/0x180
	[ 4575.194415]  kthread+0x106/0x140
	[ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
	[ 4575.196903]  ? kthread_park+0x90/0x90
	[ 4575.198412]  ret_from_fork+0x3a/0x50
	[ 4575.199374] irq event stamp: 54922780
	[ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
	[ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
	[ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
	[ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
	[ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---

For my own kernel builds I just comment out the line in fs-writeback.c,
but that's not a real solution.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]

Re: Kernels 4.15..5.0.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Nikolay Borisov]

On 22.03.19 г. 6:17 ч., Zygo Blaxell wrote:
> When filesystems are mounted flushoncommit, I get this warning roughly
> every 30 seconds:
> 
> 	[ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> 	[ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> 	[ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> 	[ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> 	[ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> 	[ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> 	[ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> 	[ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> 	[ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> 	[ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> 	[ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> 	[ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> 	[ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> 	[ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> 	[ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> 	[ 4575.190094] Call Trace:
> 	[ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> 	[ 4575.192115]  ? start_transaction+0x91/0x4d0
> 	[ 4575.193197]  transaction_kthread+0x146/0x180
> 	[ 4575.194415]  kthread+0x106/0x140
> 	[ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> 	[ 4575.196903]  ? kthread_park+0x90/0x90
> 	[ 4575.198412]  ret_from_fork+0x3a/0x50
> 	[ 4575.199374] irq event stamp: 54922780
> 	[ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> 	[ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> 	[ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> 	[ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> 	[ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> 
> For my own kernel builds I just comment out the line in fs-writeback.c,
> but that's not a real solution.
> 

This is a longstanding and known issue for which no good solution exists
ATM.

Re: Kernels 4.15..5.0.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[David Sterba]

On Fri, Mar 22, 2019 at 09:32:37AM +0200, Nikolay Borisov wrote:
> On 22.03.19 г. 6:17 ч., Zygo Blaxell wrote:
> > When filesystems are mounted flushoncommit, I get this warning roughly
> > every 30 seconds:
> > 
> > 	[ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> > 	[ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> > 	[ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> > 	[ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > 	[ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> > 	[ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> > 	[ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> > 	[ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> > 	[ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> > 	[ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> > 	[ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> > 	[ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> > 	[ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> > 	[ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > 	[ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> > 	[ 4575.190094] Call Trace:
> > 	[ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> > 	[ 4575.192115]  ? start_transaction+0x91/0x4d0
> > 	[ 4575.193197]  transaction_kthread+0x146/0x180
> > 	[ 4575.194415]  kthread+0x106/0x140
> > 	[ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> > 	[ 4575.196903]  ? kthread_park+0x90/0x90
> > 	[ 4575.198412]  ret_from_fork+0x3a/0x50
> > 	[ 4575.199374] irq event stamp: 54922780
> > 	[ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> > 	[ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> > 	[ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> > 	[ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> > 	[ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> > 
> > For my own kernel builds I just comment out the line in fs-writeback.c,
> > but that's not a real solution.
> > 
> 
> This is a longstanding and known issue for which no good solution exists
> ATM.

The s_umount mutex is taken around the writeback_inodes_sb_nr call in
btrfs_writeback_inodes_sb_nr:

 4689 static void btrfs_writeback_inodes_sb_nr(struct btrfs_fs_info *fs_info,
 4690                                          unsigned long nr_pages, int nr_items)
 4691 {
 4692         struct super_block *sb = fs_info->sb;
 4693
 4694         if (down_read_trylock(&sb->s_umount)) {
 4695                 writeback_inodes_sb_nr(sb, nr_pages, WB_REASON_FS_FREE_SPACE);
 4696                 up_read(&sb->s_umount);
 4697         } else {

but __writeback_inodes_sb_nr still complains.

So, that's a longstanding issue and I think there must be a precise
analysis why this is hard to solve somewhere in the mailinglist but I'm
not going to look it up right now.

The other comment in btrfs_writeback_inodes_sb_nr says why it's ok to
skip the s_umount mutex because we know there's other protection against
remount.

If the down_read_trylock does not help to get rid of the warning, why
it's there or why is it not taken for write?

Re: Kernels 4.15..5.0.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Filipe Manana]

On Fri, Mar 22, 2019 at 3:59 PM David Sterba <dsterba@suse.cz> wrote:
>
> On Fri, Mar 22, 2019 at 09:32:37AM +0200, Nikolay Borisov wrote:
> > On 22.03.19 г. 6:17 ч., Zygo Blaxell wrote:
> > > When filesystems are mounted flushoncommit, I get this warning roughly
> > > every 30 seconds:
> > >
> > >     [ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> > >     [ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> > >     [ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> > >     [ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > >     [ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> > >     [ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> > >     [ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> > >     [ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> > >     [ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> > >     [ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> > >     [ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> > >     [ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> > >     [ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> > >     [ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > >     [ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> > >     [ 4575.190094] Call Trace:
> > >     [ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> > >     [ 4575.192115]  ? start_transaction+0x91/0x4d0
> > >     [ 4575.193197]  transaction_kthread+0x146/0x180
> > >     [ 4575.194415]  kthread+0x106/0x140
> > >     [ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> > >     [ 4575.196903]  ? kthread_park+0x90/0x90
> > >     [ 4575.198412]  ret_from_fork+0x3a/0x50
> > >     [ 4575.199374] irq event stamp: 54922780
> > >     [ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> > >     [ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> > >     [ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> > >     [ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> > >     [ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> > >
> > > For my own kernel builds I just comment out the line in fs-writeback.c,
> > > but that's not a real solution.
> > >
> >
> > This is a longstanding and known issue for which no good solution exists
> > ATM.
>
> The s_umount mutex is taken around the writeback_inodes_sb_nr call in
> btrfs_writeback_inodes_sb_nr:
>
>  4689 static void btrfs_writeback_inodes_sb_nr(struct btrfs_fs_info *fs_info,
>  4690                                          unsigned long nr_pages, int nr_items)
>  4691 {
>  4692         struct super_block *sb = fs_info->sb;
>  4693
>  4694         if (down_read_trylock(&sb->s_umount)) {
>  4695                 writeback_inodes_sb_nr(sb, nr_pages, WB_REASON_FS_FREE_SPACE);
>  4696                 up_read(&sb->s_umount);
>  4697         } else {
>
> but __writeback_inodes_sb_nr still complains.

Yes, because btrfs_witeback_inodes_sb_nr() is not what is called
during transaction commit if the fs is mounted with -o flushoncommit.
What is called is writeback_inodes_sb() (which gets __writeback_inodes_sb_nr()).

Calling btrfs_witeback_inodes_sb_nr() would just fallback to
btrfs_start_delalloc_roots() during a concurrent freeze (which does a
down_write()
on that semaphore), bringing back the problem Josef tried to fix at [1].

This problem of the warning, and the original problem [1], could
possibly be solved by making sure no regular transaction joins happen
after we
start the transaction commit, something along the lines of:

https://friendpaste.com/45NhhVPko5txKuuzDPqhyK

Adding Josef to cc.

To just silence the warning, adding a down_read_trylock()/upread() at
btrfs_start_delalloc_flush() would be simple.

[1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=ce8ea7cc6eb3139f4c730d647325e69354159b0f

> So, that's a longstanding issue and I think there must be a precise
> analysis why this is hard to solve somewhere in the mailinglist but I'm
> not going to look it up right now.
>
> The other comment in btrfs_writeback_inodes_sb_nr says why it's ok to
> skip the s_umount mutex because we know there's other protection against
> remount.
>
> If the down_read_trylock does not help to get rid of the warning, why
> it's there or why is it not taken for write?



--
Filipe David Manana,

“Whether you think you can, or you think you can't — you're right.”

Re: Kernels 4.15..5.0.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Zygo Blaxell]

On Fri, Mar 22, 2019 at 04:59:11PM +0100, David Sterba wrote:
> On Fri, Mar 22, 2019 at 09:32:37AM +0200, Nikolay Borisov wrote:
> > On 22.03.19 г. 6:17 ч., Zygo Blaxell wrote:
> > > When filesystems are mounted flushoncommit, I get this warning roughly
> > > every 30 seconds:
> > > 
> > > 	[ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> > > 	[ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> > > 	[ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> > > 	[ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > > 	[ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> > > 	[ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> > > 	[ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> > > 	[ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> > > 	[ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> > > 	[ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> > > 	[ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> > > 	[ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> > > 	[ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> > > 	[ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > 	[ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> > > 	[ 4575.190094] Call Trace:
> > > 	[ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> > > 	[ 4575.192115]  ? start_transaction+0x91/0x4d0
> > > 	[ 4575.193197]  transaction_kthread+0x146/0x180
> > > 	[ 4575.194415]  kthread+0x106/0x140
> > > 	[ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> > > 	[ 4575.196903]  ? kthread_park+0x90/0x90
> > > 	[ 4575.198412]  ret_from_fork+0x3a/0x50
> > > 	[ 4575.199374] irq event stamp: 54922780
> > > 	[ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> > > 	[ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> > > 	[ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> > > 	[ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> > > 	[ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> > > 
> > > For my own kernel builds I just comment out the line in fs-writeback.c,
> > > but that's not a real solution.
> > > 
> > 
> > This is a longstanding and known issue for which no good solution exists
> > ATM.
> 
> The s_umount mutex is taken around the writeback_inodes_sb_nr call in
> btrfs_writeback_inodes_sb_nr:
> 
>  4689 static void btrfs_writeback_inodes_sb_nr(struct btrfs_fs_info *fs_info,
>  4690                                          unsigned long nr_pages, int nr_items)
>  4691 {
>  4692         struct super_block *sb = fs_info->sb;
>  4693
>  4694         if (down_read_trylock(&sb->s_umount)) {
>  4695                 writeback_inodes_sb_nr(sb, nr_pages, WB_REASON_FS_FREE_SPACE);
>  4696                 up_read(&sb->s_umount);
>  4697         } else {
> 
> but __writeback_inodes_sb_nr still complains.
> 
> So, that's a longstanding issue and I think there must be a precise
> analysis why this is hard to solve somewhere in the mailinglist but I'm
> not going to look it up right now.

I tried to google this, but all I got was "it's because of commit
ce8ea7cc6eb3" and "you can work around it by removing flushoncommit".

noflushoncommit isn't a good answer at the moment, because of the data
lost in delalloc extents (the files get holes where the data was supposed
to be) when the btrfs host crashes or locks up.  Other bugs in btrfs
are locking up the filesystem at a rate that varies between monthly and
several times daily.  Too often to clean up the noflushoncommit mess.

Speaking of other btrfs bugs, I wonder if cherry-picking ce8ea7cc6eb3
into 4.14.107 will solve (one of) its deadlock problem(s)...

> The other comment in btrfs_writeback_inodes_sb_nr says why it's ok to
> skip the s_umount mutex because we know there's other protection against
> remount.

Yeah, you'd need to finish any commit in progress before you could umount,
simply because umount triggers its own commit.

If it's harmless, I'll just comment out the WARN_ON while looking for bugs
I care more about.

> If the down_read_trylock does not help to get rid of the warning, why
> it's there or why is it not taken for write?

Wouldn't a write lock out all other writes during the commit?

Re: Kernels 4.15..5.0.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Zygo Blaxell]

On Fri, Mar 22, 2019 at 05:26:52PM +0000, Filipe Manana wrote:
> On Fri, Mar 22, 2019 at 3:59 PM David Sterba <dsterba@suse.cz> wrote:
> >
> > On Fri, Mar 22, 2019 at 09:32:37AM +0200, Nikolay Borisov wrote:
> > > On 22.03.19 г. 6:17 ч., Zygo Blaxell wrote:
> > > > When filesystems are mounted flushoncommit, I get this warning roughly
> > > > every 30 seconds:
> > > >
> > > >     [ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> > > >     [ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> > > >     [ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> > > >     [ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > > >     [ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> > > >     [ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> > > >     [ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> > > >     [ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> > > >     [ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> > > >     [ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> > > >     [ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> > > >     [ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> > > >     [ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> > > >     [ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > >     [ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> > > >     [ 4575.190094] Call Trace:
> > > >     [ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> > > >     [ 4575.192115]  ? start_transaction+0x91/0x4d0
> > > >     [ 4575.193197]  transaction_kthread+0x146/0x180
> > > >     [ 4575.194415]  kthread+0x106/0x140
> > > >     [ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> > > >     [ 4575.196903]  ? kthread_park+0x90/0x90
> > > >     [ 4575.198412]  ret_from_fork+0x3a/0x50
> > > >     [ 4575.199374] irq event stamp: 54922780
> > > >     [ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> > > >     [ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> > > >     [ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> > > >     [ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> > > >     [ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> > > >
> > > > For my own kernel builds I just comment out the line in fs-writeback.c,
> > > > but that's not a real solution.
> > > >
> > >
> > > This is a longstanding and known issue for which no good solution exists
> > > ATM.
> >
> > The s_umount mutex is taken around the writeback_inodes_sb_nr call in
> > btrfs_writeback_inodes_sb_nr:
> >
> >  4689 static void btrfs_writeback_inodes_sb_nr(struct btrfs_fs_info *fs_info,
> >  4690                                          unsigned long nr_pages, int nr_items)
> >  4691 {
> >  4692         struct super_block *sb = fs_info->sb;
> >  4693
> >  4694         if (down_read_trylock(&sb->s_umount)) {
> >  4695                 writeback_inodes_sb_nr(sb, nr_pages, WB_REASON_FS_FREE_SPACE);
> >  4696                 up_read(&sb->s_umount);
> >  4697         } else {
> >
> > but __writeback_inodes_sb_nr still complains.
> 
> Yes, because btrfs_witeback_inodes_sb_nr() is not what is called
> during transaction commit if the fs is mounted with -o flushoncommit.
> What is called is writeback_inodes_sb() (which gets __writeback_inodes_sb_nr()).
> 
> Calling btrfs_witeback_inodes_sb_nr() would just fallback to
> btrfs_start_delalloc_roots() during a concurrent freeze (which does a
> down_write()
> on that semaphore), bringing back the problem Josef tried to fix at [1].
> 
> This problem of the warning, and the original problem [1], could
> possibly be solved by making sure no regular transaction joins happen
> after we
> start the transaction commit, something along the lines of:
> 
> https://friendpaste.com/45NhhVPko5txKuuzDPqhyK

I threw that patch at a test machine to see what happens, and what happens
is that the filesystem is destroyed a few hours later.  So something along
those lines...but definitely not exactly that.  ;)

I wonder if this is related to the deadlocks on 4.14 that are
taking my machines down daily.  The symptoms sound similar:
btrfs_start_delalloc_roots and __sb_start_write (which is called by
sb_start_intwrite) are on call traces in 7 out of 15 deadlock cases
(all 15 have btrfs_start_delalloc_roots, 8 do not have __sb_start_write).
That would mean that there's two distinct deadlock bugs in 4.14, but hey,
I'm willing to fix them one at a time...

I'll try putting ce8ea7cc6eb3139f4c730d647325e69354159b0f on a 4.14
kernel during the next testing cycle and see what happens.

> Adding Josef to cc.
> 
> To just silence the warning, adding a down_read_trylock()/upread() at
> btrfs_start_delalloc_flush() would be simple.
> 
> [1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=ce8ea7cc6eb3139f4c730d647325e69354159b0f
> 
> > So, that's a longstanding issue and I think there must be a precise
> > analysis why this is hard to solve somewhere in the mailinglist but I'm
> > not going to look it up right now.
> >
> > The other comment in btrfs_writeback_inodes_sb_nr says why it's ok to
> > skip the s_umount mutex because we know there's other protection against
> > remount.
> >
> > If the down_read_trylock does not help to get rid of the warning, why
> > it's there or why is it not taken for write?
> 
> 
> 
> --
> Filipe David Manana,
> 
> “Whether you think you can, or you think you can't — you're right.”

Re: Kernels 4.15..5.0.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Filipe Manana]

On Tue, Mar 26, 2019 at 11:13 PM Zygo Blaxell
<ce3g8jdj@umail.furryterror.org> wrote:
>
> On Fri, Mar 22, 2019 at 05:26:52PM +0000, Filipe Manana wrote:
> > On Fri, Mar 22, 2019 at 3:59 PM David Sterba <dsterba@suse.cz> wrote:
> > >
> > > On Fri, Mar 22, 2019 at 09:32:37AM +0200, Nikolay Borisov wrote:
> > > > On 22.03.19 г. 6:17 ч., Zygo Blaxell wrote:
> > > > > When filesystems are mounted flushoncommit, I get this warning roughly
> > > > > every 30 seconds:
> > > > >
> > > > >     [ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> > > > >     [ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> > > > >     [ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> > > > >     [ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > > > >     [ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> > > > >     [ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> > > > >     [ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> > > > >     [ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> > > > >     [ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> > > > >     [ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> > > > >     [ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> > > > >     [ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> > > > >     [ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> > > > >     [ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > > >     [ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> > > > >     [ 4575.190094] Call Trace:
> > > > >     [ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> > > > >     [ 4575.192115]  ? start_transaction+0x91/0x4d0
> > > > >     [ 4575.193197]  transaction_kthread+0x146/0x180
> > > > >     [ 4575.194415]  kthread+0x106/0x140
> > > > >     [ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> > > > >     [ 4575.196903]  ? kthread_park+0x90/0x90
> > > > >     [ 4575.198412]  ret_from_fork+0x3a/0x50
> > > > >     [ 4575.199374] irq event stamp: 54922780
> > > > >     [ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> > > > >     [ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> > > > >     [ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> > > > >     [ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> > > > >     [ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> > > > >
> > > > > For my own kernel builds I just comment out the line in fs-writeback.c,
> > > > > but that's not a real solution.
> > > > >
> > > >
> > > > This is a longstanding and known issue for which no good solution exists
> > > > ATM.
> > >
> > > The s_umount mutex is taken around the writeback_inodes_sb_nr call in
> > > btrfs_writeback_inodes_sb_nr:
> > >
> > >  4689 static void btrfs_writeback_inodes_sb_nr(struct btrfs_fs_info *fs_info,
> > >  4690                                          unsigned long nr_pages, int nr_items)
> > >  4691 {
> > >  4692         struct super_block *sb = fs_info->sb;
> > >  4693
> > >  4694         if (down_read_trylock(&sb->s_umount)) {
> > >  4695                 writeback_inodes_sb_nr(sb, nr_pages, WB_REASON_FS_FREE_SPACE);
> > >  4696                 up_read(&sb->s_umount);
> > >  4697         } else {
> > >
> > > but __writeback_inodes_sb_nr still complains.
> >
> > Yes, because btrfs_witeback_inodes_sb_nr() is not what is called
> > during transaction commit if the fs is mounted with -o flushoncommit.
> > What is called is writeback_inodes_sb() (which gets __writeback_inodes_sb_nr()).
> >
> > Calling btrfs_witeback_inodes_sb_nr() would just fallback to
> > btrfs_start_delalloc_roots() during a concurrent freeze (which does a
> > down_write()
> > on that semaphore), bringing back the problem Josef tried to fix at [1].
> >
> > This problem of the warning, and the original problem [1], could
> > possibly be solved by making sure no regular transaction joins happen
> > after we
> > start the transaction commit, something along the lines of:
> >
> > https://friendpaste.com/45NhhVPko5txKuuzDPqhyK
>
> I threw that patch at a test machine to see what happens, and what happens
> is that the filesystem is destroyed a few hours later.  So something along
> those lines...but definitely not exactly that.  ;)

Not surprised, it was only compile tested. Didn't run it, but it has
some room for races.

>
> I wonder if this is related to the deadlocks on 4.14 that are
> taking my machines down daily.  The symptoms sound similar:
> btrfs_start_delalloc_roots and __sb_start_write (which is called by
> sb_start_intwrite) are on call traces in 7 out of 15 deadlock cases
> (all 15 have btrfs_start_delalloc_roots, 8 do not have __sb_start_write).
> That would mean that there's two distinct deadlock bugs in 4.14, but hey,
> I'm willing to fix them one at a time...
>
> I'll try putting ce8ea7cc6eb3139f4c730d647325e69354159b0f on a 4.14
> kernel during the next testing cycle and see what happens.
>
> > Adding Josef to cc.
> >
> > To just silence the warning, adding a down_read_trylock()/upread() at
> > btrfs_start_delalloc_flush() would be simple.
> >
> > [1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=ce8ea7cc6eb3139f4c730d647325e69354159b0f
> >
> > > So, that's a longstanding issue and I think there must be a precise
> > > analysis why this is hard to solve somewhere in the mailinglist but I'm
> > > not going to look it up right now.
> > >
> > > The other comment in btrfs_writeback_inodes_sb_nr says why it's ok to
> > > skip the s_umount mutex because we know there's other protection against
> > > remount.
> > >
> > > If the down_read_trylock does not help to get rid of the warning, why
> > > it's there or why is it not taken for write?
> >
> >
> >
> > --
> > Filipe David Manana,
> >
> > “Whether you think you can, or you think you can't — you're right.”



-- 
Filipe David Manana,

“Whether you think you can, or you think you can't — you're right.”

Re: Kernels 4.15..5.1.3: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Zygo Blaxell]

[-- Attachment #1: Type: text/plain, Size: 3082 bytes --]

On Fri, Mar 22, 2019 at 12:17:32AM -0400, Zygo Blaxell wrote:
> When filesystems are mounted flushoncommit, I get this warning roughly
> every 30 seconds:
> 
> 	[ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> 	[ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> 	[ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> 	[ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> 	[ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> 	[ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> 	[ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> 	[ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> 	[ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> 	[ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> 	[ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> 	[ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> 	[ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> 	[ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> 	[ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> 	[ 4575.190094] Call Trace:
> 	[ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> 	[ 4575.192115]  ? start_transaction+0x91/0x4d0
> 	[ 4575.193197]  transaction_kthread+0x146/0x180
> 	[ 4575.194415]  kthread+0x106/0x140
> 	[ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> 	[ 4575.196903]  ? kthread_park+0x90/0x90
> 	[ 4575.198412]  ret_from_fork+0x3a/0x50
> 	[ 4575.199374] irq event stamp: 54922780
> 	[ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> 	[ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> 	[ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> 	[ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> 	[ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> 
> For my own kernel builds I just comment out the line in fs-writeback.c,
> but that's not a real solution.

FWIW, I still get this warning, and I still just comment out the line
in fs-writeback.c.


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]

Re: Kernels 4.15..5.5: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Zygo Blaxell]

[-- Attachment #1: Type: text/plain, Size: 3262 bytes --]

On Fri, Mar 22, 2019 at 12:17:32AM -0400, Zygo Blaxell wrote:
> When filesystems are mounted flushoncommit, I get this warning roughly
> every 30 seconds:
> 
> 	[ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> 	[ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> 	[ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> 	[ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> 	[ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> 	[ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> 	[ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> 	[ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> 	[ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> 	[ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> 	[ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> 	[ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> 	[ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> 	[ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> 	[ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> 	[ 4575.190094] Call Trace:
> 	[ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> 	[ 4575.192115]  ? start_transaction+0x91/0x4d0
> 	[ 4575.193197]  transaction_kthread+0x146/0x180
> 	[ 4575.194415]  kthread+0x106/0x140
> 	[ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> 	[ 4575.196903]  ? kthread_park+0x90/0x90
> 	[ 4575.198412]  ret_from_fork+0x3a/0x50
> 	[ 4575.199374] irq event stamp: 54922780
> 	[ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> 	[ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> 	[ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> 	[ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> 	[ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> 
> For my own kernel builds I just comment out the line in fs-writeback.c,
> but that's not a real solution.

This still happens in 5.5.0.  No changes in behavior or workaround, no
apparent harmful effect, almost 2 years running in stress-testing and
production.

I, for one, am glad we fixed all those other bugs before doing anything
about this one.  It is utterly harmless.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]

Re: Kernels 4.15..5.5: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Holger Hoffstätte]

On 2/4/20 6:04 AM, Zygo Blaxell wrote:
> On Fri, Mar 22, 2019 at 12:17:32AM -0400, Zygo Blaxell wrote:
>> When filesystems are mounted flushoncommit, I get this warning roughly
>> every 30 seconds:
>>
>> 	[ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
>> 	[ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
>> 	[ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
>> 	[ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>> 	[ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
>> 	[ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
>> 	[ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
>> 	[ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
>> 	[ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
>> 	[ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
>> 	[ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
>> 	[ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
>> 	[ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
>> 	[ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> 	[ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
>> 	[ 4575.190094] Call Trace:
>> 	[ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
>> 	[ 4575.192115]  ? start_transaction+0x91/0x4d0
>> 	[ 4575.193197]  transaction_kthread+0x146/0x180
>> 	[ 4575.194415]  kthread+0x106/0x140
>> 	[ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
>> 	[ 4575.196903]  ? kthread_park+0x90/0x90
>> 	[ 4575.198412]  ret_from_fork+0x3a/0x50
>> 	[ 4575.199374] irq event stamp: 54922780
>> 	[ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
>> 	[ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
>> 	[ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
>> 	[ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
>> 	[ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
>>
>> For my own kernel builds I just comment out the line in fs-writeback.c,
>> but that's not a real solution.
> 
> This still happens in 5.5.0.  No changes in behavior or workaround, no
> apparent harmful effect, almost 2 years running in stress-testing and
> production.
> 
> I, for one, am glad we fixed all those other bugs before doing anything
> about this one.  It is utterly harmless.

This triggered my archeology itch. I had to go deeper.

The warning goes all the way back to 2010 (kernel 2.6.x) when everything
happened at FusionIO.

Commit [1] introduced it as preparation for [2].

The only caller of writeback_inodes_sb_nr is btrfs_writeback_inodes_sb_nr in
(today's) space-info.c, where the mutex trylock was introduced in [3], apparently
to work around a VFS function that didn't do it for btrfs at the time.

Flushoncommit was added by Sage Weil for Ceph's btrfs backend in [4], even
before the WARN_ON, in 2009. We know how that story ended.

Why has nobody except you noticed this? Probably because the number of people
actually using it or reporting bugs is.. very small. ¯\_(ツ)_/¯

Unfortunately I'm still none the wiser why btrfs feels it's necessary to
"open-code"/circumvent the rwsem check. Maybe this gives you a clue.

cheers,
Holger

[1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/fs/fs-writeback.c?id=cf37e972478ec58a8a54a6b4f951815f0ae28f78

[2] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/fs/fs-writeback.c?id=d19de7edf59cdd586777b009e0e8fbe5412dd35f

[3] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/fs/btrfs/extent-tree.c?id=925a6efb8ff0c2bdbec107ed9890e62650c83306

[4] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=dccae99995089641fbac452ebc7f0cab18751ddb

Re: Kernels 4.15..5.5: "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Zygo Blaxell]

[-- Attachment #1: Type: text/plain, Size: 6560 bytes --]

On Tue, Feb 04, 2020 at 02:58:52PM +0100, Holger Hoffstätte wrote:
> On 2/4/20 6:04 AM, Zygo Blaxell wrote:
> > On Fri, Mar 22, 2019 at 12:17:32AM -0400, Zygo Blaxell wrote:
> > > When filesystems are mounted flushoncommit, I get this warning roughly
> > > every 30 seconds:
> > > 
> > > 	[ 4575.142805] WARNING: CPU: 3 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0
> > > 	[ 4575.145567] Modules linked in: crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel dm_cache snd_pcm ghash_clmulni_intel aesni_intel sr_mod dm_persistent_data ppdev joydev dm_bio_prison aes_x86_64 crypto_simd snd_timer dm_bufio cryptd cdrom snd glue_helper dm_mod parport_pc soundcore sg floppy parport pcspkr psmouse bochs_drm rtc_cmos ide_pci_generic piix input_leds i2c_piix4 ide_core serio_raw evbug qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
> > > 	[ 4575.160021] CPU: 3 PID: 4150 Comm: btrfs-transacti Tainted: G        W         5.0.3-zb64+ #1
> > > 	[ 4575.162484] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > > 	[ 4575.164505] RIP: 0010:__writeback_inodes_sb_nr+0xa9/0xc0
> > > 	[ 4575.165809] Code: 0f b6 d2 e8 b9 f8 ff ff 48 89 ee 48 89 df e8 0e f8 ff ff 48 8b 44 24 48 65 48 33 04 25 28 00 00 00 75 0b 48 83 c4 50 5b 5d c3 <0f> 0b eb cb e8 4e e9 d6 ff 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00
> > > 	[ 4575.171927] RSP: 0018:ffffa9cac0eabde8 EFLAGS: 00010246
> > > 	[ 4575.173045] RAX: 0000000000000000 RBX: ffff9353e23af000 RCX: 0000000000000000
> > > 	[ 4575.175639] RDX: 0000000000000002 RSI: 0000000000030c67 RDI: ffffa9cac0eabe30
> > > 	[ 4575.177619] RBP: ffffa9cac0eabdec R08: ffffa9cac0eabdf0 R09: ffff9353f12da000
> > > 	[ 4575.179736] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9353e1980000
> > > 	[ 4575.181661] R13: ffff9353e1981430 R14: ffff9353f27e4260 R15: ffff9353e1981518
> > > 	[ 4575.183871] FS:  0000000000000000(0000) GS:ffff9353f6800000(0000) knlGS:0000000000000000
> > > 	[ 4575.185940] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > 	[ 4575.188072] CR2: 00007fb81841fa20 CR3: 00000002218c0006 CR4: 00000000001606e0
> > > 	[ 4575.190094] Call Trace:
> > > 	[ 4575.190828]  btrfs_commit_transaction+0x7a6/0x9e0
> > > 	[ 4575.192115]  ? start_transaction+0x91/0x4d0
> > > 	[ 4575.193197]  transaction_kthread+0x146/0x180
> > > 	[ 4575.194415]  kthread+0x106/0x140
> > > 	[ 4575.195403]  ? btrfs_cleanup_transaction+0x620/0x620
> > > 	[ 4575.196903]  ? kthread_park+0x90/0x90
> > > 	[ 4575.198412]  ret_from_fork+0x3a/0x50
> > > 	[ 4575.199374] irq event stamp: 54922780
> > > 	[ 4575.200218] hardirqs last  enabled at (54922779): [<ffffffffa3d5f2e2>] _raw_spin_unlock_irqrestore+0x32/0x60
> > > 	[ 4575.202753] hardirqs last disabled at (54922780): [<ffffffffa300379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> > > 	[ 4575.205921] softirqs last  enabled at (54922378): [<ffffffffa40003a4>] __do_softirq+0x3a4/0x45f
> > > 	[ 4575.208350] softirqs last disabled at (54922361): [<ffffffffa30a3d44>] irq_exit+0xe4/0xf0
> > > 	[ 4575.210616] ---[ end trace 5309dcf3a1920eca ]---
> > > 
> > > For my own kernel builds I just comment out the line in fs-writeback.c,
> > > but that's not a real solution.
> > 
> > This still happens in 5.5.0.  No changes in behavior or workaround, no
> > apparent harmful effect, almost 2 years running in stress-testing and
> > production.
> > 
> > I, for one, am glad we fixed all those other bugs before doing anything
> > about this one.  It is utterly harmless.
> 
> This triggered my archeology itch. I had to go deeper.

You could start with this thread:

	https://www.spinics.net/lists/linux-btrfs/msg87752.html

> The warning goes all the way back to 2010 (kernel 2.6.x) when everything
> happened at FusionIO.
> 
> Commit [1] introduced it as preparation for [2].
> 
> The only caller of writeback_inodes_sb_nr is btrfs_writeback_inodes_sb_nr in
> (today's) space-info.c, where the mutex trylock was introduced in [3], apparently
> to work around a VFS function that didn't do it for btrfs at the time.
> 
> Flushoncommit was added by Sage Weil for Ceph's btrfs backend in [4], even
> before the WARN_ON, in 2009. We know how that story ended.
> 
> Why has nobody except you noticed this? Probably because the number of people
> actually using it or reporting bugs is.. very small. ¯\_(ツ)_/¯

I'm not the only one to notice, or report, e.g.

	https://www.spinics.net/lists/linux-btrfs/msg74496.html
	https://www.spinics.net/lists/linux-btrfs/msg72483.html
	https://github.com/Zygo/bees/issues/68

plus it comes up every now and then on IRC.  I have heard from other
users of flushoncommit that they also patch their kernels to get rid of
the WARN_ON (or make it WARN_ON_ONCE).

The WARN_ON appears in btrfs starting in 4.15 after:

	https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=ce8ea7cc6eb3139f4c730d647325e69354159b0f

which rearranges some calls to put the fs-writeback.c WARN_ON on a code
path where it doesn't hold the lock.

To answer a question I asked in

	https://www.spinics.net/lists/linux-btrfs/msg87769.html

(and again in another message of this thread), the answer is
"cherry-picking ce8ea7cc6eb3 into 4.14.107 makes 4.14.107 deadlock
immediately".  Reverting the same commit makes kernel 4.15 and later
deadlock immediately.

btrfs crashes _much_ less often now than it did in 4.14.  Mounting with
noflushoncommit is starting to look like an option worth contemplating
for some workloads on 5.4.18+.  On the other hand, one of the reasons
why I use btrfs instead of other filesystems is that other filesystems
don't implement a sane equivalent of flushoncommit, and those use cases
aren't going away any time soon.

> Unfortunately I'm still none the wiser why btrfs feels it's necessary to
> "open-code"/circumvent the rwsem check. Maybe this gives you a clue.
> 
> cheers,
> Holger
> 
> [1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/fs/fs-writeback.c?id=cf37e972478ec58a8a54a6b4f951815f0ae28f78
> 
> [2] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/fs/fs-writeback.c?id=d19de7edf59cdd586777b009e0e8fbe5412dd35f
> 
> [3] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/fs/btrfs/extent-tree.c?id=925a6efb8ff0c2bdbec107ed9890e62650c83306
> 
> [4] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=dccae99995089641fbac452ebc7f0cab18751ddb

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]

Re: Kernel 5.5.8 : "WARNING: CPU: 2 PID: 4150 at fs/fs-writeback.c:2363 __writeback_inodes_sb_nr+0xa9/0xc0"

[Chris Murphy]

I'm seeing this too, with kernel 5.5.8. It starts almost immediately
after remounting with flushoncommit.

[1098047.402847] fnuc.local kernel: BTRFS info (device sdb2): turning
on flush-on-commit
[1098047.402856] fnuc.local kernel: BTRFS info (device sdb2): disabling tree log
[1098047.402861] fnuc.local kernel: BTRFS info (device sdb2): using
free space tree
[1098053.747527] fnuc.local kernel: BTRFS info (device dm-0): turning
on flush-on-commit
[1098053.747535] fnuc.local kernel: BTRFS info (device dm-0): disabling tree log
[1098053.747538] fnuc.local kernel: BTRFS info (device dm-0): using
free space tree
[1098077.413093] fnuc.local kernel: ------------[ cut here ]------------
[1098077.413131] fnuc.local kernel: WARNING: CPU: 2 PID: 379 at
fs/fs-writeback.c:2466 __writeback_inodes_sb_nr+0xc0/0xd0
[1098077.413136] fnuc.local kernel: Modules linked in: cdc_acm
dm_crypt nf_conntrack_netbios_ns nf_conntrack_broadcast xt_CT
ip6t_REJECT nf_reject_ipv6 ip6t_rpfilter ipt_REJECT nf_reject_ipv4
xt_conntrack ebtable_nat ebtable_broute ip6table_nat ip6table_mangle
ip6table_raw ip6table_security iptable_nat nf_nat iptable_mangle
iptable_raw iptable_security nf_conntrack nf_defrag_ipv6
nf_defrag_ipv4 ip_set nfnetlink ebtable_filter ebtables
ip6table_filter ip6_tables iptable_filter cmac bnep sunrpc
snd_hda_codec_hdmi intel_rapl_msr snd_hda_codec_realtek
snd_hda_codec_generic ledtrig_audio mei_hdcp snd_hda_intel
intel_rapl_common snd_intel_dspcfg intel_powerclamp iTCO_wdt coretemp
iTCO_vendor_support snd_hda_codec kvm_intel iwlmvm mac80211 kvm
snd_hda_core libarc4 btusb irqbypass snd_hwdep snd_seq
crct10dif_pclmul iwlwifi btrtl crc32_pclmul btbcm snd_seq_device
btintel snd_pcm ghash_clmulni_intel bluetooth intel_cstate cfg80211
snd_timer snd ecdh_generic ecc soundcore r8169 mei_txe
intel_xhci_usb_role_switch mei rfkill
[1098077.413395] fnuc.local kernel:  roles i2c_i801 lpc_ich dw_dmac
intel_int0002_vgpio vfat fat binfmt_misc zram ip_tables btrfs
blake2b_generic libcrc32c xor zstd_decompress zstd_compress raid6_pq
i915 i2c_algo_bit crc32c_intel drm_kms_helper drm uas usb_storage
sdhci_acpi sdhci video mmc_core pwm_lpss_platform pwm_lpss fuse
[1098077.413515] fnuc.local kernel: CPU: 2 PID: 379 Comm:
btrfs-transacti Not tainted 5.5.8-200.fc31.x86_64 #1
[1098077.413522] fnuc.local kernel: Hardware name:  /NUC5PPYB, BIOS
PYBSWCEL.86A.0078.2019.0807.1133 08/07/2019
[1098077.413539] fnuc.local kernel: RIP: 0010:__writeback_inodes_sb_nr+0xc0/0xd0
[1098077.413553] fnuc.local kernel: Code: 0f b6 d1 48 8d 74 24 10 e8
6d fc ff ff 48 89 e7 e8 e5 fb ff ff 48 8b 44 24 50 65 48 33 04 25 28
00 00 00 75 09 48 83 c4 58 c3 <0f> 0b eb cf e8 b7 38 d9 ff 0f 1f 80 00
00 00 00 0f 1f 44 00 00 31
[1098077.413561] fnuc.local kernel: RSP: 0018:ffffabed404a7df0 EFLAGS: 00010246
[1098077.413572] fnuc.local kernel: RAX: 0000000000000000 RBX:
ffff8cc172cfc960 RCX: 0000000000000000
[1098077.413578] fnuc.local kernel: RDX: 0000000000000002 RSI:
0000000000001d2a RDI: ffff8cc17abf5000
[1098077.413585] fnuc.local kernel: RBP: ffff8cc176b84e38 R08:
ffff8cc17666e800 R09: ffffabed404a7de8
[1098077.413592] fnuc.local kernel: R10: ffff8cc048cd3758 R11:
000000000003c000 R12: ffff8cc172cf0000
[1098077.413599] fnuc.local kernel: R13: ffff8cc13dc2a000 R14:
ffff8cc172cfc938 R15: ffff8cc13dc2a000
[1098077.413608] fnuc.local kernel: FS:  0000000000000000(0000)
GS:ffff8cc17bd00000(0000) knlGS:0000000000000000
[1098077.413614] fnuc.local kernel: CS:  0010 DS: 0000 ES: 0000 CR0:
0000000080050033
[1098077.413621] fnuc.local kernel: CR2: 0000555defae5e90 CR3:
000000014b60a000 CR4: 00000000001006e0
[1098077.413626] fnuc.local kernel: Call Trace:
[1098077.413820] fnuc.local kernel:
btrfs_commit_transaction+0x303/0xa20 [btrfs]
[1098077.413977] fnuc.local kernel:  ? start_transaction+0xbb/0x4c0 [btrfs]
[1098077.414124] fnuc.local kernel:  transaction_kthread+0x13c/0x180 [btrfs]
[1098077.414146] fnuc.local kernel:  kthread+0xf9/0x130
[1098077.414292] fnuc.local kernel:  ?
btrfs_cleanup_transaction+0x5c0/0x5c0 [btrfs]
[1098077.414306] fnuc.local kernel:  ? kthread_park+0x90/0x90
[1098077.414323] fnuc.local kernel:  ret_from_fork+0x35/0x40
[1098077.414340] fnuc.local kernel: ---[ end trace a3fc4c6144f1f7ae ]---
[1098107.620280] fnuc.local kernel: ------------[ cut here ]------------

--
Chris Murphy