kernel BUG at fs/btrfs/ctree.c:3230!

kernel BUG at fs/btrfs/ctree.c:3230!

[Gregory Malloff]

Hello, 

After 7 days, BTRFS crashed again with the same error: 

[Tue Apr 23 21:59:40 2019] ------------[ cut here ]------------ 
[Tue Apr 23 21:59:40 2019] kernel BUG at fs/btrfs/ctree.c:3230! 
[Tue Apr 23 21:59:40 2019] invalid opcode: 0000 [#1] SMP PTI 
[Tue Apr 23 21:59:40 2019] CPU: 0 PID: 526 Comm: nfsd Not tainted 4.19.0-4-amd64 #1 Debian 4.19.28-2 
[Tue Apr 23 21:59:40 2019] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/17/2015 
[Tue Apr 23 21:59:40 2019] RIP: 0010:btrfs_set_item_key_safe+0x116/0x190 [btrfs] 
[Tue Apr 23 21:59:40 2019] Code: 48 8d 7c 24 17 48 89 44 24 20 0f b6 44 24 0e 88 44 24 1f 48 8b 44 24 06 48 89 44 24 17 e8 c2 f3 ff ff 85 c0 0f 8f 46 ff ff ff <0f> 0b 8d 43 ff 48 8d 74 24 06 4c 89 e7 b9 11 00 00 00 48 98 48 8d 
[Tue Apr 23 21:59:40 2019] RSP: 0018:ffffb23fc082f6a0 EFLAGS: 00010246 
[Tue Apr 23 21:59:40 2019] RAX: 0000000000000000 RBX: 000000000000008d RCX: 000000000c71b000 
[Tue Apr 23 21:59:40 2019] RDX: 000000000003996e RSI: ffffb23fc082f795 RDI: ffffb23fc082f6b7 
[Tue Apr 23 21:59:40 2019] RBP: ffff9e9ec6bc95b0 R08: 0000000000001000 R09: 0000000000004000 
[Tue Apr 23 21:59:40 2019] R10: 0000000000000000 R11: 00000000ffffffff R12: ffff9e9e90957000 
[Tue Apr 23 21:59:40 2019] R13: ffffb23fc082f795 R14: 0000000000000000 R15: 000000000d007000 
[Tue Apr 23 21:59:40 2019] FS: 0000000000000000(0000) GS:ffff9e9efda00000(0000) knlGS:0000000000000000 
[Tue Apr 23 21:59:40 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 
[Tue Apr 23 21:59:40 2019] CR2: 00007f8bddd7fae4 CR3: 00000000735de000 CR4: 00000000000406f0 
[Tue Apr 23 21:59:40 2019] Call Trace: 
[Tue Apr 23 21:59:40 2019] __btrfs_drop_extents+0x7ae/0xcf0 [btrfs] 
[Tue Apr 23 21:59:40 2019] btrfs_log_changed_extents.isra.24+0x391/0x990 [btrfs] 
[Tue Apr 23 21:59:40 2019] btrfs_log_inode+0xb54/0x1240 [btrfs] 
[Tue Apr 23 21:59:40 2019] ? __schedule+0x2aa/0x870 
[Tue Apr 23 21:59:40 2019] ? __switch_to_asm+0x34/0x70 
[Tue Apr 23 21:59:40 2019] btrfs_log_inode_parent+0x2a1/0xac0 [btrfs] 
[Tue Apr 23 21:59:40 2019] ? wait_current_trans+0x2f/0xf0 [btrfs] 
[Tue Apr 23 21:59:40 2019] ? refcount_inc_checked+0x5/0x30 
[Tue Apr 23 21:59:40 2019] ? join_transaction+0xec/0x410 [btrfs] 
[Tue Apr 23 21:59:40 2019] btrfs_log_dentry_safe+0x4a/0x70 [btrfs] 
[Tue Apr 23 21:59:40 2019] btrfs_sync_file+0x1cb/0x3d0 [btrfs] 
[Tue Apr 23 21:59:40 2019] btrfs_file_write_iter+0x495/0x590 [btrfs] 
[Tue Apr 23 21:59:40 2019] ? apparmor_cred_prepare+0x4c/0x60 
[Tue Apr 23 21:59:40 2019] do_iter_readv_writev+0x13a/0x1b0 
[Tue Apr 23 21:59:40 2019] do_iter_write+0x80/0x190 
[Tue Apr 23 21:59:40 2019] nfsd_vfs_write+0xe6/0x450 [nfsd] 
[Tue Apr 23 21:59:40 2019] ? do_dentry_open+0xd1/0x330 
[Tue Apr 23 21:59:40 2019] nfsd_write+0x88/0x170 [nfsd] 
[Tue Apr 23 21:59:40 2019] ? _cond_resched+0x15/0x30 
[Tue Apr 23 21:59:40 2019] nfsd3_proc_write+0xc3/0x170 [nfsd] 
[Tue Apr 23 21:59:40 2019] nfsd_dispatch+0x9e/0x210 [nfsd] 
[Tue Apr 23 21:59:40 2019] svc_process_common+0x4a5/0x720 [sunrpc] 
[Tue Apr 23 21:59:40 2019] ? nfsd_destroy+0x50/0x50 [nfsd] 
[Tue Apr 23 21:59:40 2019] svc_process+0xb7/0xf0 [sunrpc] 
[Tue Apr 23 21:59:40 2019] nfsd+0xe3/0x140 [nfsd] 
[Tue Apr 23 21:59:40 2019] kthread+0x112/0x130 
[Tue Apr 23 21:59:40 2019] ? kthread_bind+0x30/0x30 
[Tue Apr 23 21:59:40 2019] ret_from_fork+0x35/0x40 
[Tue Apr 23 21:59:40 2019] Modules linked in: vmw_vsock_vmci_transport vsock coretemp crct10dif_pclmul crc32_pclmul vmwgfx ttm ghash_clmulni_intel ppdev drm_kms_helper vmw_balloon intel_rapl_perf joydev evdev drm pcspkr serio_raw sg vmw_vmci parport_pc parport button ac nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto ecb btrfs xor zstd_decompress zstd_compress xxhash raid6_pq libcrc32c crc32c_generic sd_mod sr_mod cdrom ata_generic crc32c_intel aesni_intel aes_x86_64 crypto_simd cryptd glue_helper psmouse ata_piix mptspi mptscsih mptbase libata vmxnet3 scsi_transport_spi scsi_mod i2c_piix4 floppy 
[Tue Apr 23 21:59:40 2019] ---[ end trace 9153b7dc6f042f19 ]--- 
[Tue Apr 23 21:59:40 2019] RIP: 0010:btrfs_set_item_key_safe+0x116/0x190 [btrfs] 
[Tue Apr 23 21:59:40 2019] Code: 48 8d 7c 24 17 48 89 44 24 20 0f b6 44 24 0e 88 44 24 1f 48 8b 44 24 06 48 89 44 24 17 e8 c2 f3 ff ff 85 c0 0f 8f 46 ff ff ff <0f> 0b 8d 43 ff 48 8d 74 24 06 4c 89 e7 b9 11 00 00 00 48 98 48 8d 
[Tue Apr 23 21:59:40 2019] RSP: 0018:ffffb23fc082f6a0 EFLAGS: 00010246 
[Tue Apr 23 21:59:40 2019] RAX: 0000000000000000 RBX: 000000000000008d RCX: 000000000c71b000 
[Tue Apr 23 21:59:40 2019] RDX: 000000000003996e RSI: ffffb23fc082f795 RDI: ffffb23fc082f6b7 
[Tue Apr 23 21:59:40 2019] RBP: ffff9e9ec6bc95b0 R08: 0000000000001000 R09: 0000000000004000 
[Tue Apr 23 21:59:40 2019] R10: 0000000000000000 R11: 00000000ffffffff R12: ffff9e9e90957000 
[Tue Apr 23 21:59:40 2019] R13: ffffb23fc082f795 R14: 0000000000000000 R15: 000000000d007000 
[Tue Apr 23 21:59:40 2019] FS: 0000000000000000(0000) GS:ffff9e9efda00000(0000) knlGS:0000000000000000 
[Tue Apr 23 21:59:40 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 
[Tue Apr 23 21:59:40 2019] CR2: 00007f8bddd7fae4 CR3: 00000000735de000 CR4: 00000000000406f0 
[05:24 AM] root@nas-201-b:~> uptime 
05:24:56 up 7 days, 15:05, 1 user, load average: 16.07, 16.03, 15.85 

Please let me know if you need any other details to help me resolve this issue. 

----- Original Message -----

From: "Gregory Malloff" <gregory.malloff@silvernetworks.ca> 
To: linux-btrfs@vger.kernel.org 
Sent: Tuesday, April 16, 2019 12:53:20 PM 
Subject: kernel BUG at fs/btrfs/ctree.c:3230! 


Hello, 

Problem: On a Debian 9 or 10 system with an NFS share and heavy I/O, about every 5 days or so, I get the following: 

http://cwillu.com:8080/207.102.58.55 

4,1352,538395169676,-;------------[ cut here ]------------ 
2,1353,538395169680,-;kernel BUG at fs/btrfs/ctree.c:3230! 
4,1354,538395169742,-;invalid opcode: 0000 [#1] SMP PTI 
4,1355,538395169767,-;CPU: 0 PID: 859 Comm: nfsd Not tainted 4.19.0-4-amd64 #1 Debian 4.19.28-2 
4,1356,538395169802,-;Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/17/2015 
4,1357,538395169884,-;RIP: 0010:btrfs_set_item_key_safe+0x116/0x190 [btrfs] 
4,1358,538395169921,-;Code: 48 8d 7c 24 17 48 89 44 24 20 0f b6 44 24 0e 88 44 24 1f 48 8b 44 24 06 48 89 44 24 17 e8 c2 f3 ff ff 85 c0 0f 8f 46 ff ff ff <0f> 0b 8d 43 ff 48 8d 74 24 06 4c 89 e7 b9 11 00 00 00 48 98 48 8d 
4,1359,538395170000,-;RSP: 0018:ffffc08a41fbf6a0 EFLAGS: 00010246 
4,1360,538395171003,-;RAX: 0000000000000000 RBX: 000000000000008f RCX: 000000005baa2000 
4,1361,538395171948,-;RDX: 0000000000031b05 RSI: ffffc08a41fbf795 RDI: ffffc08a41fbf6b7 
4,1362,538395172882,-;RBP: ffff9d6b33ef3460 R08: 0000000000001000 R09: 0000000000004000 
4,1363,538395173774,-;R10: 0000000000000000 R11: 00000000ffffffff R12: ffff9d6c5a788c08 
4,1364,538395174713,-;R13: ffffc08a41fbf795 R14: 0000000000000000 R15: 000000005c01a000 
4,1365,538395175761,-;FS: 0000000000000000(0000) GS:ffff9d6cb7a00000(0000) knlGS:0000000000000000 
4,1366,538395176716,-;CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 
4,1367,538395177582,-;CR2: 00007ffe8161dbe8 CR3: 000000022b3fa000 CR4: 00000000000406f0 
4,1368,538395178523,-;Call Trace: 
4,1369,538395179418,-; __btrfs_drop_extents+0x7ae/0xcf0 [btrfs] 
4,1370,538395180296,-; btrfs_log_changed_extents.isra.24+0x391/0x990 [btrfs] 
4,1371,538395181233,-; btrfs_log_inode+0xb54/0x1240 [btrfs] 
4,1372,538395182096,-; ? __kprobes_text_end+0xe5c68/0xe5c68 
4,1373,538395182930,-; ? __switch_to_asm+0x34/0x70 
4,1374,538395183747,-; ? __switch_to_asm+0x40/0x70 
4,1375,538395184542,-; ? __switch_to_asm+0x34/0x70 
4,1376,538395185320,-; ? __switch_to_asm+0x34/0x70 
4,1377,538395186078,-; ? __switch_to_asm+0x40/0x70 
4,1378,538395186859,-; btrfs_log_inode_parent+0x2a1/0xac0 [btrfs] 
4,1379,538395187644,-; ? wait_current_trans+0x2f/0xf0 [btrfs] 
4,1380,538395188379,-; ? refcount_inc_checked+0x5/0x30 
4,1381,538395189254,-; ? join_transaction+0xec/0x410 [btrfs] 
4,1382,538395190159,-; btrfs_log_dentry_safe+0x4a/0x70 [btrfs] 
4,1383,538395190901,-; btrfs_sync_file+0x1cb/0x3d0 [btrfs] 
4,1384,538395191826,-; btrfs_file_write_iter+0x495/0x590 [btrfs] 
4,1385,538395192631,-; ? apparmor_cred_prepare+0x4c/0x60 
4,1386,538395193334,-; do_iter_readv_writev+0x13a/0x1b0 
4,1387,538395195201,-; do_iter_write+0x80/0x190 
4,1388,538395195877,-; nfsd_vfs_write+0xe6/0x450 [nfsd] 
4,1389,538395196537,-; ? do_dentry_open+0xd1/0x330 
4,1390,538395197182,-; nfsd_write+0x88/0x170 [nfsd] 
4,1391,538395197785,-; ? _cond_resched+0x15/0x30 
4,1392,538395198386,-; nfsd3_proc_write+0xc3/0x170 [nfsd] 
4,1393,538395198980,-; nfsd_dispatch+0x9e/0x210 [nfsd] 
4,1394,538395199561,-; svc_process_common+0x4a5/0x720 [sunrpc] 
4,1395,538395200128,-; ? nfsd_destroy+0x50/0x50 [nfsd] 
4,1396,538395200682,-; svc_process+0xb7/0xf0 [sunrpc] 
4,1397,538395201219,-; nfsd+0xe3/0x140 [nfsd] 
4,1398,538395201742,-; kthread+0x112/0x130 
4,1399,538395202263,-; ? kthread_bind+0x30/0x30 
4,1400,538395202776,-; ret_from_fork+0x35/0x40 
4,1401,538395203296,-;Modules linked in: vmw_vsock_vmci_transport vsock coretemp crct10dif_pclmul crc32_pclmul vmwgfx vmw_balloon ttm ghash_clmulni_intel ppdev drm_kms_helper intel_rapl_perf joydev pcspkr serio_raw drm sg vmw_vmci evdev parport_pc parport button ac nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto ecb btrfs xor zstd_decompress zstd_compress xxhash raid6_pq libcrc32c crc32c_generic sd_mod sr_mod cdrom ata_generic crc32c_intel aesni_intel aes_x86_64 crypto_simd cryptd glue_helper psmouse mptspi mptscsih ata_piix mptbase scsi_transport_spi libata scsi_mod vmxnet3 i2c_piix4 floppy 
4,1402,538395207304,-;---[ end trace 4eda186227cc8ba6 ]--- 

#uname -a 
Linux nas-201-b 4.19.0-4-amd64 #1 SMP Debian 4.19.28-2 (2019-03-15) x86_64 GNU/Linux 

#btrfs --version 
btrfs-progs v4.20.1 

#btrfs fi show 
Label: none uuid: 1388dd44-f704-42bd-bdfd-95f2b43af671 
Total devices 1 FS bytes used 2.95TiB 
devid 1 size 5.00TiB used 3.35TiB path /dev/sdb 

#btrfs fi df /data 
Data, single: total=3.33TiB, used=2.94TiB 
System, DUP: total=40.00MiB, used=416.00KiB 
Metadata, DUP: total=10.00GiB, used=7.21GiB 
GlobalReserve, single: total=512.00MiB, used=0.00B 

#btrfs check --readonly /dev/sdb 
Opening filesystem to check... 
Checking filesystem on /dev/sdb 
UUID: 1388dd44-f704-42bd-bdfd-95f2b43af671 
[1/7] checking root items 
[2/7] checking extents 
[3/7] checking free space cache 
[4/7] checking fs roots 
[5/7] checking only csums items (without verifying data) 
[6/7] checking root refs 
[7/7] checking quota groups skipped (not enabled on this FS) 
found 3244857946112 bytes used, no error found 
total csum bytes: 3160375372 
total tree bytes: 7738867712 
total fs tree bytes: 2187886592 
total extent tree bytes: 1546764288 
btree space waste bytes: 1368283474 
file data blocks allocated: 6333316149248 
referenced 6330266890240 

#btrfs scrub start /data 
scrub started on /data, fsid 1388dd44-f704-42bd-bdfd-95f2b43af671 (pid=887) 

#btrfs scrub status /data 
scrub status for 1388dd44-f704-42bd-bdfd-95f2b43af671 
scrub started at Tue Apr 16 11:06:49 2019 and finished after 01:27:55 
total bytes scrubbed: 2.96TiB with 0 errors 

#btrfs device stats /data 
[/dev/sdb].write_io_errs 0 
[/dev/sdb].read_io_errs 0 
[/dev/sdb].flush_io_errs 0 
[/dev/sdb].corruption_errs 0 
[/dev/sdb].generation_errs 0 

[dmesg.log file attached] 

Cheers, 
Greg 

Re: kernel BUG at fs/btrfs/ctree.c:3230!

[Qu Wenruo]

[-- Attachment #1.1: Type: text/plain, Size: 12508 bytes --]



On 2019/4/24 下午8:28, Gregory Malloff wrote:
> 
> Hello, 
> 
> After 7 days, BTRFS crashed again with the same error: 
> 
> [Tue Apr 23 21:59:40 2019] ------------[ cut here ]------------ 
> [Tue Apr 23 21:59:40 2019] kernel BUG at fs/btrfs/ctree.c:3230! 
> [Tue Apr 23 21:59:40 2019] invalid opcode: 0000 [#1] SMP PTI 
> [Tue Apr 23 21:59:40 2019] CPU: 0 PID: 526 Comm: nfsd Not tainted 4.19.0-4-amd64 #1 Debian 4.19.28-2 
> [Tue Apr 23 21:59:40 2019] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/17/2015 
> [Tue Apr 23 21:59:40 2019] RIP: 0010:btrfs_set_item_key_safe+0x116/0x190 [btrfs] 
> [Tue Apr 23 21:59:40 2019] Code: 48 8d 7c 24 17 48 89 44 24 20 0f b6 44 24 0e 88 44 24 1f 48 8b 44 24 06 48 89 44 24 17 e8 c2 f3 ff ff 85 c0 0f 8f 46 ff ff ff <0f> 0b 8d 43 ff 48 8d 74 24 06 4c 89 e7 b9 11 00 00 00 48 98 48 8d 
> [Tue Apr 23 21:59:40 2019] RSP: 0018:ffffb23fc082f6a0 EFLAGS: 00010246 
> [Tue Apr 23 21:59:40 2019] RAX: 0000000000000000 RBX: 000000000000008d RCX: 000000000c71b000 
> [Tue Apr 23 21:59:40 2019] RDX: 000000000003996e RSI: ffffb23fc082f795 RDI: ffffb23fc082f6b7 
> [Tue Apr 23 21:59:40 2019] RBP: ffff9e9ec6bc95b0 R08: 0000000000001000 R09: 0000000000004000 
> [Tue Apr 23 21:59:40 2019] R10: 0000000000000000 R11: 00000000ffffffff R12: ffff9e9e90957000 
> [Tue Apr 23 21:59:40 2019] R13: ffffb23fc082f795 R14: 0000000000000000 R15: 000000000d007000 
> [Tue Apr 23 21:59:40 2019] FS: 0000000000000000(0000) GS:ffff9e9efda00000(0000) knlGS:0000000000000000 
> [Tue Apr 23 21:59:40 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 
> [Tue Apr 23 21:59:40 2019] CR2: 00007f8bddd7fae4 CR3: 00000000735de000 CR4: 00000000000406f0 
> [Tue Apr 23 21:59:40 2019] Call Trace: 
> [Tue Apr 23 21:59:40 2019] __btrfs_drop_extents+0x7ae/0xcf0 [btrfs] 
> [Tue Apr 23 21:59:40 2019] btrfs_log_changed_extents.isra.24+0x391/0x990 [btrfs] 
> [Tue Apr 23 21:59:40 2019] btrfs_log_inode+0xb54/0x1240 [btrfs] 
> [Tue Apr 23 21:59:40 2019] ? __schedule+0x2aa/0x870 
> [Tue Apr 23 21:59:40 2019] ? __switch_to_asm+0x34/0x70 
> [Tue Apr 23 21:59:40 2019] btrfs_log_inode_parent+0x2a1/0xac0 [btrfs] 
> [Tue Apr 23 21:59:40 2019] ? wait_current_trans+0x2f/0xf0 [btrfs] 
> [Tue Apr 23 21:59:40 2019] ? refcount_inc_checked+0x5/0x30 
> [Tue Apr 23 21:59:40 2019] ? join_transaction+0xec/0x410 [btrfs] 
> [Tue Apr 23 21:59:40 2019] btrfs_log_dentry_safe+0x4a/0x70 [btrfs] 
> [Tue Apr 23 21:59:40 2019] btrfs_sync_file+0x1cb/0x3d0 [btrfs] 
> [Tue Apr 23 21:59:40 2019] btrfs_file_write_iter+0x495/0x590 [btrfs] 
> [Tue Apr 23 21:59:40 2019] ? apparmor_cred_prepare+0x4c/0x60 
> [Tue Apr 23 21:59:40 2019] do_iter_readv_writev+0x13a/0x1b0 
> [Tue Apr 23 21:59:40 2019] do_iter_write+0x80/0x190 
> [Tue Apr 23 21:59:40 2019] nfsd_vfs_write+0xe6/0x450 [nfsd] 
> [Tue Apr 23 21:59:40 2019] ? do_dentry_open+0xd1/0x330 
> [Tue Apr 23 21:59:40 2019] nfsd_write+0x88/0x170 [nfsd] 
> [Tue Apr 23 21:59:40 2019] ? _cond_resched+0x15/0x30 
> [Tue Apr 23 21:59:40 2019] nfsd3_proc_write+0xc3/0x170 [nfsd] 
> [Tue Apr 23 21:59:40 2019] nfsd_dispatch+0x9e/0x210 [nfsd] 
> [Tue Apr 23 21:59:40 2019] svc_process_common+0x4a5/0x720 [sunrpc] 
> [Tue Apr 23 21:59:40 2019] ? nfsd_destroy+0x50/0x50 [nfsd] 
> [Tue Apr 23 21:59:40 2019] svc_process+0xb7/0xf0 [sunrpc] 
> [Tue Apr 23 21:59:40 2019] nfsd+0xe3/0x140 [nfsd] 
> [Tue Apr 23 21:59:40 2019] kthread+0x112/0x130 
> [Tue Apr 23 21:59:40 2019] ? kthread_bind+0x30/0x30 
> [Tue Apr 23 21:59:40 2019] ret_from_fork+0x35/0x40 
> [Tue Apr 23 21:59:40 2019] Modules linked in: vmw_vsock_vmci_transport vsock coretemp crct10dif_pclmul crc32_pclmul vmwgfx ttm ghash_clmulni_intel ppdev drm_kms_helper vmw_balloon intel_rapl_perf joydev evdev drm pcspkr serio_raw sg vmw_vmci parport_pc parport button ac nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto ecb btrfs xor zstd_decompress zstd_compress xxhash raid6_pq libcrc32c crc32c_generic sd_mod sr_mod cdrom ata_generic crc32c_intel aesni_intel aes_x86_64 crypto_simd cryptd glue_helper psmouse ata_piix mptspi mptscsih mptbase libata vmxnet3 scsi_transport_spi scsi_mod i2c_piix4 floppy 
> [Tue Apr 23 21:59:40 2019] ---[ end trace 9153b7dc6f042f19 ]--- 
> [Tue Apr 23 21:59:40 2019] RIP: 0010:btrfs_set_item_key_safe+0x116/0x190 [btrfs] 
> [Tue Apr 23 21:59:40 2019] Code: 48 8d 7c 24 17 48 89 44 24 20 0f b6 44 24 0e 88 44 24 1f 48 8b 44 24 06 48 89 44 24 17 e8 c2 f3 ff ff 85 c0 0f 8f 46 ff ff ff <0f> 0b 8d 43 ff 48 8d 74 24 06 4c 89 e7 b9 11 00 00 00 48 98 48 8d 
> [Tue Apr 23 21:59:40 2019] RSP: 0018:ffffb23fc082f6a0 EFLAGS: 00010246 
> [Tue Apr 23 21:59:40 2019] RAX: 0000000000000000 RBX: 000000000000008d RCX: 000000000c71b000 
> [Tue Apr 23 21:59:40 2019] RDX: 000000000003996e RSI: ffffb23fc082f795 RDI: ffffb23fc082f6b7 
> [Tue Apr 23 21:59:40 2019] RBP: ffff9e9ec6bc95b0 R08: 0000000000001000 R09: 0000000000004000 
> [Tue Apr 23 21:59:40 2019] R10: 0000000000000000 R11: 00000000ffffffff R12: ffff9e9e90957000 
> [Tue Apr 23 21:59:40 2019] R13: ffffb23fc082f795 R14: 0000000000000000 R15: 000000000d007000 
> [Tue Apr 23 21:59:40 2019] FS: 0000000000000000(0000) GS:ffff9e9efda00000(0000) knlGS:0000000000000000 
> [Tue Apr 23 21:59:40 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 
> [Tue Apr 23 21:59:40 2019] CR2: 00007f8bddd7fae4 CR3: 00000000735de000 CR4: 00000000000406f0 
> [05:24 AM] root@nas-201-b:~> uptime 
> 05:24:56 up 7 days, 15:05, 1 user, load average: 16.07, 16.03, 15.85 
> 
> Please let me know if you need any other details to help me resolve this issue. 

Not familiar with tree log code, but the following patch could provide
extra debug info:
https://patchwork.kernel.org/patch/10914687/

And, if your primary objective is to avoid such BUG_ON(), you can simply
disable tree log by "notreelog" mount option, if fsync() performance is
not your primary concern.

Thanks,
Qu

> 
> ----- Original Message -----
> 
> From: "Gregory Malloff" <gregory.malloff@silvernetworks.ca> 
> To: linux-btrfs@vger.kernel.org 
> Sent: Tuesday, April 16, 2019 12:53:20 PM 
> Subject: kernel BUG at fs/btrfs/ctree.c:3230! 
> 
> 
> Hello, 
> 
> Problem: On a Debian 9 or 10 system with an NFS share and heavy I/O, about every 5 days or so, I get the following: 
> 
> http://cwillu.com:8080/207.102.58.55 
> 
> 4,1352,538395169676,-;------------[ cut here ]------------ 
> 2,1353,538395169680,-;kernel BUG at fs/btrfs/ctree.c:3230! 
> 4,1354,538395169742,-;invalid opcode: 0000 [#1] SMP PTI 
> 4,1355,538395169767,-;CPU: 0 PID: 859 Comm: nfsd Not tainted 4.19.0-4-amd64 #1 Debian 4.19.28-2 
> 4,1356,538395169802,-;Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/17/2015 
> 4,1357,538395169884,-;RIP: 0010:btrfs_set_item_key_safe+0x116/0x190 [btrfs] 
> 4,1358,538395169921,-;Code: 48 8d 7c 24 17 48 89 44 24 20 0f b6 44 24 0e 88 44 24 1f 48 8b 44 24 06 48 89 44 24 17 e8 c2 f3 ff ff 85 c0 0f 8f 46 ff ff ff <0f> 0b 8d 43 ff 48 8d 74 24 06 4c 89 e7 b9 11 00 00 00 48 98 48 8d 
> 4,1359,538395170000,-;RSP: 0018:ffffc08a41fbf6a0 EFLAGS: 00010246 
> 4,1360,538395171003,-;RAX: 0000000000000000 RBX: 000000000000008f RCX: 000000005baa2000 
> 4,1361,538395171948,-;RDX: 0000000000031b05 RSI: ffffc08a41fbf795 RDI: ffffc08a41fbf6b7 
> 4,1362,538395172882,-;RBP: ffff9d6b33ef3460 R08: 0000000000001000 R09: 0000000000004000 
> 4,1363,538395173774,-;R10: 0000000000000000 R11: 00000000ffffffff R12: ffff9d6c5a788c08 
> 4,1364,538395174713,-;R13: ffffc08a41fbf795 R14: 0000000000000000 R15: 000000005c01a000 
> 4,1365,538395175761,-;FS: 0000000000000000(0000) GS:ffff9d6cb7a00000(0000) knlGS:0000000000000000 
> 4,1366,538395176716,-;CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 
> 4,1367,538395177582,-;CR2: 00007ffe8161dbe8 CR3: 000000022b3fa000 CR4: 00000000000406f0 
> 4,1368,538395178523,-;Call Trace: 
> 4,1369,538395179418,-; __btrfs_drop_extents+0x7ae/0xcf0 [btrfs] 
> 4,1370,538395180296,-; btrfs_log_changed_extents.isra.24+0x391/0x990 [btrfs] 
> 4,1371,538395181233,-; btrfs_log_inode+0xb54/0x1240 [btrfs] 
> 4,1372,538395182096,-; ? __kprobes_text_end+0xe5c68/0xe5c68 
> 4,1373,538395182930,-; ? __switch_to_asm+0x34/0x70 
> 4,1374,538395183747,-; ? __switch_to_asm+0x40/0x70 
> 4,1375,538395184542,-; ? __switch_to_asm+0x34/0x70 
> 4,1376,538395185320,-; ? __switch_to_asm+0x34/0x70 
> 4,1377,538395186078,-; ? __switch_to_asm+0x40/0x70 
> 4,1378,538395186859,-; btrfs_log_inode_parent+0x2a1/0xac0 [btrfs] 
> 4,1379,538395187644,-; ? wait_current_trans+0x2f/0xf0 [btrfs] 
> 4,1380,538395188379,-; ? refcount_inc_checked+0x5/0x30 
> 4,1381,538395189254,-; ? join_transaction+0xec/0x410 [btrfs] 
> 4,1382,538395190159,-; btrfs_log_dentry_safe+0x4a/0x70 [btrfs] 
> 4,1383,538395190901,-; btrfs_sync_file+0x1cb/0x3d0 [btrfs] 
> 4,1384,538395191826,-; btrfs_file_write_iter+0x495/0x590 [btrfs] 
> 4,1385,538395192631,-; ? apparmor_cred_prepare+0x4c/0x60 
> 4,1386,538395193334,-; do_iter_readv_writev+0x13a/0x1b0 
> 4,1387,538395195201,-; do_iter_write+0x80/0x190 
> 4,1388,538395195877,-; nfsd_vfs_write+0xe6/0x450 [nfsd] 
> 4,1389,538395196537,-; ? do_dentry_open+0xd1/0x330 
> 4,1390,538395197182,-; nfsd_write+0x88/0x170 [nfsd] 
> 4,1391,538395197785,-; ? _cond_resched+0x15/0x30 
> 4,1392,538395198386,-; nfsd3_proc_write+0xc3/0x170 [nfsd] 
> 4,1393,538395198980,-; nfsd_dispatch+0x9e/0x210 [nfsd] 
> 4,1394,538395199561,-; svc_process_common+0x4a5/0x720 [sunrpc] 
> 4,1395,538395200128,-; ? nfsd_destroy+0x50/0x50 [nfsd] 
> 4,1396,538395200682,-; svc_process+0xb7/0xf0 [sunrpc] 
> 4,1397,538395201219,-; nfsd+0xe3/0x140 [nfsd] 
> 4,1398,538395201742,-; kthread+0x112/0x130 
> 4,1399,538395202263,-; ? kthread_bind+0x30/0x30 
> 4,1400,538395202776,-; ret_from_fork+0x35/0x40 
> 4,1401,538395203296,-;Modules linked in: vmw_vsock_vmci_transport vsock coretemp crct10dif_pclmul crc32_pclmul vmwgfx vmw_balloon ttm ghash_clmulni_intel ppdev drm_kms_helper intel_rapl_perf joydev pcspkr serio_raw drm sg vmw_vmci evdev parport_pc parport button ac nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto ecb btrfs xor zstd_decompress zstd_compress xxhash raid6_pq libcrc32c crc32c_generic sd_mod sr_mod cdrom ata_generic crc32c_intel aesni_intel aes_x86_64 crypto_simd cryptd glue_helper psmouse mptspi mptscsih ata_piix mptbase scsi_transport_spi libata scsi_mod vmxnet3 i2c_piix4 floppy 
> 4,1402,538395207304,-;---[ end trace 4eda186227cc8ba6 ]--- 
> 
> #uname -a 
> Linux nas-201-b 4.19.0-4-amd64 #1 SMP Debian 4.19.28-2 (2019-03-15) x86_64 GNU/Linux 
> 
> #btrfs --version 
> btrfs-progs v4.20.1 
> 
> #btrfs fi show 
> Label: none uuid: 1388dd44-f704-42bd-bdfd-95f2b43af671 
> Total devices 1 FS bytes used 2.95TiB 
> devid 1 size 5.00TiB used 3.35TiB path /dev/sdb 
> 
> #btrfs fi df /data 
> Data, single: total=3.33TiB, used=2.94TiB 
> System, DUP: total=40.00MiB, used=416.00KiB 
> Metadata, DUP: total=10.00GiB, used=7.21GiB 
> GlobalReserve, single: total=512.00MiB, used=0.00B 
> 
> #btrfs check --readonly /dev/sdb 
> Opening filesystem to check... 
> Checking filesystem on /dev/sdb 
> UUID: 1388dd44-f704-42bd-bdfd-95f2b43af671 
> [1/7] checking root items 
> [2/7] checking extents 
> [3/7] checking free space cache 
> [4/7] checking fs roots 
> [5/7] checking only csums items (without verifying data) 
> [6/7] checking root refs 
> [7/7] checking quota groups skipped (not enabled on this FS) 
> found 3244857946112 bytes used, no error found 
> total csum bytes: 3160375372 
> total tree bytes: 7738867712 
> total fs tree bytes: 2187886592 
> total extent tree bytes: 1546764288 
> btree space waste bytes: 1368283474 
> file data blocks allocated: 6333316149248 
> referenced 6330266890240 
> 
> #btrfs scrub start /data 
> scrub started on /data, fsid 1388dd44-f704-42bd-bdfd-95f2b43af671 (pid=887) 
> 
> #btrfs scrub status /data 
> scrub status for 1388dd44-f704-42bd-bdfd-95f2b43af671 
> scrub started at Tue Apr 16 11:06:49 2019 and finished after 01:27:55 
> total bytes scrubbed: 2.96TiB with 0 errors 
> 
> #btrfs device stats /data 
> [/dev/sdb].write_io_errs 0 
> [/dev/sdb].read_io_errs 0 
> [/dev/sdb].flush_io_errs 0 
> [/dev/sdb].corruption_errs 0 
> [/dev/sdb].generation_errs 0 
> 
> [dmesg.log file attached] 
> 
> Cheers, 
> Greg 
> 


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]