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.
