* WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3)
@ 2019-03-26 2:50 Zygo Blaxell
2019-03-26 4:30 ` Zygo Blaxell
2019-04-29 22:34 ` WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (still on 5.0.10) Zygo Blaxell
0 siblings, 2 replies; 10+ messages in thread
From: Zygo Blaxell @ 2019-03-26 2:50 UTC (permalink / raw)
To: linux-btrfs
Running balance, rsync, and dedupe, I get kernel warnings every few
minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
Mount options are: flushoncommit,space_cache=v2,compress=zstd.
There are two different stacks on the warnings. This one comes from
btrfs balance:
[Mon Mar 25 18:22:42 2019] WARNING: CPU: 0 PID: 4786 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
[Mon Mar 25 18:22:42 2019] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
[Mon Mar 25 18:22:42 2019] CPU: 0 PID: 4786 Comm: btrfs-balance Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
[Mon Mar 25 18:22:42 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[Mon Mar 25 18:22:42 2019] RIP: 0010:btrfs_merge_delayed_refs+0x3dc/0x410
[Mon Mar 25 18:22:42 2019] Code: 7c 24 28 be ff ff ff ff e8 31 a0 c1 ff 85 c0 0f 85 7c fe ff ff 0f 0b e9 75 fe ff ff 0f 0b e9 0a fe ff ff 0f 0b e9 1b fe ff ff <0f> 0b e9 25 ff ff ff 0f 0b e9 b0 fe ff ff 48 c7 44 24 10 00 00 00
[Mon Mar 25 18:22:42 2019] RSP: 0018:ffffabb981377b70 EFLAGS: 00010246
[Mon Mar 25 18:22:42 2019] RAX: 00000000000000b6 RBX: 00000000ffffffff RCX: 0000000000000001
[Mon Mar 25 18:22:42 2019] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000282
[Mon Mar 25 18:22:42 2019] RBP: ffff9392514bbb80 R08: ffff9392514bbc80 R09: 0000000000000000
[Mon Mar 25 18:22:42 2019] R10: 0000000000000000 R11: 0000000000000001 R12: ffff93928a5c8f08
[Mon Mar 25 18:22:42 2019] R13: ffff939269744e38 R14: ffff939269744e38 R15: ffff9392697449c0
[Mon Mar 25 18:22:42 2019] FS: 0000000000000000(0000) GS:ffff939475c00000(0000) knlGS:0000000000000000
[Mon Mar 25 18:22:42 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[Mon Mar 25 18:22:42 2019] CR2: 00007f0882d38600 CR3: 0000000230eb6002 CR4: 00000000001606f0
[Mon Mar 25 18:22:42 2019] Call Trace:
[Mon Mar 25 18:22:42 2019] __btrfs_run_delayed_refs+0x70/0x170
[Mon Mar 25 18:22:42 2019] btrfs_run_delayed_refs+0x7d/0x1d0
[Mon Mar 25 18:22:42 2019] btrfs_commit_transaction+0x50/0x9e0
[Mon Mar 25 18:22:42 2019] ? start_transaction+0x91/0x4d0
[Mon Mar 25 18:22:42 2019] relocate_block_group+0x1bd/0x600
[Mon Mar 25 18:22:42 2019] btrfs_relocate_block_group+0x15b/0x260
[Mon Mar 25 18:22:42 2019] btrfs_relocate_chunk+0x46/0xf0
[Mon Mar 25 18:22:42 2019] btrfs_balance+0xa60/0x12b0
[Mon Mar 25 18:22:42 2019] balance_kthread+0x36/0x50
[Mon Mar 25 18:22:42 2019] kthread+0x106/0x140
[Mon Mar 25 18:22:42 2019] ? btrfs_balance+0x12b0/0x12b0
[Mon Mar 25 18:22:42 2019] ? kthread_park+0x90/0x90
[Mon Mar 25 18:22:42 2019] ret_from_fork+0x3a/0x50
[Mon Mar 25 18:22:42 2019] irq event stamp: 81529004
[Mon Mar 25 18:22:42 2019] hardirqs last enabled at (81529003): [<ffffffffaa2be2b7>] kmem_cache_free+0x67/0x1e0
[Mon Mar 25 18:22:42 2019] hardirqs last disabled at (81529004): [<ffffffffaa00379f>] trace_hardirqs_off_thunk+0x1a/0x1c
[Mon Mar 25 18:22:42 2019] softirqs last enabled at (81527500): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
[Mon Mar 25 18:22:42 2019] softirqs last disabled at (81527493): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
[Mon Mar 25 18:22:42 2019] ---[ end trace 3d8cdfff7444099a ]---
This one comes from btrfs-transaction:
[Mon Mar 25 18:27:58 2019] WARNING: CPU: 3 PID: 4137 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
[Mon Mar 25 18:27:58 2019] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
[Mon Mar 25 18:27:58 2019] CPU: 3 PID: 4137 Comm: btrfs-transacti Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
[Mon Mar 25 18:27:58 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[Mon Mar 25 18:27:58 2019] RIP: 0010:btrfs_merge_delayed_refs+0x3dc/0x410
[Mon Mar 25 18:27:58 2019] Code: 7c 24 28 be ff ff ff ff e8 31 a0 c1 ff 85 c0 0f 85 7c fe ff ff 0f 0b e9 75 fe ff ff 0f 0b e9 0a fe ff ff 0f 0b e9 1b fe ff ff <0f> 0b e9 25 ff ff ff 0f 0b e9 b0 fe ff ff 48 c7 44 24 10 00 00 00
[Mon Mar 25 18:27:58 2019] RSP: 0018:ffffabb9812f7d40 EFLAGS: 00010246
[Mon Mar 25 18:27:58 2019] RAX: 00000000000000b6 RBX: 00000000ffffffff RCX: 0000000000000001
[Mon Mar 25 18:27:58 2019] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000286
[Mon Mar 25 18:27:58 2019] RBP: ffff93925b187ce0 R08: ffff93925b187de0 R09: 0000000000000000
[Mon Mar 25 18:27:58 2019] R10: 0000000000000000 R11: 0000000000000001 R12: ffff93938b59d308
[Mon Mar 25 18:27:58 2019] R13: ffff9393a5d09820 R14: ffff9393a5d09820 R15: ffff939261978820
[Mon Mar 25 18:27:58 2019] FS: 0000000000000000(0000) GS:ffff939476800000(0000) knlGS:0000000000000000
[Mon Mar 25 18:27:58 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[Mon Mar 25 18:27:58 2019] CR2: 00007f91f6321c50 CR3: 00000001ef54e003 CR4: 00000000001606e0
[Mon Mar 25 18:27:58 2019] Call Trace:
[Mon Mar 25 18:27:58 2019] __btrfs_run_delayed_refs+0x70/0x170
[Mon Mar 25 18:27:58 2019] btrfs_run_delayed_refs+0x7d/0x1d0
[Mon Mar 25 18:27:58 2019] btrfs_commit_transaction+0x50/0x9e0
[Mon Mar 25 18:27:58 2019] ? start_transaction+0x91/0x4d0
[Mon Mar 25 18:27:58 2019] transaction_kthread+0x146/0x180
[Mon Mar 25 18:27:58 2019] kthread+0x106/0x140
[Mon Mar 25 18:27:58 2019] ? btrfs_cleanup_transaction+0x620/0x620
[Mon Mar 25 18:27:58 2019] ? kthread_park+0x90/0x90
[Mon Mar 25 18:27:58 2019] ret_from_fork+0x3a/0x50
[Mon Mar 25 18:27:58 2019] irq event stamp: 81665152
[Mon Mar 25 18:27:58 2019] hardirqs last enabled at (81665151): [<ffffffffaa2be2b7>] kmem_cache_free+0x67/0x1e0
[Mon Mar 25 18:27:58 2019] hardirqs last disabled at (81665152): [<ffffffffaa00379f>] trace_hardirqs_off_thunk+0x1a/0x1c
[Mon Mar 25 18:27:58 2019] softirqs last enabled at (81664580): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
[Mon Mar 25 18:27:58 2019] softirqs last disabled at (81664565): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
[Mon Mar 25 18:27:58 2019] ---[ end trace 3d8cdfff7444099c ]---
Sometimes they both happen at the same time, and the stack trace is a
confusing jumble! I didn't know Linux kernel stack traces could do this:
Mar 25 14:46:52 [24240.160913] WARNING: CPU: 3 PID: 4214 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
Mar 25 14:46:52 [24240.161158] WARNING: CPU: 0 PID: 4254 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
Mar 25 14:46:52 [24240.167509] Modules linked in: bochs_drm dm_cache_smq joydev dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod ppdev crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel aes_x86_64 crypto_simd cryptd glue_helper sr_mod cdrom sg ide_pci_generic piix i2c_piix4 ide_core input_leds psmouse rtc_cmos floppy pcc_cpufreq snd_pcm serio_raw parport_pc parport evbug evdev snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
Mar 25 14:46:52 [24240.169564] Modules linked in: bochs_drm dm_cache_smq joydev dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod ppdev crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel aes_x86_64 crypto_simd cryptd glue_helper sr_mod cdrom sg ide_pci_generic piix i2c_piix4 ide_core input_leds psmouse rtc_cmos floppy pcc_cpufreq snd_pcm serio_raw parport_pc parport evbug evdev snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
Mar 25 14:46:52 [24240.179818] CPU: 3 PID: 4214 Comm: btrfs-transacti Tainted: G W 5.0.4-zb64-2b44cea8b720+ #1
Mar 25 14:46:52 [24240.179820] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
Mar 25 14:46:52 [24240.188662] CPU: 0 PID: 4254 Comm: btrfs-balance Tainted: G W 5.0.4-zb64-2b44cea8b720+ #1
Mar 25 14:46:52 [24240.190711] RIP: 0010:btrfs_merge_delayed_refs+0x3dc/0x410
Mar 25 14:46:52 [24240.192571] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
Mar 25 14:46:52 [24240.192576] RIP: 0010:btrfs_merge_delayed_refs+0x3dc/0x410
Mar 25 14:46:52 [24240.194563] Code: 7c 24 28 be ff ff ff ff e8 31 a0 c1 ff 85 c0 0f 85 7c fe ff ff 0f 0b e9 75 fe ff ff 0f 0b e9 0a fe ff ff 0f 0b e9 1b fe ff ff <0f> 0b e9 25 ff ff ff 0f 0b e9 b0 fe ff ff 48 c7 44 24 10 00 00 00
Mar 25 14:46:52 [24240.195747] Code: 7c 24 28 be ff ff ff ff e8 31 a0 c1 ff 85 c0 0f 85 7c fe ff ff 0f 0b e9 75 fe ff ff 0f 0b e9 0a fe ff ff 0f 0b e9 1b fe ff ff <0f> 0b e9 25 ff ff ff 0f 0b e9 b0 fe ff ff 48 c7 44 24 10 00 00 00
Mar 25 14:46:52 [24240.195749] RSP: 0000:ffffb1ad0121bb70 EFLAGS: 00010246
Mar 25 14:46:52 [24240.197511] RSP: 0000:ffffb1ad0122bd40 EFLAGS: 00010246
Mar 25 14:46:52 [24240.198686] RAX: 00000000000000b6 RBX: 00000000ffffffff RCX: 0000000000000001
Mar 25 14:46:52 [24240.198689] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000282
Mar 25 14:46:52 [24240.202841] RAX: 00000000000000b6 RBX: 00000000ffffffff RCX: 0000000000000001
Mar 25 14:46:52 [24240.206920] RBP: ffff9a015e0b6460 R08: ffff9a015e0b6560 R09: 0000000000000000
Mar 25 14:46:52 [24240.206922] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9a01967a2308
Mar 25 14:46:52 [24240.208040] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000286
Mar 25 14:46:52 [24240.209158] R13: ffff9a0025aab208 R14: ffff9a0025aab208 R15: ffff99ffc8d8b7b8
Mar 25 14:46:52 [24240.209160] FS: 0000000000000000(0000) GS:ffff9a01f5c00000(0000) knlGS:0000000000000000
Mar 25 14:46:52 [24240.210671] RBP: ffff9a00f01841e0 R08: ffff9a00f01842e0 R09: 0000000000000000
Mar 25 14:46:52 [24240.212191] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 25 14:46:52 [24240.212193] CR2: 000055c2d6202280 CR3: 0000000185eae001 CR4: 00000000001606f0
Mar 25 14:46:52 [24240.213833] R10: 0000000000000000 R11: 0000000000000001 R12: ffff9a01967a2308
Mar 25 14:46:52 [24240.215309] Call Trace:
Mar 25 14:46:52 [24240.216762] R13: ffff99ffe4f9f208 R14: ffff99ffe4f9f208 R15: ffff9a01ea9441a0
Mar 25 14:46:52 [24240.216764] FS: 0000000000000000(0000) GS:ffff9a01f6800000(0000) knlGS:0000000000000000
Mar 25 14:46:52 [24240.218283] __btrfs_run_delayed_refs+0x70/0x170
Mar 25 14:46:52 [24240.219755] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 25 14:46:52 [24240.219757] CR2: 000055e5c552f988 CR3: 00000001fcb3a002 CR4: 00000000001606e0
Mar 25 14:46:52 [24240.221535] btrfs_run_delayed_refs+0x7d/0x1d0
Mar 25 14:46:52 [24240.223014] Call Trace:
Mar 25 14:46:52 [24240.224251] btrfs_commit_transaction+0x50/0x9e0
Mar 25 14:46:52 [24240.225887] __btrfs_run_delayed_refs+0x70/0x170
Mar 25 14:46:52 [24240.227403] ? start_transaction+0x91/0x4d0
Mar 25 14:46:52 [24240.227921] btrfs_run_delayed_refs+0x7d/0x1d0
Mar 25 14:46:52 [24240.229688] relocate_block_group+0x1bd/0x600
Mar 25 14:46:52 [24240.229702] btrfs_relocate_block_group+0x15b/0x260
Mar 25 14:46:52 [24240.229710] btrfs_relocate_chunk+0x46/0xf0
Mar 25 14:46:52 [24240.229716] btrfs_balance+0xa60/0x12b0
Mar 25 14:46:52 [24240.231375] btrfs_commit_transaction+0x50/0x9e0
Mar 25 14:46:52 [24240.232353] balance_kthread+0x36/0x50
Mar 25 14:46:52 [24240.233507] ? start_transaction+0x91/0x4d0
Mar 25 14:46:52 [24240.235001] kthread+0x106/0x140
Mar 25 14:46:52 [24240.235953] transaction_kthread+0x146/0x180
Mar 25 14:46:52 [24240.236485] ? btrfs_balance+0x12b0/0x12b0
Mar 25 14:46:52 [24240.237497] kthread+0x106/0x140
Mar 25 14:46:52 [24240.238526] ? kthread_park+0x90/0x90
Mar 25 14:46:52 [24240.239455] ? btrfs_cleanup_transaction+0x620/0x620
Mar 25 14:46:52 [24240.240455] ret_from_fork+0x3a/0x50
Mar 25 14:46:52 [24240.241413] ? kthread_park+0x90/0x90
Mar 25 14:46:52 [24240.242511] irq event stamp: 2299215120
Mar 25 14:46:52 [24240.243436] ret_from_fork+0x3a/0x50
Mar 25 14:46:52 [24240.244286] hardirqs last enabled at (2299215119): [<ffffffffbc2be2b7>] kmem_cache_free+0x67/0x1e0
Mar 25 14:46:52 [24240.244291] hardirqs last disabled at (2299215120): [<ffffffffbc00379f>] trace_hardirqs_off_thunk+0x1a/0x1c
Mar 25 14:46:52 [24240.245320] irq event stamp: 1574357192
Mar 25 14:46:52 [24240.246152] softirqs last enabled at (2299214848): [<ffffffffbd0003a4>] __do_softirq+0x3a4/0x45f
Mar 25 14:46:52 [24240.246157] softirqs last disabled at (2299214665): [<ffffffffbc0a3d24>] irq_exit+0xe4/0xf0
Mar 25 14:46:52 [24240.247088] hardirqs last enabled at (1574357191): [<ffffffffbc2be2b7>] kmem_cache_free+0x67/0x1e0
Mar 25 14:46:52 [24240.247091] hardirqs last disabled at (1574357192): [<ffffffffbc00379f>] trace_hardirqs_off_thunk+0x1a/0x1c
Mar 25 14:46:52 [24240.247806] ---[ end trace c0ec186e7aead1da ]---
Mar 25 14:46:52 [24240.248719] softirqs last enabled at (1574357050): [<ffffffffbd0003a4>] __do_softirq+0x3a4/0x45f
Mar 25 14:46:52 [24240.248723] softirqs last disabled at (1574356895): [<ffffffffbc0a3d24>] irq_exit+0xe4/0xf0
Mar 25 14:46:52 [24240.249728] WARNING: CPU: 0 PID: 4254 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
Mar 25 14:46:52 [24240.250325] ---[ end trace c0ec186e7aead1db ]---
Pausing the balance makes the warnings stop.
Mounting with noflushoncommit looks like it might also stop the warnings,
but I haven't let it run long enough to be sure.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3)
2019-03-26 2:50 WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3) Zygo Blaxell
@ 2019-03-26 4:30 ` Zygo Blaxell
2019-03-26 8:42 ` Nikolay Borisov
` (2 more replies)
2019-04-29 22:34 ` WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (still on 5.0.10) Zygo Blaxell
1 sibling, 3 replies; 10+ messages in thread
From: Zygo Blaxell @ 2019-03-26 4:30 UTC (permalink / raw)
To: linux-btrfs
On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
> Running balance, rsync, and dedupe, I get kernel warnings every few
> minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
>
> Mount options are: flushoncommit,space_cache=v2,compress=zstd.
>
> There are two different stacks on the warnings. This one comes from
> btrfs balance:
[snip]
Possibly unrelated, but I'm also repeatably getting this in 5.0.4 and
not 5.0.3, after about 5 hours of uptime. Different processes, same
kernel stack:
[Mon Mar 25 23:35:17 2019] kworker/u8:4: page allocation failure: order:0, mode:0x404000(GFP_NOWAIT|__GFP_COMP), nodemask=(null),cpuset=/,mems_allowed=0
[Mon Mar 25 23:35:17 2019] CPU: 2 PID: 29518 Comm: kworker/u8:4 Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
[Mon Mar 25 23:35:17 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[Mon Mar 25 23:35:17 2019] Workqueue: btrfs-submit btrfs_submit_helper
[Mon Mar 25 23:35:17 2019] Call Trace:
[Mon Mar 25 23:35:17 2019] dump_stack+0x7d/0xbb
[Mon Mar 25 23:35:17 2019] warn_alloc+0x108/0x190
[Mon Mar 25 23:35:17 2019] __alloc_pages_nodemask+0x12c4/0x13f0
[Mon Mar 25 23:35:17 2019] ? rcu_read_lock_sched_held+0x68/0x70
[Mon Mar 25 23:35:17 2019] ? __update_load_avg_se+0x208/0x280
[Mon Mar 25 23:35:17 2019] cache_grow_begin+0x79/0x730
[Mon Mar 25 23:35:17 2019] ? cache_grow_begin+0x79/0x730
[Mon Mar 25 23:35:17 2019] ? ____cache_alloc_node+0x165/0x1e0
[Mon Mar 25 23:35:17 2019] fallback_alloc+0x1e4/0x280
[Mon Mar 25 23:35:17 2019] kmem_cache_alloc+0x2e9/0x310
[Mon Mar 25 23:35:17 2019] btracker_queue+0x47/0x170 [dm_cache]
[Mon Mar 25 23:35:17 2019] __lookup+0x51a/0x600 [dm_cache_smq]
[Mon Mar 25 23:35:17 2019] ? smq_lookup+0x37/0x7b [dm_cache_smq]
[Mon Mar 25 23:35:17 2019] smq_lookup+0x5d/0x7b [dm_cache_smq]
[Mon Mar 25 23:35:18 2019] map_bio.part.40+0x14d/0x5d0 [dm_cache]
[Mon Mar 25 23:35:18 2019] ? bio_detain_shared+0xb3/0x120 [dm_cache]
[Mon Mar 25 23:35:18 2019] cache_map+0x120/0x170 [dm_cache]
[Mon Mar 25 23:35:18 2019] __map_bio+0x42/0x1f0 [dm_mod]
[Mon Mar 25 23:35:18 2019] __split_and_process_non_flush+0x152/0x1e0 [dm_mod]
[Mon Mar 25 23:35:18 2019] __split_and_process_bio+0xd4/0x400 [dm_mod]
[Mon Mar 25 23:35:18 2019] ? lock_acquire+0xbc/0x1c0
[Mon Mar 25 23:35:18 2019] ? dm_get_live_table+0x5/0xc0 [dm_mod]
[Mon Mar 25 23:35:18 2019] dm_make_request+0x4d/0x100 [dm_mod]
[Mon Mar 25 23:35:18 2019] generic_make_request+0x297/0x470
[Mon Mar 25 23:35:18 2019] ? kvm_sched_clock_read+0x14/0x30
[Mon Mar 25 23:35:18 2019] ? submit_bio+0x6c/0x140
[Mon Mar 25 23:35:18 2019] submit_bio+0x6c/0x140
[Mon Mar 25 23:35:18 2019] run_scheduled_bios+0x1e6/0x500
[Mon Mar 25 23:35:18 2019] ? normal_work_helper+0x95/0x530
[Mon Mar 25 23:35:18 2019] normal_work_helper+0x95/0x530
[Mon Mar 25 23:35:18 2019] process_one_work+0x223/0x5d0
[Mon Mar 25 23:35:18 2019] worker_thread+0x4f/0x3b0
[Mon Mar 25 23:35:18 2019] kthread+0x106/0x140
[Mon Mar 25 23:35:18 2019] ? process_one_work+0x5d0/0x5d0
[Mon Mar 25 23:35:18 2019] ? kthread_park+0x90/0x90
[Mon Mar 25 23:35:18 2019] ret_from_fork+0x3a/0x50
[Mon Mar 25 23:35:18 2019] Mem-Info:
[Mon Mar 25 23:35:18 2019] active_anon:195872 inactive_anon:15658 isolated_anon:0
active_file:629653 inactive_file:308914 isolated_file:0
unevictable:65536 dirty:14449 writeback:27580 unstable:0
slab_reclaimable:492522 slab_unreclaimable:94393
mapped:10915 shmem:18846 pagetables:2178 bounce:0
free:66082 free_pcp:1963 free_cma:24
[Mon Mar 25 23:35:18 2019] Node 0 active_anon:783488kB inactive_anon:62632kB active_file:2516656kB inactive_file:1235604kB unevictable:262144kB isolated(anon):0kB isolated(file):0kB mapped:43660kB dirty:57796kB writeback:110320kB shmem:75384kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 137216kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[Mon Mar 25 23:35:18 2019] Node 0 DMA free:15844kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 2939 7906 7906 7906
[Mon Mar 25 23:35:18 2019] Node 0 DMA32 free:116632kB min:81336kB low:87592kB high:93848kB active_anon:330436kB inactive_anon:31840kB active_file:531512kB inactive_file:491372kB unevictable:108544kB writepending:121984kB present:3129176kB managed:3019336kB mlocked:108544kB kernel_stack:2704kB pagetables:2944kB bounce:0kB free_pcp:3800kB local_pcp:256kB free_cma:0kB
[Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 0 4966 4966 4966
[Mon Mar 25 23:35:18 2019] Node 0 Normal free:141932kB min:42420kB low:53024kB high:63628kB active_anon:453224kB inactive_anon:30792kB active_file:1984568kB inactive_file:737244kB unevictable:153600kB writepending:46544kB present:5242880kB managed:5102032kB mlocked:153600kB kernel_stack:7020kB pagetables:5768kB bounce:0kB free_pcp:4188kB local_pcp:1700kB free_cma:96kB
[Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 0 0 0 0
[Mon Mar 25 23:35:18 2019] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 1*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15844kB
[Mon Mar 25 23:35:18 2019] Node 0 DMA32: 12698*4kB (UME) 6110*8kB (UME) 1087*16kB (UME) 4*32kB (M) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 117192kB
[Mon Mar 25 23:35:18 2019] Node 0 Normal: 13507*4kB (UMEHC) 8008*8kB (UMEHC) 1374*16kB (UMEH) 3*32kB (H) 4*64kB (H) 4*128kB (H) 2*256kB (H) 1*512kB (H) 0*1024kB 0*2048kB 0*4096kB = 141964kB
[Mon Mar 25 23:35:18 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[Mon Mar 25 23:35:18 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Mon Mar 25 23:35:18 2019] 955001 total pagecache pages
[Mon Mar 25 23:35:18 2019] 0 pages in swap cache
[Mon Mar 25 23:35:18 2019] Swap cache stats: add 0, delete 0, find 0/0
[Mon Mar 25 23:35:18 2019] Free swap = 0kB
[Mon Mar 25 23:35:18 2019] Total swap = 0kB
[Mon Mar 25 23:35:18 2019] 2097012 pages RAM
[Mon Mar 25 23:35:18 2019] 0 pages HighMem/MovableOnly
[Mon Mar 25 23:35:18 2019] 62693 pages reserved
[Mon Mar 25 23:35:18 2019] 4096 pages cma reserved
[Mon Mar 25 23:35:18 2019] 0 pages hwpoisoned
As far as I can tell from logs of memory usage (recording memcg and
MemAvail stats every second), there are gigabytes of available (clean
page cache) RAM at all times during these tests.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3)
2019-03-26 4:30 ` Zygo Blaxell
@ 2019-03-26 8:42 ` Nikolay Borisov
2019-03-26 15:09 ` Zygo Blaxell
2019-03-26 15:30 ` BUG: workqueue lockup - pool cpus=0-3 flags=0x4 nice=0 stuck for 20915s! (on 4.20+) Zygo Blaxell
2019-05-15 20:27 ` btrfs + KASAN + SLAB + lvmcache + rsync + kernel 5.0 = page allocation failure and/or OOM kills (solved...ish) Zygo Blaxell
2 siblings, 1 reply; 10+ messages in thread
From: Nikolay Borisov @ 2019-03-26 8:42 UTC (permalink / raw)
To: Zygo Blaxell, linux-btrfs
On 26.03.19 г. 6:30 ч., Zygo Blaxell wrote:
> On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
>> Running balance, rsync, and dedupe, I get kernel warnings every few
>> minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
>>
>> Mount options are: flushoncommit,space_cache=v2,compress=zstd.
>>
>> There are two different stacks on the warnings. This one comes from
>> btrfs balance:
>
> [snip]
>
> Possibly unrelated, but I'm also repeatably getting this in 5.0.4 and
> not 5.0.3, after about 5 hours of uptime. Different processes, same
> kernel stack:
>
> [Mon Mar 25 23:35:17 2019] kworker/u8:4: page allocation failure: order:0, mode:0x404000(GFP_NOWAIT|__GFP_COMP), nodemask=(null),cpuset=/,mems_allowed=0
> [Mon Mar 25 23:35:17 2019] CPU: 2 PID: 29518 Comm: kworker/u8:4 Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
What commits does this kernel include because it doesn't seem to be a
pristine upstream 5.0.4 ? Also what you are seeing below is definitely a
bug in MM. The question is whether it's due to your doing faulty
backports in the kernel or it's due to something that got automatically
backported to 5.0.4
> [Mon Mar 25 23:35:17 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> [Mon Mar 25 23:35:17 2019] Workqueue: btrfs-submit btrfs_submit_helper
> [Mon Mar 25 23:35:17 2019] Call Trace:
> [Mon Mar 25 23:35:17 2019] dump_stack+0x7d/0xbb
> [Mon Mar 25 23:35:17 2019] warn_alloc+0x108/0x190
> [Mon Mar 25 23:35:17 2019] __alloc_pages_nodemask+0x12c4/0x13f0
> [Mon Mar 25 23:35:17 2019] ? rcu_read_lock_sched_held+0x68/0x70
> [Mon Mar 25 23:35:17 2019] ? __update_load_avg_se+0x208/0x280
> [Mon Mar 25 23:35:17 2019] cache_grow_begin+0x79/0x730
> [Mon Mar 25 23:35:17 2019] ? cache_grow_begin+0x79/0x730
> [Mon Mar 25 23:35:17 2019] ? ____cache_alloc_node+0x165/0x1e0
> [Mon Mar 25 23:35:17 2019] fallback_alloc+0x1e4/0x280
> [Mon Mar 25 23:35:17 2019] kmem_cache_alloc+0x2e9/0x310
> [Mon Mar 25 23:35:17 2019] btracker_queue+0x47/0x170 [dm_cache]
> [Mon Mar 25 23:35:17 2019] __lookup+0x51a/0x600 [dm_cache_smq]
> [Mon Mar 25 23:35:17 2019] ? smq_lookup+0x37/0x7b [dm_cache_smq]
> [Mon Mar 25 23:35:17 2019] smq_lookup+0x5d/0x7b [dm_cache_smq]
> [Mon Mar 25 23:35:18 2019] map_bio.part.40+0x14d/0x5d0 [dm_cache]
> [Mon Mar 25 23:35:18 2019] ? bio_detain_shared+0xb3/0x120 [dm_cache]
> [Mon Mar 25 23:35:18 2019] cache_map+0x120/0x170 [dm_cache]
> [Mon Mar 25 23:35:18 2019] __map_bio+0x42/0x1f0 [dm_mod]
> [Mon Mar 25 23:35:18 2019] __split_and_process_non_flush+0x152/0x1e0 [dm_mod]
> [Mon Mar 25 23:35:18 2019] __split_and_process_bio+0xd4/0x400 [dm_mod]
> [Mon Mar 25 23:35:18 2019] ? lock_acquire+0xbc/0x1c0
> [Mon Mar 25 23:35:18 2019] ? dm_get_live_table+0x5/0xc0 [dm_mod]
> [Mon Mar 25 23:35:18 2019] dm_make_request+0x4d/0x100 [dm_mod]
> [Mon Mar 25 23:35:18 2019] generic_make_request+0x297/0x470
> [Mon Mar 25 23:35:18 2019] ? kvm_sched_clock_read+0x14/0x30
> [Mon Mar 25 23:35:18 2019] ? submit_bio+0x6c/0x140
> [Mon Mar 25 23:35:18 2019] submit_bio+0x6c/0x140
> [Mon Mar 25 23:35:18 2019] run_scheduled_bios+0x1e6/0x500
> [Mon Mar 25 23:35:18 2019] ? normal_work_helper+0x95/0x530
> [Mon Mar 25 23:35:18 2019] normal_work_helper+0x95/0x530
> [Mon Mar 25 23:35:18 2019] process_one_work+0x223/0x5d0
> [Mon Mar 25 23:35:18 2019] worker_thread+0x4f/0x3b0
> [Mon Mar 25 23:35:18 2019] kthread+0x106/0x140
> [Mon Mar 25 23:35:18 2019] ? process_one_work+0x5d0/0x5d0
> [Mon Mar 25 23:35:18 2019] ? kthread_park+0x90/0x90
> [Mon Mar 25 23:35:18 2019] ret_from_fork+0x3a/0x50
> [Mon Mar 25 23:35:18 2019] Mem-Info:
> [Mon Mar 25 23:35:18 2019] active_anon:195872 inactive_anon:15658 isolated_anon:0
> active_file:629653 inactive_file:308914 isolated_file:0
> unevictable:65536 dirty:14449 writeback:27580 unstable:0
> slab_reclaimable:492522 slab_unreclaimable:94393
> mapped:10915 shmem:18846 pagetables:2178 bounce:0
> free:66082 free_pcp:1963 free_cma:24
> [Mon Mar 25 23:35:18 2019] Node 0 active_anon:783488kB inactive_anon:62632kB active_file:2516656kB inactive_file:1235604kB unevictable:262144kB isolated(anon):0kB isolated(file):0kB mapped:43660kB dirty:57796kB writeback:110320kB shmem:75384kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 137216kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
> [Mon Mar 25 23:35:18 2019] Node 0 DMA free:15844kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
> [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 2939 7906 7906 7906
> [Mon Mar 25 23:35:18 2019] Node 0 DMA32 free:116632kB min:81336kB low:87592kB high:93848kB active_anon:330436kB inactive_anon:31840kB active_file:531512kB inactive_file:491372kB unevictable:108544kB writepending:121984kB present:3129176kB managed:3019336kB mlocked:108544kB kernel_stack:2704kB pagetables:2944kB bounce:0kB free_pcp:3800kB local_pcp:256kB free_cma:0kB
> [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 0 4966 4966 4966
> [Mon Mar 25 23:35:18 2019] Node 0 Normal free:141932kB min:42420kB low:53024kB high:63628kB active_anon:453224kB inactive_anon:30792kB active_file:1984568kB inactive_file:737244kB unevictable:153600kB writepending:46544kB present:5242880kB managed:5102032kB mlocked:153600kB kernel_stack:7020kB pagetables:5768kB bounce:0kB free_pcp:4188kB local_pcp:1700kB free_cma:96kB
> [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 0 0 0 0
> [Mon Mar 25 23:35:18 2019] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 1*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15844kB
> [Mon Mar 25 23:35:18 2019] Node 0 DMA32: 12698*4kB (UME) 6110*8kB (UME) 1087*16kB (UME) 4*32kB (M) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 117192kB
> [Mon Mar 25 23:35:18 2019] Node 0 Normal: 13507*4kB (UMEHC) 8008*8kB (UMEHC) 1374*16kB (UMEH) 3*32kB (H) 4*64kB (H) 4*128kB (H) 2*256kB (H) 1*512kB (H) 0*1024kB 0*2048kB 0*4096kB = 141964kB
> [Mon Mar 25 23:35:18 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
> [Mon Mar 25 23:35:18 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
> [Mon Mar 25 23:35:18 2019] 955001 total pagecache pages
> [Mon Mar 25 23:35:18 2019] 0 pages in swap cache
> [Mon Mar 25 23:35:18 2019] Swap cache stats: add 0, delete 0, find 0/0
> [Mon Mar 25 23:35:18 2019] Free swap = 0kB
> [Mon Mar 25 23:35:18 2019] Total swap = 0kB
> [Mon Mar 25 23:35:18 2019] 2097012 pages RAM
> [Mon Mar 25 23:35:18 2019] 0 pages HighMem/MovableOnly
> [Mon Mar 25 23:35:18 2019] 62693 pages reserved
> [Mon Mar 25 23:35:18 2019] 4096 pages cma reserved
> [Mon Mar 25 23:35:18 2019] 0 pages hwpoisoned
>
> As far as I can tell from logs of memory usage (recording memcg and
> MemAvail stats every second), there are gigabytes of available (clean
> page cache) RAM at all times during these tests.
>
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3)
2019-03-26 8:42 ` Nikolay Borisov
@ 2019-03-26 15:09 ` Zygo Blaxell
2019-03-26 15:13 ` Nikolay Borisov
0 siblings, 1 reply; 10+ messages in thread
From: Zygo Blaxell @ 2019-03-26 15:09 UTC (permalink / raw)
To: Nikolay Borisov; +Cc: linux-btrfs
On Tue, Mar 26, 2019 at 10:42:31AM +0200, Nikolay Borisov wrote:
>
>
> On 26.03.19 г. 6:30 ч., Zygo Blaxell wrote:
> > On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
> >> Running balance, rsync, and dedupe, I get kernel warnings every few
> >> minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
> >>
> >> Mount options are: flushoncommit,space_cache=v2,compress=zstd.
> >>
> >> There are two different stacks on the warnings. This one comes from
> >> btrfs balance:
> >
> > [snip]
> >
> > Possibly unrelated, but I'm also repeatably getting this in 5.0.4 and
> > not 5.0.3, after about 5 hours of uptime. Different processes, same
> > kernel stack:
> >
> > [Mon Mar 25 23:35:17 2019] kworker/u8:4: page allocation failure: order:0, mode:0x404000(GFP_NOWAIT|__GFP_COMP), nodemask=(null),cpuset=/,mems_allowed=0
> > [Mon Mar 25 23:35:17 2019] CPU: 2 PID: 29518 Comm: kworker/u8:4 Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
>
> What commits does this kernel include because it doesn't seem to be a
> pristine upstream 5.0.4 ? Also what you are seeing below is definitely a
> bug in MM. The question is whether it's due to your doing faulty
> backports in the kernel or it's due to something that got automatically
> backported to 5.0.4
That was the first thing I thought of, so I reverted to vanilla 5.0.4,
repeated the test, and obtained the same result.
You may have a point about non-btrfs patches in 5.0.4, though.
I previously tested 5.0.3 with most of the 5.0.4 fs/btrfs commits
already included by cherry-pick:
1098803b8cb7 Btrfs: fix deadlock between clone/dedupe and rename
3486142a68e3 Btrfs: fix corruption reading shared and compressed extents after hole punching
fb9c36acfab1 btrfs: scrub: fix circular locking dependency warning
9d7b327affb8 Btrfs: setup a nofs context for memory allocation at __btrfs_set_acl
80dcd07c27df Btrfs: setup a nofs context for memory allocation at btrfs_create_tree()
The commits that are in 5.0.4 but not in my last 5.0.3 test run are:
ebbb48419e8a btrfs: init csum_list before possible free
88e610ae4c3a btrfs: ensure that a DUP or RAID1 block group has exactly two stripes
9c58f2ada4fa btrfs: drop the lock on error in btrfs_dev_replace_cancel
and I don't see how those commits could lead to the observed changes
in behavior. I didn't include them for 5.0.3 because my test scenario
doesn't execute the code they touch. So the problem might be outside
of btrfs completely.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3)
2019-03-26 15:09 ` Zygo Blaxell
@ 2019-03-26 15:13 ` Nikolay Borisov
2019-03-26 15:45 ` Zygo Blaxell
0 siblings, 1 reply; 10+ messages in thread
From: Nikolay Borisov @ 2019-03-26 15:13 UTC (permalink / raw)
To: Zygo Blaxell; +Cc: linux-btrfs
On 26.03.19 г. 17:09 ч., Zygo Blaxell wrote:
> On Tue, Mar 26, 2019 at 10:42:31AM +0200, Nikolay Borisov wrote:
>>
>>
>> On 26.03.19 г. 6:30 ч., Zygo Blaxell wrote:
>>> On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
>>>> Running balance, rsync, and dedupe, I get kernel warnings every few
>>>> minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
>>>>
>>>> Mount options are: flushoncommit,space_cache=v2,compress=zstd.
>>>>
>>>> There are two different stacks on the warnings. This one comes from
>>>> btrfs balance:
>>>
>>> [snip]
>>>
>>> Possibly unrelated, but I'm also repeatably getting this in 5.0.4 and
>>> not 5.0.3, after about 5 hours of uptime. Different processes, same
>>> kernel stack:
>>>
>>> [Mon Mar 25 23:35:17 2019] kworker/u8:4: page allocation failure: order:0, mode:0x404000(GFP_NOWAIT|__GFP_COMP), nodemask=(null),cpuset=/,mems_allowed=0
>>> [Mon Mar 25 23:35:17 2019] CPU: 2 PID: 29518 Comm: kworker/u8:4 Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
>>
>> What commits does this kernel include because it doesn't seem to be a
>> pristine upstream 5.0.4 ? Also what you are seeing below is definitely a
>> bug in MM. The question is whether it's due to your doing faulty
>> backports in the kernel or it's due to something that got automatically
>> backported to 5.0.4
>
> That was the first thing I thought of, so I reverted to vanilla 5.0.4,
> repeated the test, and obtained the same result.
>
> You may have a point about non-btrfs patches in 5.0.4, though.
> I previously tested 5.0.3 with most of the 5.0.4 fs/btrfs commits
> already included by cherry-pick:
>
> 1098803b8cb7 Btrfs: fix deadlock between clone/dedupe and rename
> 3486142a68e3 Btrfs: fix corruption reading shared and compressed extents after hole punching
> fb9c36acfab1 btrfs: scrub: fix circular locking dependency warning
> 9d7b327affb8 Btrfs: setup a nofs context for memory allocation at __btrfs_set_acl
> 80dcd07c27df Btrfs: setup a nofs context for memory allocation at btrfs_create_tree()
>
> The commits that are in 5.0.4 but not in my last 5.0.3 test run are:
>
> ebbb48419e8a btrfs: init csum_list before possible free
> 88e610ae4c3a btrfs: ensure that a DUP or RAID1 block group has exactly two stripes
> 9c58f2ada4fa btrfs: drop the lock on error in btrfs_dev_replace_cancel
>
> and I don't see how those commits could lead to the observed changes
> in behavior. I didn't include them for 5.0.3 because my test scenario
> doesn't execute the code they touch. So the problem might be outside
> of btrfs completely.
I think it might very well be outside of btrfs because you are seeing an
order 0 failure when you have plenty of order 0 free pages. That's
definitely something you might want to report to mm.
>
^ permalink raw reply [flat|nested] 10+ messages in thread
* BUG: workqueue lockup - pool cpus=0-3 flags=0x4 nice=0 stuck for 20915s! (on 4.20+)
2019-03-26 4:30 ` Zygo Blaxell
2019-03-26 8:42 ` Nikolay Borisov
@ 2019-03-26 15:30 ` Zygo Blaxell
2019-05-15 20:27 ` btrfs + KASAN + SLAB + lvmcache + rsync + kernel 5.0 = page allocation failure and/or OOM kills (solved...ish) Zygo Blaxell
2 siblings, 0 replies; 10+ messages in thread
From: Zygo Blaxell @ 2019-03-26 15:30 UTC (permalink / raw)
To: linux-btrfs
On Tue, Mar 26, 2019 at 12:30:07AM -0400, Zygo Blaxell wrote:
> On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
> > Running balance, rsync, and dedupe, [...]
> >
> > Mount options are: flushoncommit,space_cache=v2,compress=zstd.
[snip]
The 5.0.4 test machine locked up overnight. Userspace has been
unresponsive for 6 continuous hours, and the kernel is spewing these:
[57659.907080] BUG: workqueue lockup - pool cpus=0-3 flags=0x4 nice=0 stuck for 20915s!
[57659.908242] Showing busy workqueues and worker pools:
[57659.908978] workqueue events: flags=0x0
[57659.909549] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[57659.910418] pending: cache_reap
[57659.910934] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
[57659.911805] pending: cache_reap
[57659.912321] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=2/256
[57659.913189] pending: psi_update_work, cache_reap
[57659.913919] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=7/256
[57659.914786] in-flight: 5391:cgroup1_release_agent, 5390:cgroup1_release_agent, 5387:cgroup1_release_agent, 5442:cgroup1_release_agent, 5388:cgroup1_release_agent, 23068:cgroup1_release_agent, 11703:cgroup1_release_agent
[57659.917587] workqueue events_unbound: flags=0x2
[57659.918254] pwq 8: cpus=0-3 flags=0x4 nice=0 active=12/512
[57659.919074] pending: flush_to_ldisc, flush_to_ldisc, flush_to_ldisc, flush_to_ldisc, call_usermodehelper_exec_work, call_usermodehelper_exec_work, call_usermodehelper_exec_work, call_usermodehelper_exec_work, call_usermodehelper_exec_work, call_usermodehelper_exec_work, call_usermodehelper_exec_work, flush_to_ldisc
[57659.923001] workqueue events_power_efficient: flags=0x80
[57659.923760] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[57659.924608] pending: sync_hw_clock
[57659.925153] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=2/256
[57659.926006] pending: neigh_periodic_work, check_lifetime
[57659.926814] workqueue events_freezable_power_: flags=0x84
[57659.927579] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[57659.928433] pending: disk_events_workfn
[57659.929040] workqueue mm_percpu_wq: flags=0x8
[57659.929662] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[57659.930516] pending: vmstat_update
[57659.931059] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
[57659.931908] pending: vmstat_update
[57659.932448] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[57659.933301] pending: vmstat_update
[57659.933845] workqueue writeback: flags=0x4e
[57659.934444] pwq 8: cpus=0-3 flags=0x4 nice=0 active=3/256
[57659.935239] in-flight: 22897:wb_workfn
[57659.935827] pending: wb_workfn, wb_workfn
[57659.936453] workqueue kblockd: flags=0x18
[57659.937030] pwq 7: cpus=3 node=0 flags=0x0 nice=-20 active=2/256
[57659.937903] pending: blk_mq_timeout_work, blk_mq_timeout_work
[57659.938770] pwq 3: cpus=1 node=0 flags=0x0 nice=-20 active=2/256
[57659.939639] pending: blk_mq_timeout_work, blk_mq_timeout_work
[57659.940508] workqueue ipv6_addrconf: flags=0x40008
[57659.941196] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/1
[57659.942021] pending: addrconf_verify_work [ipv6]
[57659.942738] workqueue dm_bufio_cache: flags=0x8
[57659.943389] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[57659.944240] pending: work_fn [dm_bufio]
[57659.944845] workqueue dm-cache: flags=0x8
[57659.945421] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
[57659.946271] pending: do_waker [dm_cache]
[57659.946887] workqueue kcopyd: flags=0x8
[57659.947440] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[57659.948291] pending: do_work [dm_mod]
[57659.948875] workqueue btrfs-delalloc: flags=0xe
[57659.949521] pwq 8: cpus=0-3 flags=0x4 nice=0 active=6/6
[57659.950289] pending: btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper
[57659.952299] delayed: btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper
[57659.952320] , btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper, btrfs_delalloc_helper
[57659.970678] workqueue btrfs-endio-meta: flags=0xe
[57659.971355] pwq 8: cpus=0-3 flags=0x4 nice=0 active=1/6
[57659.972126] pending: btrfs_endio_meta_helper
[57659.972793] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=0s workers=9 idle: 5587 5389
[57659.973893] pool 8: cpus=0-3 flags=0x4 nice=0 hung=20915s workers=17 idle: 32317 28343 27652 5842 2072 8322 26565 12095 13036 31394 23436 28378 9538 13699 946 3001
[57668.083089] watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [crawl_259:4967]
[57668.084148] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
[57668.089852] irq event stamp: 2528136198
[57668.090402] hardirqs last enabled at (2528136197): [<ffffffffaad5f339>] _raw_spin_unlock_irq+0x29/0x40
[57668.091721] hardirqs last disabled at (2528136198): [<ffffffffaad57955>] __schedule+0xd5/0xb60
[57668.092934] softirqs last enabled at (2528134802): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
[57668.094178] softirqs last disabled at (2528134793): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
[57668.095357] CPU: 1 PID: 4967 Comm: crawl_259 Tainted: G D W L 5.0.4-zb64-303ce93b05c9+ #1
[57668.096635] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[57668.097813] RIP: 0010:native_safe_halt+0x2/0x10
[57668.098458] Code: 55 ff ff ff 7f c3 65 48 8b 04 25 00 6e 01 00 f0 80 48 02 20 48 8b 00 a8 08 74 8c eb c2 f3 c3 90 90 90 90 90 90 90 90 90 fb f4 <c3> 0f 1f 00 66 2e 0f 1f 84 00 00 00 00 00 f4 c3 90 90 90 90 90 90
[57668.100062] watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [crawl_259:4964]
[57668.101072] RSP: 0018:ffffabb981517780 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
[57668.102091] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
[57668.103158] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000008
[57668.103159] RDX: ffff93942b9d0000 RSI: 0000000000000000 RDI: ffffffffaa075ed1
[57668.108770] irq event stamp: 2284123572
[57668.109776] RBP: ffff93946dd796a4 R08: 0000000000000000 R09: 000000000000000c
[57668.110769] hardirqs last enabled at (2284123571): [<ffffffffaad5f339>] _raw_spin_unlock_irq+0x29/0x40
[57668.111315] R10: ffffabb981517790 R11: ffff93946dd796b8 R12: 0000000000000246
[57668.112308] hardirqs last disabled at (2284123572): [<ffffffffaad57955>] __schedule+0xd5/0xb60
[57668.112309] softirqs last enabled at (2284121412): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
[57668.113626] R13: 0000000000000100 R14: 0000000000000000 R15: 0000000000080000
[57668.113627] FS: 00007f51867fc700(0000) GS:ffff939476000000(0000) knlGS:0000000000000000
[57668.114622] softirqs last disabled at (2284121403): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
[57668.114623] CPU: 3 PID: 4964 Comm: crawl_259 Tainted: G D W L 5.0.4-zb64-303ce93b05c9+ #1
[57668.115834] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[57668.117036] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[57668.118032] CR2: 00007f262a484300 CR3: 00000001ef54e001 CR4: 00000000001606e0
[57668.118034] Call Trace:
[57668.119254] RIP: 0010:queued_write_lock_slowpath+0x4c/0x80
[57668.120427] kvm_wait+0x86/0x90
[57668.121695] Code: ba ff 00 00 00 f0 0f b1 13 85 c0 74 34 f0 81 03 00 01 00 00 b9 ff 00 00 00 be 00 01 00 00 8b 13 81 fa 00 01 00 00 74 0c f3 90 <8b> 13 81 fa 00 01 00 00 75 f4 89 f0 f0 0f b1 0b 3d 00 01 00 00 75
[57668.122507] __pv_queued_spin_lock_slowpath+0x256/0x290
[57668.123663] RSP: 0018:ffffabb9814ffb58 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff13
[57668.124672] queued_read_lock_slowpath+0x6c/0x70
[57668.125027] RAX: 0000000000000400 RBX: ffff93946dd796a0 RCX: 00000000000000ff
[57668.125028] RDX: 0000000000000500 RSI: 0000000000000100 RDI: ffff93946dd796a0
[57668.125809] _raw_read_lock+0x55/0x70
[57668.126254] RBP: ffff93946dd796a4 R08: ffffffffaa46954b R09: 0000000000000000
[57668.126255] R10: ffffabb9814ffb10 R11: ffff93946dd796b8 R12: ffff93946dd796a0
[57668.128883] __tree_mod_log_search+0x28/0xa0
[57668.129613] R13: ffff93946dd79640 R14: ffffabb98b26d000 R15: ffff93946dd78000
[57668.129615] FS: 00007f5187fff700(0000) GS:ffff939476800000(0000) knlGS:0000000000000000
[57668.130683] __tree_mod_log_oldest_root.isra.1+0x47/0x70
[57668.131332] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[57668.131334] CR2: 00007f419a9face0 CR3: 00000001ef54e004 CR4: 00000000001606e0
[57668.132341] btrfs_search_old_slot+0x7f/0x820
[57668.133336] Call Trace:
[57668.133865] btrfs_next_old_leaf+0xfe/0x430
[57668.134858] do_raw_write_lock+0xa9/0xb0
[57668.135866] resolve_indirect_refs+0x4e4/0x960
[57668.136464] _raw_write_lock+0x52/0x70
[57668.137501] find_parent_nodes+0x41d/0x1210
[57668.138595] btrfs_get_tree_mod_seq+0x2b/0xb0
[57668.139354] ? btrfs_inode_flags_to_fsflags+0x80/0x80
[57668.140293] ? btrfs_inode_flags_to_fsflags+0x80/0x80
[57668.141339] iterate_extent_inodes+0x119/0x3c0
[57668.141959] iterate_extent_inodes+0xbd/0x3c0
[57668.142320] ? iterate_inodes_from_logical+0xa6/0xd0
[57668.143197] ? free_extent_buffer+0x46/0x90
[57668.143773] iterate_inodes_from_logical+0xa6/0xd0
[57668.144406] ? iterate_inodes_from_logical+0xa6/0xd0
[57668.145051] ? btrfs_inode_flags_to_fsflags+0x80/0x80
[57668.145643] iterate_inodes_from_logical+0xa6/0xd0
[57668.146267] btrfs_ioctl_logical_to_ino+0xe8/0x190
[57668.146983] ? btrfs_inode_flags_to_fsflags+0x80/0x80
[57668.146985] btrfs_ioctl_logical_to_ino+0xe8/0x190
[57668.146987] btrfs_ioctl+0xcf7/0x2cb0
[57668.146990] ? get_task_mm+0x1b/0x50
[57668.146993] ? lock_acquire+0xbc/0x1c0
[57668.146997] ? do_vfs_ioctl+0xa2/0x6f0
[57668.146998] ? btrfs_ioctl_get_supported_features+0x30/0x30
[57668.146999] do_vfs_ioctl+0xa2/0x6f0
[57668.147001] ? __fget+0x11f/0x210
[57668.147003] ksys_ioctl+0x70/0x80
[57668.147005] __x64_sys_ioctl+0x16/0x20
[57668.147007] do_syscall_64+0x60/0x190
[57668.147010] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[57668.147012] RIP: 0033:0x7f518d7fd777
[57668.147013] Code: 00 00 90 48 8b 05 19 a7 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d e9 a6 0c 00 f7 d8 64 89 01 48
[57668.147014] RSP: 002b:00007f5187ffc458 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[57668.147015] RAX: ffffffffffffffda RBX: 00007f5187ffc780 RCX: 00007f518d7fd777
[57668.147016] RDX: 00007f5187ffc788 RSI: 00000000c038943b RDI: 0000000000000004
[57668.147017] RBP: 0000000001000000 R08: 0000000000000000 R09: 00007f5187ffc960
[57668.147018] R10: 000055ebc655ec60 R11: 0000000000000246 R12: 0000000000000004
[57668.147018] R13: 00007f5187ffc788 R14: 00007f5187ffc668 R15: 00007f5187ffc890
[57668.171643] btrfs_ioctl+0xcf7/0x2cb0
[57668.172170] ? __lock_acquire+0x477/0x1b30
[57668.172759] ? do_vfs_ioctl+0xa2/0x6f0
[57668.173296] ? btrfs_ioctl_get_supported_features+0x30/0x30
[57668.174086] do_vfs_ioctl+0xa2/0x6f0
[57668.174598] ? __fget+0x11f/0x210
[57668.175076] ksys_ioctl+0x70/0x80
[57668.175551] __x64_sys_ioctl+0x16/0x20
[57668.176089] do_syscall_64+0x60/0x190
[57668.176613] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[57668.177330] RIP: 0033:0x7f518d7fd777
[57668.177846] Code: 00 00 90 48 8b 05 19 a7 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d e9 a6 0c 00 f7 d8 64 89 01 48
[57668.180448] RSP: 002b:00007f51867f9308 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[57668.181512] RAX: ffffffffffffffda RBX: 00007f51867f9630 RCX: 00007f518d7fd777
[57668.182514] RDX: 00007f51867f9638 RSI: 00000000c038943b RDI: 0000000000000004
[57668.183513] RBP: 0000000001000000 R08: 0000000000000000 R09: 00007f51867f9810
[57668.184516] R10: 000055ebc655ec60 R11: 0000000000000246 R12: 0000000000000004
[57668.185517] R13: 00007f51867f9638 R14: 00007f51867f9518 R15: 00007f51867f9740
[57676.091103] watchdog: BUG: soft lockup - CPU#2 stuck for 23s! [btrfs:24558]
[57676.092121] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
[57676.097700] irq event stamp: 1719174273
[57676.098239] hardirqs last enabled at (1719174273): [<ffffffffaa2bd47e>] kmem_cache_alloc+0x1fe/0x310
[57676.099514] hardirqs last disabled at (1719174272): [<ffffffffaa2bd335>] kmem_cache_alloc+0xb5/0x310
[57676.100797] softirqs last enabled at (1719173992): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
[57676.102037] softirqs last disabled at (1719173985): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
[57676.103194] CPU: 2 PID: 24558 Comm: btrfs Tainted: G D W L 5.0.4-zb64-303ce93b05c9+ #1
[57676.104428] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[57676.105596] RIP: 0010:native_safe_halt+0x2/0x10
[57676.106241] Code: 55 ff ff ff 7f c3 65 48 8b 04 25 00 6e 01 00 f0 80 48 02 20 48 8b 00 a8 08 74 8c eb c2 f3 c3 90 90 90 90 90 90 90 90 90 fb f4 <c3> 0f 1f 00 66 2e 0f 1f 84 00 00 00 00 00 f4 c3 90 90 90 90 90 90
[57676.108824] RSP: 0018:ffffabb982067730 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
[57676.109884] RAX: 0000000000000000 RBX: 0000000000000001 RCX: 0000000000000001
[57676.110871] RDX: ffff93925de1c000 RSI: 0000000000000000 RDI: ffffffffaa075ed1
[57676.111870] RBP: ffff9394766159d4 R08: 0000000000000000 R09: 0000000000000000
[57676.113277] R10: ffffabb982067750 R11: ffff93946dd796b8 R12: 0000000000000246
[57676.114283] R13: ffff9394766159d4 R14: 0000000000000001 R15: 00000000000c0000
[57676.115285] FS: 00007fe387cef8c0(0000) GS:ffff939476400000(0000) knlGS:0000000000000000
[57676.116418] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[57676.117228] CR2: 0000559ff5ab4270 CR3: 0000000136df4005 CR4: 00000000001606e0
[57676.118236] Call Trace:
[57676.118586] kvm_wait+0x86/0x90
[57676.119130] __pv_queued_spin_lock_slowpath+0x1db/0x290
[57676.119874] ? tree_mod_log_insert_root.isra.2+0x10e/0x350
[57676.120644] queued_write_lock_slowpath+0x7a/0x80
[57676.121315] do_raw_write_lock+0xa9/0xb0
[57676.121877] _raw_write_lock+0x52/0x70
[57676.122410] tree_mod_log_insert_root.isra.2+0x10e/0x350
[57676.123163] __btrfs_cow_block+0x42a/0x580
[57676.123748] btrfs_cow_block+0xe9/0x220
[57676.124298] replace_path.isra.18+0x43f/0x7a0
[57676.124928] merge_reloc_root+0x289/0x540
[57676.125500] merge_reloc_roots+0xdc/0x270
[57676.126077] relocate_block_group+0x17c/0x600
[57676.126693] btrfs_relocate_block_group+0x15b/0x260
[57676.127377] btrfs_relocate_chunk+0x46/0xf0
[57676.127972] btrfs_balance+0xa60/0x12b0
[57676.128520] btrfs_ioctl_balance+0x1a2/0x360
[57676.129128] btrfs_ioctl+0x17b5/0x2cb0
[57676.129664] ? kvm_sched_clock_read+0x14/0x30
[57676.130282] ? __handle_mm_fault+0x105e/0x1800
[57676.130915] ? do_raw_spin_unlock+0x49/0xc0
[57676.131506] ? _raw_spin_unlock+0x24/0x30
[57676.132078] ? __handle_mm_fault+0x105e/0x1800
[57676.132707] ? do_vfs_ioctl+0xa2/0x6f0
[57676.133238] ? btrfs_ioctl_get_supported_features+0x30/0x30
[57676.134023] do_vfs_ioctl+0xa2/0x6f0
[57676.134532] ? __do_page_fault+0x324/0x550
[57676.135115] ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[57676.135853] ksys_ioctl+0x70/0x80
[57676.136323] __x64_sys_ioctl+0x16/0x20
[57676.136858] do_syscall_64+0x60/0x190
[57676.137376] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[57676.138087] RIP: 0033:0x7fe387de2777
[57676.138596] Code: 00 00 90 48 8b 05 19 a7 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d e9 a6 0c 00 f7 d8 64 89 01 48
[57676.141179] RSP: 002b:00007ffefbf583f8 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[57676.142233] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007fe387de2777
[57676.143228] RDX: 00007ffefbf58408 RSI: 00000000c4009420 RDI: 0000000000000003
[57676.144224] RBP: 0000000000000003 R08: 0000000000000003 R09: 0000000000000078
[57676.145209] R10: fffffffffffffa4a R11: 0000000000000202 R12: 00007ffefbf59be2
[57676.146205] R13: 0000000000000000 R14: 0000557caad01052 R15: 0000000000000000
I previously observed a lockup on earlier 5.0.x kernel test runs, so at
least the lockup isn't new in 5.0.4, but it has now happened multiple
times on 5.0 and 4.20 kernels, and crossed the repeatability threshold
for me to report it.
Soft lockups in iterate_inodes_from_logical are nothing new--they've
been happening since 4.0, and they're probably worth a separate thread
because that function gets called from lots of places in btrfs and its
extremely variable performance (7 orders of magnitude between slowest
and fastest run time) impacts almost everything in btrfs. Here's a soft
lockup from some random production machine on 4.14.103 from the other day:
[19831.313928] watchdog: BUG: soft lockup - CPU#2 stuck for 23s! [crawl_5:10732]
[19831.314985] Modules linked in: crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel pcbc joydev ppdev aesni_intel aes_x86_64 sr_mod crypto_simd snd_pcm glue_helper cdrom cryptd snd_timer snd soundcore sg input_leds psmouse ide_pci_generic pcspkr piix bcache serio_raw parport_pc floppy rtc_cmos evbug ide_core bochs_drm parport i2c_piix4 qemu_fw_cfg evdev ip_tables x_tables ipv6 crc_ccitt autofs4
[19831.320084] irq event stamp: 0
[19831.320534] hardirqs last enabled at (0): [< (null)>] (null)
[19831.321600] hardirqs last disabled at (0): [<ffffffffae08c77b>] copy_process.part.6+0x4fb/0x1eb0
[19831.322856] softirqs last enabled at (0): [<ffffffffae08c77b>] copy_process.part.6+0x4fb/0x1eb0
[19831.324111] softirqs last disabled at (0): [< (null)>] (null)
[19831.325169] CPU: 2 PID: 10732 Comm: crawl_5 Tainted: G W L 4.14.103-zb64+ #1
[19831.326311] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[19831.327497] task: ffff8d6266ee8000 task.stack: ffff9c4dc96bc000
[19831.328347] RIP: 0010:iterate_extent_inodes+0x1f9/0x3a0
[19831.329101] RSP: 0018:ffff9c4dc96bfc50 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
[19831.330183] RAX: 0000000000000000 RBX: 0000000000000983 RCX: ffff9c4dcc151000
[19831.331205] RDX: 00000000ca52d620 RSI: 00000000006da000 RDI: 0000000000040d0c
[19831.332224] RBP: ffff9c4dc96bfd00 R08: 00000000001ffffb R09: 0000000000000001
[19831.333248] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffafa0a1c2
[19831.334266] R13: ffffffffae472be0 R14: ffff9c4dcc151000 R15: ffff8d627e0c1ec0
[19831.335287] FS: 00007f8cb27fc700(0000) GS:ffff8d62b8c00000(0000) knlGS:0000000000000000
[19831.336443] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[19831.337256] CR2: 00007ff65c4867f0 CR3: 0000000126eb8001 CR4: 00000000001606e0
[19831.338396] Call Trace:
[19831.338748] ? iterate_inodes_from_logical+0x96/0xb0
[19831.339460] iterate_inodes_from_logical+0x96/0xb0
[19831.340141] ? extent_same_check_offsets+0x60/0x60
[19831.340820] btrfs_ioctl_logical_to_ino+0xe8/0x190
[19831.341503] btrfs_ioctl+0xc5d/0x26a0
[19831.342028] ? lock_acquire+0xbc/0x200
[19831.342566] ? __might_fault+0x3e/0x90
[19831.343108] ? lock_acquire+0xbc/0x200
[19831.343646] ? do_vfs_ioctl+0x92/0x6b0
[19831.344190] ? btrfs_ioctl_get_supported_features+0x30/0x30
[19831.344980] do_vfs_ioctl+0x92/0x6b0
[19831.345499] ? __fget+0x11f/0x210
[19831.345979] SyS_ioctl+0x74/0x80
[19831.346446] do_syscall_64+0x76/0x180
[19831.346967] entry_SYSCALL_64_after_hwframe+0x42/0xb7
[19831.347682] RIP: 0033:0x7f8cb9769017
[19831.348196] RSP: 002b:00007f8cb27f9478 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[19831.349264] RAX: ffffffffffffffda RBX: 00007f8cb27f97a0 RCX: 00007f8cb9769017
[19831.350270] RDX: 00007f8cb27f97a8 RSI: 00000000c038943b RDI: 0000000000000003
[19831.351272] RBP: 0000000001000000 R08: 0000000000000000 R09: 00007f8cb27f9980
[19831.352272] R10: 000055d0f3857c60 R11: 0000000000000246 R12: 0000000000000003
[19831.353280] R13: 00007f8cb27f97a8 R14: 00007f8cb27f9688 R15: 00007f8cb27f98b0
[19831.354283] Code: 6f f6 05 a4 f7 55 01 04 0f 85 e6 00 00 00 48 8b 18 48 8b 45 80 49 c7 c4 c2 a1 a0 af 4c 8b 78 08 4d 85 ff 75 21 eb c8 49 8b 77 08 <4c> 89 f1 48 89 da 49 8b 3f e8 d9 87 b5 00 85 c0 75 41 4d 8b 7f
and here's another one from an earlier 4.20.13 test run:
[309224.545560] watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [crawl_5:4548]
[309224.545563] Modules linked in: dm_cache_smq dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod crct10dif_pclmul joydev ppdev crc32_pclmul snd_pcm crc32c_intel ghash_clmulni_intel sr_mod snd_timer snd cdrom sg aesni_intel aes_x86_64 soundcore crypto_simd cryptd glue_helper input_leds psmouse ide_pci_generic serio_raw bochs_drm piix ide_core i2c_piix4 pcspkr rtc_cmos parport_pc parport floppy evbug evdev qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
[309224.545594] irq event stamp: 4232596770
[309224.545599] hardirqs last enabled at (4232596769): [<ffffffff9923fd3b>] get_page_from_freelist+0x2db/0x1950
[309224.545603] hardirqs last disabled at (4232596770): [<ffffffff9900379f>] trace_hardirqs_off_thunk+0x1a/0x1c
[309224.545606] softirqs last enabled at (4211556454): [<ffffffff9a0003a4>] __do_softirq+0x3a4/0x45f
[309224.545609] softirqs last disabled at (4210205079): [<ffffffff990a2cb4>] irq_exit+0xe4/0xf0
[309224.545613] CPU: 3 PID: 4548 Comm: crawl_5 Tainted: G L 4.20.13-zb64+ #1
[309224.545614] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[309224.545619] RIP: 0010:map_private_extent_buffer+0x79/0xd0
[309224.545622] Code: 81 e3 00 f0 ff ff ba 00 10 00 00 49 29 db 31 db 4d 89 18 4a 8b 84 e7 a0 01 00 00 48 2b 05 3f a7 25 01 48 c1 f8 06 48 c1 e0 0c <48> 03 05 40 a7 25 01 48 01 d8 48 89 01 31 c0 49 89 11 5b 5d 41 5c
[309224.545624] RSP: 0018:ffffac3d0188f7b0 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff13
[309224.545626] RAX: 0000000011fe0000 RBX: 0000000000000000 RCX: ffffac3d0188f7d8
[309224.545628] RDX: 0000000000001000 RSI: 000000000000380d RDI: ffffa0fa24362500
[309224.545630] RBP: 0000000000004000 R08: ffffac3d0188f7e0 R09: ffffac3d0188f7e8
[309224.545632] R10: 0000000000000003 R11: 0000000000003000 R12: 0000000000000003
[309224.545633] R13: 0000000000003815 R14: 000000000000380d R15: 00000000000023ef
[309224.545636] FS: 00007fd5ec9a1700(0000) GS:ffffa0fb39800000(0000) knlGS:0000000000000000
[309224.545637] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[309224.545639] CR2: 00007fd5eda84fed CR3: 0000000164086001 CR4: 00000000001606e0
[309224.545643] Call Trace:
[309224.545652] btrfs_set_token_64+0x109/0x130
[309224.545663] __tree_mod_log_rewind+0xef/0x210
[309224.545669] btrfs_search_old_slot+0x494/0x830
[309224.545683] btrfs_next_old_leaf+0xfe/0x430
[309224.545697] resolve_indirect_refs+0x4e4/0x960
[309224.545717] find_parent_nodes+0x41d/0x1210
[309224.545745] ? extent_same_check_offsets+0x60/0x60
[309224.545749] iterate_extent_inodes+0x119/0x3c0
[309224.545769] ? iterate_inodes_from_logical+0xa6/0xd0
[309224.545772] iterate_inodes_from_logical+0xa6/0xd0
[309224.545776] ? extent_same_check_offsets+0x60/0x60
[309224.545785] btrfs_ioctl_logical_to_ino+0xe8/0x190
[309224.545792] btrfs_ioctl+0xcf7/0x2cb0
[309224.545801] ? __lock_acquire+0x477/0x1b30
[309224.545820] ? do_vfs_ioctl+0xa2/0x6f0
[309224.545823] ? btrfs_ioctl_get_supported_features+0x30/0x30
[309224.545825] do_vfs_ioctl+0xa2/0x6f0
[309224.545832] ? __fget+0x11f/0x210
[309224.545840] ksys_ioctl+0x70/0x80
[309224.545846] __x64_sys_ioctl+0x16/0x20
[309224.545849] do_syscall_64+0x60/0x190
[309224.545854] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[309224.545857] RIP: 0033:0x7fd5eda85017
[309224.545862] Code: Bad RIP value.
[309224.545864] RSP: 002b:00007fd5ec99e478 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[309224.545866] RAX: ffffffffffffffda RBX: 00007fd5ec99e7a0 RCX: 00007fd5eda85017
[309224.545868] RDX: 00007fd5ec99e7a8 RSI: 00000000c038943b RDI: 0000000000000004
[309224.545870] RBP: 0000000001000000 R08: 0000000000000000 R09: 00007fd5ec99e980
[309224.545871] R10: 000056334558ec60 R11: 0000000000000246 R12: 0000000000000004
[309224.545873] R13: 00007fd5ec99e7a8 R14: 00007fd5ec99e688 R15: 00007fd5ec99e8b0
Normally on kernels up to 4.19, these lockups were hours to months apart,
and recovery takes a minute or less. Userspace barely notices, apart
from the spike in commit latency and having a core stuck in the kernel
for a few seconds or minutes.
The difference on 4.20 and 5.0.x is that the soft lockups now cripple
the machine, and they don't go away without external intervention.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3)
2019-03-26 15:13 ` Nikolay Borisov
@ 2019-03-26 15:45 ` Zygo Blaxell
0 siblings, 0 replies; 10+ messages in thread
From: Zygo Blaxell @ 2019-03-26 15:45 UTC (permalink / raw)
To: Nikolay Borisov; +Cc: linux-btrfs
On Tue, Mar 26, 2019 at 05:13:53PM +0200, Nikolay Borisov wrote:
>
>
> On 26.03.19 г. 17:09 ч., Zygo Blaxell wrote:
> > On Tue, Mar 26, 2019 at 10:42:31AM +0200, Nikolay Borisov wrote:
> >>
> >>
> >> On 26.03.19 г. 6:30 ч., Zygo Blaxell wrote:
> >>> On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
> >>>> Running balance, rsync, and dedupe, I get kernel warnings every few
> >>>> minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
> >>>>
> >>>> Mount options are: flushoncommit,space_cache=v2,compress=zstd.
> >>>>
> >>>> There are two different stacks on the warnings. This one comes from
> >>>> btrfs balance:
> >>>
> >>> [snip]
> >>>
> >>> Possibly unrelated, but I'm also repeatably getting this in 5.0.4 and
> >>> not 5.0.3, after about 5 hours of uptime. Different processes, same
> >>> kernel stack:
> >>>
> >>> [Mon Mar 25 23:35:17 2019] kworker/u8:4: page allocation failure: order:0, mode:0x404000(GFP_NOWAIT|__GFP_COMP), nodemask=(null),cpuset=/,mems_allowed=0
> >>> [Mon Mar 25 23:35:17 2019] CPU: 2 PID: 29518 Comm: kworker/u8:4 Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
> >>
> >> What commits does this kernel include because it doesn't seem to be a
> >> pristine upstream 5.0.4 ? Also what you are seeing below is definitely a
> >> bug in MM. The question is whether it's due to your doing faulty
> >> backports in the kernel or it's due to something that got automatically
> >> backported to 5.0.4
> >
> > That was the first thing I thought of, so I reverted to vanilla 5.0.4,
> > repeated the test, and obtained the same result.
> >
> > You may have a point about non-btrfs patches in 5.0.4, though.
> > I previously tested 5.0.3 with most of the 5.0.4 fs/btrfs commits
> > already included by cherry-pick:
> >
> > 1098803b8cb7 Btrfs: fix deadlock between clone/dedupe and rename
> > 3486142a68e3 Btrfs: fix corruption reading shared and compressed extents after hole punching
> > fb9c36acfab1 btrfs: scrub: fix circular locking dependency warning
> > 9d7b327affb8 Btrfs: setup a nofs context for memory allocation at __btrfs_set_acl
> > 80dcd07c27df Btrfs: setup a nofs context for memory allocation at btrfs_create_tree()
> >
> > The commits that are in 5.0.4 but not in my last 5.0.3 test run are:
> >
> > ebbb48419e8a btrfs: init csum_list before possible free
> > 88e610ae4c3a btrfs: ensure that a DUP or RAID1 block group has exactly two stripes
> > 9c58f2ada4fa btrfs: drop the lock on error in btrfs_dev_replace_cancel
> >
> > and I don't see how those commits could lead to the observed changes
> > in behavior. I didn't include them for 5.0.3 because my test scenario
> > doesn't execute the code they touch. So the problem might be outside
> > of btrfs completely.
>
> I think it might very well be outside of btrfs because you are seeing an
> order 0 failure when you have plenty of order 0 free pages. That's
> definitely something you might want to report to mm.
I found a similar incident in logs from older (and slightly different)
test runs, this one on 4.20.13:
[112241.575678] kworker/u8:17: page allocation failure: order:0, mode:0x404000(GFP_NOWAIT|__GFP_COMP), nodemask=(null)
[112241.587462] kworker/u8:17 cpuset=/ mems_allowed=0
[112241.588442] CPU: 1 PID: 22891 Comm: kworker/u8:17 Not tainted 4.20.13-zb64+ #1
[112241.589550] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[112241.590814] Workqueue: btrfs-submit btrfs_submit_helper
[112241.591611] Call Trace:
[112241.592034] dump_stack+0x7d/0xbb
[112241.592564] warn_alloc+0xfc/0x180
[112241.593121] __alloc_pages_nodemask+0x1297/0x13e0
[112241.593860] ? rcu_read_lock_sched_held+0x68/0x70
[112241.594607] cache_grow_begin+0x79/0x730
[112241.595226] ? cache_grow_begin+0x79/0x730
[112241.595875] ? ____cache_alloc_node+0x165/0x1e0
[112241.596573] fallback_alloc+0x1e4/0x280
[112241.597162] kmem_cache_alloc+0x2e9/0x310
[112241.597763] btracker_queue+0x47/0x170 [dm_cache]
[112241.598465] __lookup+0x474/0x600 [dm_cache_smq]
[112241.599151] ? smq_lookup+0x37/0x7b [dm_cache_smq]
[112241.599867] smq_lookup+0x5d/0x7b [dm_cache_smq]
[112241.600554] map_bio.part.40+0x14d/0x5d0 [dm_cache]
[112241.601307] ? bio_detain_shared+0xb3/0x120 [dm_cache]
[112241.602075] cache_map+0x120/0x1a0 [dm_cache]
[112241.602813] __map_bio+0x42/0x1f0 [dm_mod]
[112241.603506] __split_and_process_non_flush+0x10e/0x1e0 [dm_mod]
[112241.604418] __split_and_process_bio+0xb2/0x1a0 [dm_mod]
[112241.605371] ? __process_bio+0x170/0x170 [dm_mod]
[112241.606099] __dm_make_request.isra.20+0x4c/0x100 [dm_mod]
[112241.606936] generic_make_request+0x29d/0x470
[112241.607611] ? kvm_sched_clock_read+0x14/0x30
[112241.608282] ? submit_bio+0x6c/0x140
[112241.608841] submit_bio+0x6c/0x140
[112241.609379] run_scheduled_bios+0x1f5/0x530
[112241.610034] ? normal_work_helper+0x95/0x530
[112241.610699] normal_work_helper+0x95/0x530
[112241.611343] process_one_work+0x223/0x5d0
[112241.611973] worker_thread+0x4f/0x3b0
[112241.612545] kthread+0x106/0x140
[112241.613059] ? process_one_work+0x5d0/0x5d0
[112241.613721] ? kthread_park+0x90/0x90
[112241.614305] ret_from_fork+0x3a/0x50
[112241.614949] Mem-Info:
[112241.615320] active_anon:155365 inactive_anon:2116 isolated_anon:0
[112241.615320] active_file:466942 inactive_file:242123 isolated_file:0
[112241.615320] unevictable:262144 dirty:30009 writeback:23033 unstable:0
[112241.615320] slab_reclaimable:39503 slab_unreclaimable:19905
[112241.615320] mapped:2750 shmem:2447 pagetables:2077 bounce:0
[112241.615320] free:38378 free_pcp:1387 free_cma:2928
[112241.620633] Node 0 active_anon:621460kB inactive_anon:8464kB active_file:1867768kB inactive_file:968492kB unevictable:1048576kB isolated(anon):0kB isolated(file):0kB mapped:11000kB dirty:114264kB writeback:97756kB shmem:9788kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 1146880kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[112241.625103] Node 0 DMA free:15844kB min:212kB low:264kB high:316kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[112241.629016] lowmem_reserve[]: 0 2939 4882 4882 4882
[112241.629776] Node 0 DMA32 free:78616kB min:40432kB low:50540kB high:60648kB active_anon:411892kB inactive_anon:24kB active_file:1374720kB inactive_file:701652kB unevictable:241664kB writepending:133964kB present:3129176kB managed:3019400kB mlocked:241664kB kernel_stack:752kB pagetables:3860kB bounce:0kB free_pcp:1980kB local_pcp:0kB free_cma:0kB
[112241.634350] lowmem_reserve[]: 0 0 1942 1942 1942
[112241.635098] Node 0 Normal free:43292kB min:26936kB low:33668kB high:40400kB active_anon:209568kB inactive_anon:8440kB active_file:494452kB inactive_file:266024kB unevictable:806912kB writepending:77516kB present:2097152kB managed:2005456kB mlocked:806912kB kernel_stack:2768kB pagetables:4448kB bounce:0kB free_pcp:3032kB local_pcp:0kB free_cma:11712kB
[112241.639679] lowmem_reserve[]: 0 0 0 0 0
[112241.640262] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 1*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15844kB
[112241.642205] Node 0 DMA32: 7549*4kB (UME) 4950*8kB (UME) 484*16kB (UME) 25*32kB (UE) 1*64kB (M) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 78404kB
[112241.644176] Node 0 Normal: 3796*4kB (UMEHC) 2435*8kB (UMEHC) 317*16kB (UMHC) 51*32kB (UMHC) 7*64kB (HC) 3*128kB (UH) 3*256kB (H) 1*512kB (H) 0*1024kB 0*2048kB 0*4096kB = 43480kB
[112241.646403] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[112241.647639] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[112241.648839] 711461 total pagecache pages
[112241.649416] 0 pages in swap cache
[112241.649912] Swap cache stats: add 0, delete 0, find 0/0
[112241.650664] Free swap = 0kB
[112241.651098] Total swap = 0kB
[112241.651656] 1310580 pages RAM
[112241.652107] 0 pages HighMem/MovableOnly
[112241.652669] 50389 pages reserved
[112241.653150] 4096 pages cma reserved
[112241.653662] 0 pages hwpoisoned
It happens on 4.20.14 as well. Not sure why it's so rare on 5.0.3
(3x longer test run than 4.20.x or 5.0.4, no incidents), and I don't
have data from older kernels running sufficiently similar tests to
widen the data set.
I have been noticing a lot of unexpected OOM kills on 4.20+ kernels,
but I increased RAM in the test VMs and those went away. Maybe I
misidentified the cause of that problem as something in userspace,
when it was really a MM bug.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (still on 5.0.10)
2019-03-26 2:50 WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3) Zygo Blaxell
2019-03-26 4:30 ` Zygo Blaxell
@ 2019-04-29 22:34 ` Zygo Blaxell
2020-02-04 3:16 ` WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (fixed in 5.2) Zygo Blaxell
1 sibling, 1 reply; 10+ messages in thread
From: Zygo Blaxell @ 2019-04-29 22:34 UTC (permalink / raw)
To: linux-btrfs
[-- Attachment #1: Type: text/plain, Size: 8260 bytes --]
On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
> Running balance, rsync, and dedupe, I get kernel warnings every few
> minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
>
> Mount options are: flushoncommit,space_cache=v2,compress=zstd.
>
> There are two different stacks on the warnings. This one comes from
> btrfs balance:
>
> [Mon Mar 25 18:22:42 2019] WARNING: CPU: 0 PID: 4786 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
> [Mon Mar 25 18:22:42 2019] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
> [Mon Mar 25 18:22:42 2019] CPU: 0 PID: 4786 Comm: btrfs-balance Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
> [Mon Mar 25 18:22:42 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> [Mon Mar 25 18:22:42 2019] RIP: 0010:btrfs_merge_delayed_refs+0x3dc/0x410
> [Mon Mar 25 18:22:42 2019] Code: 7c 24 28 be ff ff ff ff e8 31 a0 c1 ff 85 c0 0f 85 7c fe ff ff 0f 0b e9 75 fe ff ff 0f 0b e9 0a fe ff ff 0f 0b e9 1b fe ff ff <0f> 0b e9 25 ff ff ff 0f 0b e9 b0 fe ff ff 48 c7 44 24 10 00 00 00
> [Mon Mar 25 18:22:42 2019] RSP: 0018:ffffabb981377b70 EFLAGS: 00010246
> [Mon Mar 25 18:22:42 2019] RAX: 00000000000000b6 RBX: 00000000ffffffff RCX: 0000000000000001
> [Mon Mar 25 18:22:42 2019] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000282
> [Mon Mar 25 18:22:42 2019] RBP: ffff9392514bbb80 R08: ffff9392514bbc80 R09: 0000000000000000
> [Mon Mar 25 18:22:42 2019] R10: 0000000000000000 R11: 0000000000000001 R12: ffff93928a5c8f08
> [Mon Mar 25 18:22:42 2019] R13: ffff939269744e38 R14: ffff939269744e38 R15: ffff9392697449c0
> [Mon Mar 25 18:22:42 2019] FS: 0000000000000000(0000) GS:ffff939475c00000(0000) knlGS:0000000000000000
> [Mon Mar 25 18:22:42 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [Mon Mar 25 18:22:42 2019] CR2: 00007f0882d38600 CR3: 0000000230eb6002 CR4: 00000000001606f0
> [Mon Mar 25 18:22:42 2019] Call Trace:
> [Mon Mar 25 18:22:42 2019] __btrfs_run_delayed_refs+0x70/0x170
> [Mon Mar 25 18:22:42 2019] btrfs_run_delayed_refs+0x7d/0x1d0
> [Mon Mar 25 18:22:42 2019] btrfs_commit_transaction+0x50/0x9e0
> [Mon Mar 25 18:22:42 2019] ? start_transaction+0x91/0x4d0
> [Mon Mar 25 18:22:42 2019] relocate_block_group+0x1bd/0x600
> [Mon Mar 25 18:22:42 2019] btrfs_relocate_block_group+0x15b/0x260
> [Mon Mar 25 18:22:42 2019] btrfs_relocate_chunk+0x46/0xf0
> [Mon Mar 25 18:22:42 2019] btrfs_balance+0xa60/0x12b0
> [Mon Mar 25 18:22:42 2019] balance_kthread+0x36/0x50
> [Mon Mar 25 18:22:42 2019] kthread+0x106/0x140
> [Mon Mar 25 18:22:42 2019] ? btrfs_balance+0x12b0/0x12b0
> [Mon Mar 25 18:22:42 2019] ? kthread_park+0x90/0x90
> [Mon Mar 25 18:22:42 2019] ret_from_fork+0x3a/0x50
> [Mon Mar 25 18:22:42 2019] irq event stamp: 81529004
> [Mon Mar 25 18:22:42 2019] hardirqs last enabled at (81529003): [<ffffffffaa2be2b7>] kmem_cache_free+0x67/0x1e0
> [Mon Mar 25 18:22:42 2019] hardirqs last disabled at (81529004): [<ffffffffaa00379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> [Mon Mar 25 18:22:42 2019] softirqs last enabled at (81527500): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
> [Mon Mar 25 18:22:42 2019] softirqs last disabled at (81527493): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
> [Mon Mar 25 18:22:42 2019] ---[ end trace 3d8cdfff7444099a ]---
>
> This one comes from btrfs-transaction:
>
> [Mon Mar 25 18:27:58 2019] WARNING: CPU: 3 PID: 4137 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
> [Mon Mar 25 18:27:58 2019] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
> [Mon Mar 25 18:27:58 2019] CPU: 3 PID: 4137 Comm: btrfs-transacti Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
> [Mon Mar 25 18:27:58 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> [Mon Mar 25 18:27:58 2019] RIP: 0010:btrfs_merge_delayed_refs+0x3dc/0x410
> [Mon Mar 25 18:27:58 2019] Code: 7c 24 28 be ff ff ff ff e8 31 a0 c1 ff 85 c0 0f 85 7c fe ff ff 0f 0b e9 75 fe ff ff 0f 0b e9 0a fe ff ff 0f 0b e9 1b fe ff ff <0f> 0b e9 25 ff ff ff 0f 0b e9 b0 fe ff ff 48 c7 44 24 10 00 00 00
> [Mon Mar 25 18:27:58 2019] RSP: 0018:ffffabb9812f7d40 EFLAGS: 00010246
> [Mon Mar 25 18:27:58 2019] RAX: 00000000000000b6 RBX: 00000000ffffffff RCX: 0000000000000001
> [Mon Mar 25 18:27:58 2019] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000286
> [Mon Mar 25 18:27:58 2019] RBP: ffff93925b187ce0 R08: ffff93925b187de0 R09: 0000000000000000
> [Mon Mar 25 18:27:58 2019] R10: 0000000000000000 R11: 0000000000000001 R12: ffff93938b59d308
> [Mon Mar 25 18:27:58 2019] R13: ffff9393a5d09820 R14: ffff9393a5d09820 R15: ffff939261978820
> [Mon Mar 25 18:27:58 2019] FS: 0000000000000000(0000) GS:ffff939476800000(0000) knlGS:0000000000000000
> [Mon Mar 25 18:27:58 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [Mon Mar 25 18:27:58 2019] CR2: 00007f91f6321c50 CR3: 00000001ef54e003 CR4: 00000000001606e0
> [Mon Mar 25 18:27:58 2019] Call Trace:
> [Mon Mar 25 18:27:58 2019] __btrfs_run_delayed_refs+0x70/0x170
> [Mon Mar 25 18:27:58 2019] btrfs_run_delayed_refs+0x7d/0x1d0
> [Mon Mar 25 18:27:58 2019] btrfs_commit_transaction+0x50/0x9e0
> [Mon Mar 25 18:27:58 2019] ? start_transaction+0x91/0x4d0
> [Mon Mar 25 18:27:58 2019] transaction_kthread+0x146/0x180
> [Mon Mar 25 18:27:58 2019] kthread+0x106/0x140
> [Mon Mar 25 18:27:58 2019] ? btrfs_cleanup_transaction+0x620/0x620
> [Mon Mar 25 18:27:58 2019] ? kthread_park+0x90/0x90
> [Mon Mar 25 18:27:58 2019] ret_from_fork+0x3a/0x50
> [Mon Mar 25 18:27:58 2019] irq event stamp: 81665152
> [Mon Mar 25 18:27:58 2019] hardirqs last enabled at (81665151): [<ffffffffaa2be2b7>] kmem_cache_free+0x67/0x1e0
> [Mon Mar 25 18:27:58 2019] hardirqs last disabled at (81665152): [<ffffffffaa00379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> [Mon Mar 25 18:27:58 2019] softirqs last enabled at (81664580): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
> [Mon Mar 25 18:27:58 2019] softirqs last disabled at (81664565): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
> [Mon Mar 25 18:27:58 2019] ---[ end trace 3d8cdfff7444099c ]---
>
> Pausing the balance makes the warnings stop.
After sorting out some unrelated issues with 5.0 kernels, these warnings
are now the top of my list of unresolved 5.0 kernel issues. They are
popping up more often: 31804 times over two machine-days. Too much
spam for the kernel logs.
This is the code surrounding the WARN_ON:
static bool merge_ref(...
{
// ...
drop_delayed_ref(trans, delayed_refs, head, next);
ref->ref_mod += mod;
if (ref->ref_mod == 0) {
drop_delayed_ref(trans, delayed_refs, head, ref);
done = true;
} else {
/*
* Can't have multiples of the same ref on a tree block.
*/
WARN_ON(ref->type == BTRFS_TREE_BLOCK_REF_KEY ||
ref->type == BTRFS_SHARED_BLOCK_REF_KEY);
}
// ...
}
Should the warning be removed? If something bad was going to happen,
I would have expected it to happen some time in the last month of
stress-testing, but I can find no evidence of failure related to
this warning.
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]
^ permalink raw reply [flat|nested] 10+ messages in thread
* btrfs + KASAN + SLAB + lvmcache + rsync + kernel 5.0 = page allocation failure and/or OOM kills (solved...ish)
2019-03-26 4:30 ` Zygo Blaxell
2019-03-26 8:42 ` Nikolay Borisov
2019-03-26 15:30 ` BUG: workqueue lockup - pool cpus=0-3 flags=0x4 nice=0 stuck for 20915s! (on 4.20+) Zygo Blaxell
@ 2019-05-15 20:27 ` Zygo Blaxell
2 siblings, 0 replies; 10+ messages in thread
From: Zygo Blaxell @ 2019-05-15 20:27 UTC (permalink / raw)
To: linux-btrfs
[-- Attachment #1: Type: text/plain, Size: 15838 bytes --]
On Tue, Mar 26, 2019 at 12:30:07AM -0400, Zygo Blaxell wrote:
> On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
> > Running balance, rsync, and dedupe, I get kernel warnings every few
> > minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
> >
> > Mount options are: flushoncommit,space_cache=v2,compress=zstd.
> >
> > There are two different stacks on the warnings. This one comes from
> > btrfs balance:
>
> [snip]
>
> Possibly unrelated, but I'm also repeatably getting this in 5.0.4 and
> not 5.0.3, after about 5 hours of uptime. Different processes, same
> kernel stack:
>
> [Mon Mar 25 23:35:17 2019] kworker/u8:4: page allocation failure: order:0, mode:0x404000(GFP_NOWAIT|__GFP_COMP), nodemask=(null),cpuset=/,mems_allowed=0
It turns out there were two bugs overlapping here:
5.0.3 -> 5.0.4 introduced the initial bug I observed in March
In my own 5.0.6 builds, I turned on KASAN (and several other
memory debug kernel config options) to chase an unrelated bug
with behavior that was looking like a use-after-free. This
introduced a second page allocation failure behavior that occurred
much more rapidly (every few seconds instead of every few hours).
Somewhere between 5.0.5 and 5.0.10, the first, infrequent bug
introduced in March was fixed.
In my 5.0.10 and later builds, I turned KASAN off again.
This avoids the second, very frequent bug.
I have no idea what bug got introduced and removed somewhere in
5.0.3..5.0.10, but I can't reproduce it on 5.0.11 and later, and I have
more urgent bugs to squash.
I'll leave what I've learned here in case someone rediscovers these
problems.
I ran a lot of tests turning things on and off and found that page
allocation failures seem to be triggered in large numbers by a
combination of _all_ of the following:
1. btrfs (ext4 doesn't trigger it)
2. lvmcache (using the same hardware in a btrfs on plain HDD
or SSD doesn't trigger it, bcache has other problems that
make it untestable)
3. kernel KASAN (must be enabled to trigger it)
4. userspace running rsync (seems any workload that writes
pages continuously to a btrfs filesystem will suffice)
5. Linux 5.0.6..5.0.10 (haven't rigorously tested anything else)
6. Unknown other factors? (I only tested the above)
Some other things I tried turning on or off that have no effect:
A. dedupe, snapshots, balances, processes reading the btrfs
filesystem
B. using memory cgroups to limit page cache RAM usage of the
rsync process
C. sysctl vm.dirty_ratio (1..50), dirty_background_ratio (1..10)
dirty_expire_centisecs (100..30000) to try to increase or decrease
the number of reclaimable pages and reclaim rate
D. btrfs flushoncommit and compress mount options
E. running memory-hog applications to try to trigger page
allocation failures faster (fork() returns ENOMEM before these
even get to start)
F. changing host memory size (2GB to 8GB in 1GB increments)
The page allocation failures start soon after all the host's RAM is
allocated to page cache. They lead to a lot of processes getting ENOMEM
on various system calls, especially fork(). This effectively kills some
random process every second or two. Half the commands run from a shell
will immediately fail with ENOMEM, assuming the shell itself doesn't die.
Booting a desktop or building a kernel is impossible.
I can live without KASAN, so I've just turned it off for my 5.0 kernel
builds. I've had no problems since I did that near the end of April.
Here's a stacktrace with KASAN:
[ 5157.469012] kworker/2:0: page allocation failure: order:0, mode:0x400000(GFP_NOWAIT), nodemask=(null),cpuset=/,mems_allowed=0
[ 5157.482299] CPU: 2 PID: 12944 Comm: kworker/2:0 Not tainted 5.0.10-zb64-1bb762d31089+ #1
[ 5157.487810] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 5157.494046] Workqueue: dm-cache check_migrations [dm_cache]
[ 5157.496751] Call Trace:
[ 5157.497564] dump_stack+0x9c/0xf5
[ 5157.500331] warn_alloc+0x19a/0x240
[ 5157.501518] ? zone_watermark_ok_safe+0x140/0x140
[ 5157.502796] ? __isolate_free_page+0x2b0/0x2b0
[ 5157.503916] __alloc_pages_nodemask+0x1857/0x1980
[ 5157.506179] ? debug_show_all_locks+0x210/0x210
[ 5157.508559] ? gfp_pfmemalloc_allowed+0xc0/0xc0
[ 5157.509939] ? __asan_loadN+0xf/0x20
[ 5157.511398] ? pvclock_clocksource_read+0xd8/0x180
[ 5157.513057] ? kvm_sched_clock_read+0x18/0x30
[ 5157.514301] ? check_chain_key+0x147/0x200
[ 5157.515414] ? mark_lock+0xad/0x930
[ 5157.516368] ? mark_lock+0xad/0x930
[ 5157.517333] ? mark_held_locks+0x92/0xc0
[ 5157.518398] ? lock_release+0x7e/0x720
[ 5157.519432] ? mark_held_locks+0x92/0xc0
[ 5157.520627] ? __asan_loadN+0xf/0x20
[ 5157.521574] ? pvclock_clocksource_read+0xd8/0x180
[ 5157.523130] alloc_pages_current+0x75/0x110
[ 5157.524244] new_slab+0x44a/0x6a0
[ 5157.525244] ___slab_alloc+0x434/0x5c0
[ 5157.526469] ? btracker_queue+0xcc/0x2d0 [dm_cache]
[ 5157.527976] ? debug_show_all_locks+0x210/0x210
[ 5157.529254] ? __slab_alloc+0x3c/0x90
[ 5157.530412] ? btracker_queue+0xcc/0x2d0 [dm_cache]
[ 5157.531749] __slab_alloc+0x51/0x90
[ 5157.532789] ? __slab_alloc+0x51/0x90
[ 5157.533766] ? btracker_queue+0xcc/0x2d0 [dm_cache]
[ 5157.535172] kmem_cache_alloc+0x229/0x290
[ 5157.536310] btracker_queue+0xcc/0x2d0 [dm_cache]
[ 5157.537692] queue_writeback+0x157/0x1d0 [dm_cache_smq]
[ 5157.539206] ? mark_pending.isra.24+0x50/0x50 [dm_cache_smq]
[ 5157.540879] ? btracker_issue+0x28/0x120 [dm_cache]
[ 5157.542302] smq_get_background_work+0xa3/0xc0 [dm_cache_smq]
[ 5157.543805] check_migrations+0x1b8/0x2e0 [dm_cache]
[ 5157.545426] ? cache_ctr+0x1a70/0x1a70 [dm_cache]
[ 5157.548005] process_one_work+0x476/0xa00
[ 5157.549104] ? pwq_dec_nr_in_flight+0x130/0x130
[ 5157.550784] ? do_raw_spin_lock+0x1d0/0x1d0
[ 5157.551952] ? move_linked_works+0x113/0x150
[ 5157.553119] worker_thread+0x76/0x5d0
[ 5157.554163] kthread+0x1a9/0x200
[ 5157.555028] ? process_one_work+0xa00/0xa00
[ 5157.556221] ? kthread_park+0xb0/0xb0
[ 5157.559982] ret_from_fork+0x3a/0x50
[ 5157.561253] Mem-Info:
[ 5157.561822] active_anon:134320 inactive_anon:4419 isolated_anon:0
[ 5157.561822] active_file:1107612 inactive_file:249821 isolated_file:115
[ 5157.561822] unevictable:0 dirty:4092 writeback:25 unstable:0
[ 5157.561822] slab_reclaimable:95574 slab_unreclaimable:98822
[ 5157.561822] mapped:8463 shmem:4486 pagetables:2982 bounce:0
[ 5157.561822] free:25133 free_pcp:1021 free_cma:13
[ 5157.572482] Node 0 active_anon:537280kB inactive_anon:17676kB active_file:4430448kB inactive_file:999284kB unevictable:0kB isolated(anon):0kB isolated(file):460kB mapped:33852kB dirty:16368kB writeback:100kB shmem:17944kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 323584kB wr
iteback_tmp:0kB unstable:0kB all_unreclaimable? no
[ 5157.579907] Node 0 DMA free:15812kB min:152kB low:188kB high:224kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0
kB free_cma:0kB
[ 5157.585961] lowmem_reserve[]: 0 2991 6846 6846 6846
[ 5157.587060] Node 0 DMA32 free:44432kB min:29352kB low:36688kB high:44024kB active_anon:14056kB inactive_anon:8kB active_file:2068012kB inactive_file:594748kB unevictable:0kB writepending:8620kB present:3129176kB managed:3063640kB mlocked:0kB kernel_stack:960kB pagetables:556kB b
ounce:0kB free_pcp:4272kB local_pcp:748kB free_cma:0kB
[ 5157.593250] lowmem_reserve[]: 0 0 3854 3854 3854
[ 5157.594346] Node 0 Normal free:40288kB min:40124kB low:51688kB high:61204kB active_anon:523580kB inactive_anon:17668kB active_file:2361432kB inactive_file:404492kB unevictable:0kB writepending:6060kB present:5242880kB managed:3974560kB mlocked:0kB kernel_stack:15488kB pagetables
:11372kB bounce:0kB free_pcp:404kB local_pcp:32kB free_cma:52kB
[ 5157.601624] lowmem_reserve[]: 0 0 0 0 0
[ 5157.602574] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 0*32kB 1*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15812kB
[ 5157.605746] Node 0 DMA32: 605*4kB (UME) 438*8kB (UME) 378*16kB (UME) 124*32kB (UME) 162*64kB (UME) 101*128kB (UM) 21*256kB (ME) 1*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 45124kB
[ 5157.609543] Node 0 Normal: 651*4kB (UMEC) 693*8kB (UMEC) 658*16kB (UME) 398*32kB (UMEH) 63*64kB (UME) 26*128kB (UE) 9*256kB (U) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 41076kB
[ 5157.613190] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[ 5157.615305] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[ 5157.617353] 1361051 total pagecache pages
[ 5157.618413] 0 pages in swap cache
[ 5157.619220] Swap cache stats: add 0, delete 0, find 0/0
[ 5157.620582] Free swap = 0kB
[ 5157.621380] Total swap = 0kB
[ 5157.622092] 2097012 pages RAM
[ 5157.622815] 0 pages HighMem/MovableOnly
[ 5157.623804] 333485 pages reserved
[ 5157.624606] 4096 pages cma reserved
[ 5157.625493] 0 pages hwpoisoned
[ 5157.626286] SLUB: Unable to allocate memory on node -1, gfp=0x400000(GFP_NOWAIT)
[ 5157.628335] cache: bt_work, object size: 64, buffer size: 96, default order: 0, min order: 0
[ 5157.630495] node 0: slabs: 111, objs: 4662, free: 0
This is the original (5.0.4) KASAN-free stacktrace:
> [Mon Mar 25 23:35:17 2019] CPU: 2 PID: 29518 Comm: kworker/u8:4 Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
> [Mon Mar 25 23:35:17 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> [Mon Mar 25 23:35:17 2019] Workqueue: btrfs-submit btrfs_submit_helper
> [Mon Mar 25 23:35:17 2019] Call Trace:
> [Mon Mar 25 23:35:17 2019] dump_stack+0x7d/0xbb
> [Mon Mar 25 23:35:17 2019] warn_alloc+0x108/0x190
> [Mon Mar 25 23:35:17 2019] __alloc_pages_nodemask+0x12c4/0x13f0
> [Mon Mar 25 23:35:17 2019] ? rcu_read_lock_sched_held+0x68/0x70
> [Mon Mar 25 23:35:17 2019] ? __update_load_avg_se+0x208/0x280
> [Mon Mar 25 23:35:17 2019] cache_grow_begin+0x79/0x730
> [Mon Mar 25 23:35:17 2019] ? cache_grow_begin+0x79/0x730
> [Mon Mar 25 23:35:17 2019] ? ____cache_alloc_node+0x165/0x1e0
> [Mon Mar 25 23:35:17 2019] fallback_alloc+0x1e4/0x280
> [Mon Mar 25 23:35:17 2019] kmem_cache_alloc+0x2e9/0x310
> [Mon Mar 25 23:35:17 2019] btracker_queue+0x47/0x170 [dm_cache]
> [Mon Mar 25 23:35:17 2019] __lookup+0x51a/0x600 [dm_cache_smq]
> [Mon Mar 25 23:35:17 2019] ? smq_lookup+0x37/0x7b [dm_cache_smq]
> [Mon Mar 25 23:35:17 2019] smq_lookup+0x5d/0x7b [dm_cache_smq]
> [Mon Mar 25 23:35:18 2019] map_bio.part.40+0x14d/0x5d0 [dm_cache]
> [Mon Mar 25 23:35:18 2019] ? bio_detain_shared+0xb3/0x120 [dm_cache]
> [Mon Mar 25 23:35:18 2019] cache_map+0x120/0x170 [dm_cache]
> [Mon Mar 25 23:35:18 2019] __map_bio+0x42/0x1f0 [dm_mod]
> [Mon Mar 25 23:35:18 2019] __split_and_process_non_flush+0x152/0x1e0 [dm_mod]
> [Mon Mar 25 23:35:18 2019] __split_and_process_bio+0xd4/0x400 [dm_mod]
> [Mon Mar 25 23:35:18 2019] ? lock_acquire+0xbc/0x1c0
> [Mon Mar 25 23:35:18 2019] ? dm_get_live_table+0x5/0xc0 [dm_mod]
> [Mon Mar 25 23:35:18 2019] dm_make_request+0x4d/0x100 [dm_mod]
> [Mon Mar 25 23:35:18 2019] generic_make_request+0x297/0x470
> [Mon Mar 25 23:35:18 2019] ? kvm_sched_clock_read+0x14/0x30
> [Mon Mar 25 23:35:18 2019] ? submit_bio+0x6c/0x140
> [Mon Mar 25 23:35:18 2019] submit_bio+0x6c/0x140
> [Mon Mar 25 23:35:18 2019] run_scheduled_bios+0x1e6/0x500
> [Mon Mar 25 23:35:18 2019] ? normal_work_helper+0x95/0x530
> [Mon Mar 25 23:35:18 2019] normal_work_helper+0x95/0x530
> [Mon Mar 25 23:35:18 2019] process_one_work+0x223/0x5d0
> [Mon Mar 25 23:35:18 2019] worker_thread+0x4f/0x3b0
> [Mon Mar 25 23:35:18 2019] kthread+0x106/0x140
> [Mon Mar 25 23:35:18 2019] ? process_one_work+0x5d0/0x5d0
> [Mon Mar 25 23:35:18 2019] ? kthread_park+0x90/0x90
> [Mon Mar 25 23:35:18 2019] ret_from_fork+0x3a/0x50
> [Mon Mar 25 23:35:18 2019] Mem-Info:
> [Mon Mar 25 23:35:18 2019] active_anon:195872 inactive_anon:15658 isolated_anon:0
> active_file:629653 inactive_file:308914 isolated_file:0
> unevictable:65536 dirty:14449 writeback:27580 unstable:0
> slab_reclaimable:492522 slab_unreclaimable:94393
> mapped:10915 shmem:18846 pagetables:2178 bounce:0
> free:66082 free_pcp:1963 free_cma:24
> [Mon Mar 25 23:35:18 2019] Node 0 active_anon:783488kB inactive_anon:62632kB active_file:2516656kB inactive_file:1235604kB unevictable:262144kB isolated(anon):0kB isolated(file):0kB mapped:43660kB dirty:57796kB writeback:110320kB shmem:75384kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 137216kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
> [Mon Mar 25 23:35:18 2019] Node 0 DMA free:15844kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
> [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 2939 7906 7906 7906
> [Mon Mar 25 23:35:18 2019] Node 0 DMA32 free:116632kB min:81336kB low:87592kB high:93848kB active_anon:330436kB inactive_anon:31840kB active_file:531512kB inactive_file:491372kB unevictable:108544kB writepending:121984kB present:3129176kB managed:3019336kB mlocked:108544kB kernel_stack:2704kB pagetables:2944kB bounce:0kB free_pcp:3800kB local_pcp:256kB free_cma:0kB
> [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 0 4966 4966 4966
> [Mon Mar 25 23:35:18 2019] Node 0 Normal free:141932kB min:42420kB low:53024kB high:63628kB active_anon:453224kB inactive_anon:30792kB active_file:1984568kB inactive_file:737244kB unevictable:153600kB writepending:46544kB present:5242880kB managed:5102032kB mlocked:153600kB kernel_stack:7020kB pagetables:5768kB bounce:0kB free_pcp:4188kB local_pcp:1700kB free_cma:96kB
> [Mon Mar 25 23:35:18 2019] lowmem_reserve[]: 0 0 0 0 0
> [Mon Mar 25 23:35:18 2019] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 1*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15844kB
> [Mon Mar 25 23:35:18 2019] Node 0 DMA32: 12698*4kB (UME) 6110*8kB (UME) 1087*16kB (UME) 4*32kB (M) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 117192kB
> [Mon Mar 25 23:35:18 2019] Node 0 Normal: 13507*4kB (UMEHC) 8008*8kB (UMEHC) 1374*16kB (UMEH) 3*32kB (H) 4*64kB (H) 4*128kB (H) 2*256kB (H) 1*512kB (H) 0*1024kB 0*2048kB 0*4096kB = 141964kB
> [Mon Mar 25 23:35:18 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
> [Mon Mar 25 23:35:18 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
> [Mon Mar 25 23:35:18 2019] 955001 total pagecache pages
> [Mon Mar 25 23:35:18 2019] 0 pages in swap cache
> [Mon Mar 25 23:35:18 2019] Swap cache stats: add 0, delete 0, find 0/0
> [Mon Mar 25 23:35:18 2019] Free swap = 0kB
> [Mon Mar 25 23:35:18 2019] Total swap = 0kB
> [Mon Mar 25 23:35:18 2019] 2097012 pages RAM
> [Mon Mar 25 23:35:18 2019] 0 pages HighMem/MovableOnly
> [Mon Mar 25 23:35:18 2019] 62693 pages reserved
> [Mon Mar 25 23:35:18 2019] 4096 pages cma reserved
> [Mon Mar 25 23:35:18 2019] 0 pages hwpoisoned
>
> As far as I can tell from logs of memory usage (recording memcg and
> MemAvail stats every second), there are gigabytes of available (clean
> page cache) RAM at all times during these tests.
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (fixed in 5.2)
2019-04-29 22:34 ` WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (still on 5.0.10) Zygo Blaxell
@ 2020-02-04 3:16 ` Zygo Blaxell
0 siblings, 0 replies; 10+ messages in thread
From: Zygo Blaxell @ 2020-02-04 3:16 UTC (permalink / raw)
To: linux-btrfs
[-- Attachment #1: Type: text/plain, Size: 8979 bytes --]
On Mon, Apr 29, 2019 at 06:34:55PM -0400, Zygo Blaxell wrote:
> On Mon, Mar 25, 2019 at 10:50:28PM -0400, Zygo Blaxell wrote:
> > Running balance, rsync, and dedupe, I get kernel warnings every few
> > minutes on 5.0.4. No warnings on 5.0.3 under similar conditions.
> >
> > Mount options are: flushoncommit,space_cache=v2,compress=zstd.
> >
> > There are two different stacks on the warnings. This one comes from
> > btrfs balance:
> >
> > [Mon Mar 25 18:22:42 2019] WARNING: CPU: 0 PID: 4786 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
> > [Mon Mar 25 18:22:42 2019] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
> > [Mon Mar 25 18:22:42 2019] CPU: 0 PID: 4786 Comm: btrfs-balance Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
> > [Mon Mar 25 18:22:42 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > [Mon Mar 25 18:22:42 2019] RIP: 0010:btrfs_merge_delayed_refs+0x3dc/0x410
> > [Mon Mar 25 18:22:42 2019] Code: 7c 24 28 be ff ff ff ff e8 31 a0 c1 ff 85 c0 0f 85 7c fe ff ff 0f 0b e9 75 fe ff ff 0f 0b e9 0a fe ff ff 0f 0b e9 1b fe ff ff <0f> 0b e9 25 ff ff ff 0f 0b e9 b0 fe ff ff 48 c7 44 24 10 00 00 00
> > [Mon Mar 25 18:22:42 2019] RSP: 0018:ffffabb981377b70 EFLAGS: 00010246
> > [Mon Mar 25 18:22:42 2019] RAX: 00000000000000b6 RBX: 00000000ffffffff RCX: 0000000000000001
> > [Mon Mar 25 18:22:42 2019] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000282
> > [Mon Mar 25 18:22:42 2019] RBP: ffff9392514bbb80 R08: ffff9392514bbc80 R09: 0000000000000000
> > [Mon Mar 25 18:22:42 2019] R10: 0000000000000000 R11: 0000000000000001 R12: ffff93928a5c8f08
> > [Mon Mar 25 18:22:42 2019] R13: ffff939269744e38 R14: ffff939269744e38 R15: ffff9392697449c0
> > [Mon Mar 25 18:22:42 2019] FS: 0000000000000000(0000) GS:ffff939475c00000(0000) knlGS:0000000000000000
> > [Mon Mar 25 18:22:42 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [Mon Mar 25 18:22:42 2019] CR2: 00007f0882d38600 CR3: 0000000230eb6002 CR4: 00000000001606f0
> > [Mon Mar 25 18:22:42 2019] Call Trace:
> > [Mon Mar 25 18:22:42 2019] __btrfs_run_delayed_refs+0x70/0x170
> > [Mon Mar 25 18:22:42 2019] btrfs_run_delayed_refs+0x7d/0x1d0
> > [Mon Mar 25 18:22:42 2019] btrfs_commit_transaction+0x50/0x9e0
> > [Mon Mar 25 18:22:42 2019] ? start_transaction+0x91/0x4d0
> > [Mon Mar 25 18:22:42 2019] relocate_block_group+0x1bd/0x600
> > [Mon Mar 25 18:22:42 2019] btrfs_relocate_block_group+0x15b/0x260
> > [Mon Mar 25 18:22:42 2019] btrfs_relocate_chunk+0x46/0xf0
> > [Mon Mar 25 18:22:42 2019] btrfs_balance+0xa60/0x12b0
> > [Mon Mar 25 18:22:42 2019] balance_kthread+0x36/0x50
> > [Mon Mar 25 18:22:42 2019] kthread+0x106/0x140
> > [Mon Mar 25 18:22:42 2019] ? btrfs_balance+0x12b0/0x12b0
> > [Mon Mar 25 18:22:42 2019] ? kthread_park+0x90/0x90
> > [Mon Mar 25 18:22:42 2019] ret_from_fork+0x3a/0x50
> > [Mon Mar 25 18:22:42 2019] irq event stamp: 81529004
> > [Mon Mar 25 18:22:42 2019] hardirqs last enabled at (81529003): [<ffffffffaa2be2b7>] kmem_cache_free+0x67/0x1e0
> > [Mon Mar 25 18:22:42 2019] hardirqs last disabled at (81529004): [<ffffffffaa00379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> > [Mon Mar 25 18:22:42 2019] softirqs last enabled at (81527500): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
> > [Mon Mar 25 18:22:42 2019] softirqs last disabled at (81527493): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
> > [Mon Mar 25 18:22:42 2019] ---[ end trace 3d8cdfff7444099a ]---
> >
> > This one comes from btrfs-transaction:
> >
> > [Mon Mar 25 18:27:58 2019] WARNING: CPU: 3 PID: 4137 at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410
> > [Mon Mar 25 18:27:58 2019] Modules linked in: ppdev joydev crct10dif_pclmul crc32_pclmul dm_cache_smq crc32c_intel ghash_clmulni_intel dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod rtc_cmos floppy parport_pc parport aesni_intel sr_mod cdrom aes_x86_64 crypto_simd cryptd glue_helper sg ide_pci_generic piix ide_core evbug evdev bochs_drm i2c_piix4 input_leds psmouse serio_raw snd_pcm snd_timer snd soundcore pcspkr qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
> > [Mon Mar 25 18:27:58 2019] CPU: 3 PID: 4137 Comm: btrfs-transacti Tainted: G W 5.0.4-zb64-303ce93b05c9+ #1
> > [Mon Mar 25 18:27:58 2019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > [Mon Mar 25 18:27:58 2019] RIP: 0010:btrfs_merge_delayed_refs+0x3dc/0x410
> > [Mon Mar 25 18:27:58 2019] Code: 7c 24 28 be ff ff ff ff e8 31 a0 c1 ff 85 c0 0f 85 7c fe ff ff 0f 0b e9 75 fe ff ff 0f 0b e9 0a fe ff ff 0f 0b e9 1b fe ff ff <0f> 0b e9 25 ff ff ff 0f 0b e9 b0 fe ff ff 48 c7 44 24 10 00 00 00
> > [Mon Mar 25 18:27:58 2019] RSP: 0018:ffffabb9812f7d40 EFLAGS: 00010246
> > [Mon Mar 25 18:27:58 2019] RAX: 00000000000000b6 RBX: 00000000ffffffff RCX: 0000000000000001
> > [Mon Mar 25 18:27:58 2019] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000286
> > [Mon Mar 25 18:27:58 2019] RBP: ffff93925b187ce0 R08: ffff93925b187de0 R09: 0000000000000000
> > [Mon Mar 25 18:27:58 2019] R10: 0000000000000000 R11: 0000000000000001 R12: ffff93938b59d308
> > [Mon Mar 25 18:27:58 2019] R13: ffff9393a5d09820 R14: ffff9393a5d09820 R15: ffff939261978820
> > [Mon Mar 25 18:27:58 2019] FS: 0000000000000000(0000) GS:ffff939476800000(0000) knlGS:0000000000000000
> > [Mon Mar 25 18:27:58 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [Mon Mar 25 18:27:58 2019] CR2: 00007f91f6321c50 CR3: 00000001ef54e003 CR4: 00000000001606e0
> > [Mon Mar 25 18:27:58 2019] Call Trace:
> > [Mon Mar 25 18:27:58 2019] __btrfs_run_delayed_refs+0x70/0x170
> > [Mon Mar 25 18:27:58 2019] btrfs_run_delayed_refs+0x7d/0x1d0
> > [Mon Mar 25 18:27:58 2019] btrfs_commit_transaction+0x50/0x9e0
> > [Mon Mar 25 18:27:58 2019] ? start_transaction+0x91/0x4d0
> > [Mon Mar 25 18:27:58 2019] transaction_kthread+0x146/0x180
> > [Mon Mar 25 18:27:58 2019] kthread+0x106/0x140
> > [Mon Mar 25 18:27:58 2019] ? btrfs_cleanup_transaction+0x620/0x620
> > [Mon Mar 25 18:27:58 2019] ? kthread_park+0x90/0x90
> > [Mon Mar 25 18:27:58 2019] ret_from_fork+0x3a/0x50
> > [Mon Mar 25 18:27:58 2019] irq event stamp: 81665152
> > [Mon Mar 25 18:27:58 2019] hardirqs last enabled at (81665151): [<ffffffffaa2be2b7>] kmem_cache_free+0x67/0x1e0
> > [Mon Mar 25 18:27:58 2019] hardirqs last disabled at (81665152): [<ffffffffaa00379f>] trace_hardirqs_off_thunk+0x1a/0x1c
> > [Mon Mar 25 18:27:58 2019] softirqs last enabled at (81664580): [<ffffffffab0003a4>] __do_softirq+0x3a4/0x45f
> > [Mon Mar 25 18:27:58 2019] softirqs last disabled at (81664565): [<ffffffffaa0a3d24>] irq_exit+0xe4/0xf0
> > [Mon Mar 25 18:27:58 2019] ---[ end trace 3d8cdfff7444099c ]---
> >
> > Pausing the balance makes the warnings stop.
This warning appears in test runs on kernels 4.20.17, 5.0.21, 5.1.21
(and several kernels in between). It does not appear on 5.2.21, 5.3.18,
5.4.16, or 5.5.0.
I was never able to associate the warning with any bad behavior on 5.0,
which received the most testing and use of the affected kernels.
If you wrote the commit that fixed it somewhere between 5.1 and 5.2
(or possibly backported to stable from 5.3), thank you!
> After sorting out some unrelated issues with 5.0 kernels, these warnings
> are now the top of my list of unresolved 5.0 kernel issues. They are
> popping up more often: 31804 times over two machine-days. Too much
> spam for the kernel logs.
>
> This is the code surrounding the WARN_ON:
>
> static bool merge_ref(...
> {
> // ...
> drop_delayed_ref(trans, delayed_refs, head, next);
> ref->ref_mod += mod;
> if (ref->ref_mod == 0) {
> drop_delayed_ref(trans, delayed_refs, head, ref);
> done = true;
> } else {
> /*
> * Can't have multiples of the same ref on a tree block.
> */
> WARN_ON(ref->type == BTRFS_TREE_BLOCK_REF_KEY ||
> ref->type == BTRFS_SHARED_BLOCK_REF_KEY);
> }
> // ...
> }
>
> Should the warning be removed? If something bad was going to happen,
> I would have expected it to happen some time in the last month of
> stress-testing, but I can find no evidence of failure related to
> this warning.
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]
^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2020-02-04 3:16 UTC | newest]
Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-03-26 2:50 WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (new on 5.0.4, not in 5.0.3) Zygo Blaxell
2019-03-26 4:30 ` Zygo Blaxell
2019-03-26 8:42 ` Nikolay Borisov
2019-03-26 15:09 ` Zygo Blaxell
2019-03-26 15:13 ` Nikolay Borisov
2019-03-26 15:45 ` Zygo Blaxell
2019-03-26 15:30 ` BUG: workqueue lockup - pool cpus=0-3 flags=0x4 nice=0 stuck for 20915s! (on 4.20+) Zygo Blaxell
2019-05-15 20:27 ` btrfs + KASAN + SLAB + lvmcache + rsync + kernel 5.0 = page allocation failure and/or OOM kills (solved...ish) Zygo Blaxell
2019-04-29 22:34 ` WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (still on 5.0.10) Zygo Blaxell
2020-02-04 3:16 ` WARNING at fs/btrfs/delayed-ref.c:296 btrfs_merge_delayed_refs+0x3dc/0x410 (fixed in 5.2) Zygo Blaxell
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.