Re: [regression] Bug 216851 - btrfs write time corrupting for log tree

From: David Arendt
Date: Mon Jan 30 2023 - 16:07:26 EST


On 1/23/23 23:14, Filipe Manana wrote:
On Mon, Jan 23, 2023 at 9:06 PM David Arendt <admin@xxxxxxxxx> wrote:
On 1/23/23 11:28, Filipe Manana wrote:
On Sun, Jan 22, 2023 at 3:53 PM David Arendt <admin@xxxxxxxxx> wrote:
On 1/10/23 22:12, David Arendt wrote:
Hi,

In 6.2-rc3 + your patches, the problem did not appear within 2 weeks. I
skipped rc4 and today I upgraded to 6.2-rc5 which should have to patches
included (or not ?). About one hour later, the filesystem turned again
read-only with the following kernel log entries:
Ok, so 6.2-rc5 has the first 5 patches of the patchset.
If the whole patchset fixed the problem for 2 weeks, then I think
there's only one thing left to test, which is to add patch 6 on top of
6.2-rc5:

https://lore.kernel.org/linux-btrfs/ff77f41924e197d99e62ef323f03467c87ef43a0.1673361215.git.fdmanana@xxxxxxxx/

Are you able to try that?

Thanks.
Hi,

I have applied this patch to 6.2-rc5 and within an hour of intensive
testing, I was not able to reproduce the bug, so I think this patch
probably resolves the bug.

I will continue running this configuration and will report back when any
problem arises.
Nice, thank you.
Please report back after a longer while, so the patch can be added to
stable, at least 6.1, since there's another report of the same issue
but only on 6.1 (like you).

Hi,

The system was now running stable for a week. From now on, I'm testing 6.2-rc6 + patch.

Thanks in advance,

David Arendt

Thanks,

David Arendt

[ 7611.406077] BTRFS critical (device sda2): corrupt leaf:
root=18446744073709551610 block=75971280896 slot=71, bad key order, prev
(484119 96 1358553) current (484119 96 1358532)
[ 7611.406087] BTRFS info (device sda2): leaf 75971280896 gen 5130699
total ptrs 105 free space 10909 owner 18446744073709551610
[ 7611.406090] item 0 key (484119 1 0) itemoff 16123 itemsize 160
[ 7611.406091] inode generation 45 size 2198 mode 40700
[ 7611.406093] item 1 key (484119 12 484118) itemoff 16097 itemsize 26
[ 7611.406094] item 2 key (484119 72 15) itemoff 16089 itemsize 8
[ 7611.406095] item 3 key (484119 72 20) itemoff 16081 itemsize 8
[ 7611.406097] item 4 key (484119 72 25) itemoff 16073 itemsize 8
[ 7611.406098] item 5 key (484119 72 30) itemoff 16065 itemsize 8
[ 7611.406099] item 6 key (484119 72 32630) itemoff 16057 itemsize 8
[ 7611.406100] item 7 key (484119 72 40332) itemoff 16049 itemsize 8
[ 7611.406101] item 8 key (484119 72 40335) itemoff 16041 itemsize 8
[ 7611.406102] item 9 key (484119 72 93630) itemoff 16033 itemsize 8
[ 7611.406104] item 10 key (484119 72 101741) itemoff 16025 itemsize 8
[ 7611.406105] item 11 key (484119 72 131485) itemoff 16017 itemsize 8
[ 7611.406106] item 12 key (484119 72 183799) itemoff 16009 itemsize 8
[ 7611.406108] item 13 key (484119 72 183801) itemoff 16001 itemsize 8
[ 7611.406109] item 14 key (484119 72 203038) itemoff 15993 itemsize 8
[ 7611.406110] item 15 key (484119 72 254997) itemoff 15985 itemsize 8
[ 7611.406111] item 16 key (484119 72 255172) itemoff 15977 itemsize 8
[ 7611.406112] item 17 key (484119 72 255208) itemoff 15969 itemsize 8
[ 7611.406113] item 18 key (484119 72 256848) itemoff 15961 itemsize 8
[ 7611.406115] item 19 key (484119 72 264839) itemoff 15953 itemsize 8
[ 7611.406116] item 20 key (484119 72 266090) itemoff 15945 itemsize 8
[ 7611.406117] item 21 key (484119 72 266976) itemoff 15937 itemsize 8
[ 7611.406118] item 22 key (484119 72 267056) itemoff 15929 itemsize 8
[ 7611.406120] item 23 key (484119 72 302340) itemoff 15921 itemsize 8
[ 7611.406121] item 24 key (484119 72 513980) itemoff 15913 itemsize 8
[ 7611.406122] item 25 key (484119 72 848319) itemoff 15905 itemsize 8
[ 7611.406123] item 26 key (484119 72 848845) itemoff 15897 itemsize 8
[ 7611.406124] item 27 key (484119 72 938962) itemoff 15889 itemsize 8
[ 7611.406125] item 28 key (484119 72 1001565) itemoff 15881 itemsize 8
[ 7611.406127] item 29 key (484119 72 1268172) itemoff 15873 itemsize 8
[ 7611.406128] item 30 key (484119 72 1298657) itemoff 15865 itemsize 8
[ 7611.406129] item 31 key (484119 72 1299762) itemoff 15857 itemsize 8
[ 7611.406130] item 32 key (484119 72 1336351) itemoff 15849 itemsize 8
[ 7611.406131] item 33 key (484119 72 1356235) itemoff 15841 itemsize 8
[ 7611.406133] item 34 key (484119 72 1356237) itemoff 15833 itemsize 8
[ 7611.406134] item 35 key (484119 72 1357416) itemoff 15825 itemsize 8
[ 7611.406135] item 36 key (484119 72 1357797) itemoff 15817 itemsize 8
[ 7611.406137] item 37 key (484119 72 1358273) itemoff 15809 itemsize 8
[ 7611.406138] item 38 key (484119 72 1358275) itemoff 15801 itemsize 8
[ 7611.406139] item 39 key (484119 72 1358278) itemoff 15793 itemsize 8
[ 7611.406141] item 40 key (484119 72 1358448) itemoff 15785 itemsize 8
[ 7611.406142] item 41 key (484119 72 1358449) itemoff 15777 itemsize 8
[ 7611.406143] item 42 key (484119 72 1358452) itemoff 15769 itemsize 8
[ 7611.406144] item 43 key (484119 72 1358453) itemoff 15761 itemsize 8
[ 7611.406145] item 44 key (484119 72 1358456) itemoff 15753 itemsize 8
[ 7611.406147] item 45 key (484119 72 1358457) itemoff 15745 itemsize 8
[ 7611.406148] item 46 key (484119 72 1358460) itemoff 15737 itemsize 8
[ 7611.406149] item 47 key (484119 72 1358461) itemoff 15729 itemsize 8
[ 7611.406150] item 48 key (484119 72 1358463) itemoff 15721 itemsize 8
[ 7611.406151] item 49 key (484119 72 1358469) itemoff 15713 itemsize 8
[ 7611.406153] item 50 key (484119 72 1358485) itemoff 15705 itemsize 8
[ 7611.406154] item 51 key (484119 72 1358486) itemoff 15697 itemsize 8
[ 7611.406155] item 52 key (484119 72 1358499) itemoff 15689 itemsize 8
[ 7611.406156] item 53 key (484119 72 1358502) itemoff 15681 itemsize 8
[ 7611.406157] item 54 key (484119 72 1358513) itemoff 15673 itemsize 8
[ 7611.406159] item 55 key (484119 72 1358514) itemoff 15665 itemsize 8
[ 7611.406160] item 56 key (484119 72 1358515) itemoff 15657 itemsize 8
[ 7611.406161] item 57 key (484119 72 1358516) itemoff 15649 itemsize 8
[ 7611.406162] item 58 key (484119 72 1358543) itemoff 15641 itemsize 8
[ 7611.406164] item 59 key (484119 72 1358546) itemoff 15633 itemsize 8
[ 7611.406165] item 60 key (484119 72 1358548) itemoff 15625 itemsize 8
[ 7611.406166] item 61 key (484119 72 1358552) itemoff 15617 itemsize 8
[ 7611.406167] item 62 key (484119 96 1358532) itemoff 15566 itemsize 51
[ 7611.406168] item 63 key (484119 96 1358534) itemoff 15508 itemsize 58
[ 7611.406170] item 64 key (484119 96 1358536) itemoff 15465 itemsize 43
[ 7611.406171] item 65 key (484119 96 1358541) itemoff 15431 itemsize 34
[ 7611.406172] item 66 key (484119 96 1358545) itemoff 15383 itemsize 48
[ 7611.406173] item 67 key (484119 96 1358549) itemoff 15330 itemsize 53
[ 7611.406174] item 68 key (484119 96 1358550) itemoff 15283 itemsize 47
[ 7611.406175] item 69 key (484119 96 1358551) itemoff 15234 itemsize 49
[ 7611.406177] item 70 key (484119 96 1358553) itemoff 15196 itemsize 38
[ 7611.406178] item 71 key (484119 96 1358532) itemoff 15145 itemsize 51
[ 7611.406179] item 72 key (484119 96 1358534) itemoff 15087 itemsize 58
[ 7611.406180] item 73 key (484119 96 1358536) itemoff 15044 itemsize 43
[ 7611.406181] item 74 key (484119 96 1358541) itemoff 15010 itemsize 34
[ 7611.406182] item 75 key (484119 96 1358545) itemoff 14962 itemsize 48
[ 7611.406184] item 76 key (484119 96 1358549) itemoff 14909 itemsize 53
[ 7611.406185] item 77 key (484119 96 1358550) itemoff 14862 itemsize 47
[ 7611.406186] item 78 key (484119 96 1358551) itemoff 14813 itemsize 49
[ 7611.406187] item 79 key (484119 96 1358553) itemoff 14775 itemsize 38
[ 7611.406188] item 80 key (484128 1 0) itemoff 14615 itemsize 160
[ 7611.406189] inode generation 45 size 98304 mode 100644
[ 7611.406190] item 81 key (484128 108 0) itemoff 14562 itemsize 53
[ 7611.406192] extent data disk bytenr 10745529716736 nr 65536
[ 7611.406193] extent data offset 0 nr 65536 ram 65536
[ 7611.406194] item 82 key (484129 1 0) itemoff 14402 itemsize 160
[ 7611.406195] inode generation 45 size 26214400 mode 100644
[ 7611.406196] item 83 key (484129 108 98304) itemoff 14349 itemsize 53
[ 7611.406197] extent data disk bytenr 10744232108032 nr 65536
[ 7611.406198] extent data offset 0 nr 65536 ram 65536
[ 7611.406198] item 84 key (484129 108 589824) itemoff 14296 itemsize 53
[ 7611.406200] extent data disk bytenr 10745529593856 nr 32768
[ 7611.406200] extent data offset 0 nr 32768 ram 32768
[ 7611.406201] item 85 key (484129 108 4685824) itemoff 14243
itemsize 53
[ 7611.406203] extent data disk bytenr 10744231481344 nr 32768
[ 7611.406203] extent data offset 0 nr 32768 ram 32768
[ 7611.406204] item 86 key (484129 108 11468800) itemoff 14190
itemsize 53
[ 7611.406205] extent data disk bytenr 10745067331584 nr 32768
[ 7611.406206] extent data offset 0 nr 32768 ram 32768
[ 7611.406207] item 87 key (484129 108 13139968) itemoff 14137
itemsize 53
[ 7611.406208] extent data disk bytenr 10745022545920 nr 32768
[ 7611.406209] extent data offset 0 nr 32768 ram 32768
[ 7611.406210] item 88 key (484129 108 13795328) itemoff 14084
itemsize 53
[ 7611.406211] extent data disk bytenr 10744891514880 nr 32768
[ 7611.406212] extent data offset 0 nr 32768 ram 32768
[ 7611.406213] item 89 key (484129 108 20185088) itemoff 14031
itemsize 53
[ 7611.406214] extent data disk bytenr 10745022578688 nr 32768
[ 7611.406215] extent data offset 0 nr 32768 ram 32768
[ 7611.406216] item 90 key (484129 108 22347776) itemoff 13978
itemsize 53
[ 7611.406217] extent data disk bytenr 10744205844480 nr 32768
[ 7611.406218] extent data offset 0 nr 32768 ram 32768
[ 7611.406218] item 91 key (484129 108 23429120) itemoff 13925
itemsize 53
[ 7611.406220] extent data disk bytenr 10745067364352 nr 32768
[ 7611.406220] extent data offset 0 nr 32768 ram 32768
[ 7611.406221] item 92 key (484129 108 24870912) itemoff 13872
itemsize 53
[ 7611.406222] extent data disk bytenr 10745022611456 nr 32768
[ 7611.406223] extent data offset 0 nr 32768 ram 32768
[ 7611.406224] item 93 key (484129 108 25001984) itemoff 13819
itemsize 53
[ 7611.406225] extent data disk bytenr 10745022709760 nr 32768
[ 7611.406226] extent data offset 0 nr 32768 ram 32768
[ 7611.406227] item 94 key (484129 108 25165824) itemoff 13766
itemsize 53
[ 7611.406228] extent data disk bytenr 10745022742528 nr 32768
[ 7611.406229] extent data offset 0 nr 32768 ram 32768
[ 7611.406230] item 95 key (484147 1 0) itemoff 13606 itemsize 160
[ 7611.406231] inode generation 45 size 886 mode 40755
[ 7611.406232] item 96 key (484147 72 4) itemoff 13598 itemsize 8
[ 7611.406233] item 97 key (484147 72 27) itemoff 13590 itemsize 8
[ 7611.406234] item 98 key (484147 72 35) itemoff 13582 itemsize 8
[ 7611.406235] item 99 key (484147 72 40) itemoff 13574 itemsize 8
[ 7611.406236] item 100 key (484147 72 45) itemoff 13566 itemsize 8
[ 7611.406238] item 101 key (484147 72 52) itemoff 13558 itemsize 8
[ 7611.406239] item 102 key (484147 72 61) itemoff 13550 itemsize 8
[ 7611.406240] item 103 key (484147 72 65) itemoff 13542 itemsize 8
[ 7611.406241] item 104 key (484147 72 88) itemoff 13534 itemsize 8
[ 7611.406242] BTRFS error (device sda2): block=75971280896 write time
tree block corruption detected
[ 7611.406255] ------------[ cut here ]------------
[ 7611.406256] WARNING: CPU: 5 PID: 32347 at fs/btrfs/disk-io.c:376
csum_one_extent_buffer+0x136/0x140
[ 7611.406261] Modules linked in: zfs(PO) zunicode(PO) zzstd(O) zlua(O)
zavl(PO) icp(PO) zcommon(PO) znvpair(PO) spl(O)
[ 7611.406270] CPU: 5 PID: 32347 Comm: mozStorage #2 Tainted: P
W O 6.2.0-rc5 #1
[ 7611.406272] Hardware name: ASUS All Series/H87M-PRO, BIOS 2102 10/28/2014
[ 7611.406273] RIP: 0010:csum_one_extent_buffer+0x136/0x140
[ 7611.406275] Code: 48 c1 e2 29 48 03 53 70 48 c1 fa 06 81 e1 ff 0f 00
00 48 c1 e2 0c 48 01 ca b9 11 ff ff 01 48 c1 e1 27 48 83 7c 0a 58 fa 75
98 <0f> 0b eb 94 66 0f 1f 44 00 00 90 90 90 90 90 90 90 90 90 90 90 90
[ 7611.406277] RSP: 0018:ffffc9000d803850 EFLAGS: 00010246
[ 7611.406279] RAX: 00000000ffffff8b RBX: ffff888411886200 RCX:
ffff888000000000
[ 7611.406280] RDX: 0000000479022000 RSI: 0000000000000001 RDI:
ffff8887fdd5b280
[ 7611.406282] RBP: ffff888102fa3000 R08: 00000000ffffdfff R09:
00000000ffffdfff
[ 7611.406283] R10: ffffffff82854220 R11: ffffffff82854220 R12:
ffff888102fa3000
[ 7611.406284] R13: 0000000000001000 R14: ffffea0011e40880 R15:
ffff888102fa3000
[ 7611.406285] FS: 00007f43d72986c0(0000) GS:ffff8887fdd40000(0000)
knlGS:0000000000000000
[ 7611.406287] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 7611.406288] CR2: 00007f246eb9e000 CR3: 000000040de5e005 CR4:
00000000001706e0
[ 7611.406289] Call Trace:
[ 7611.406291] <TASK>
[ 7611.406293] btree_csum_one_bio+0x220/0x2a0
[ 7611.406295] btrfs_submit_metadata_bio+0x84/0xc0
[ 7611.406297] submit_one_bio+0xbd/0x110
[ 7611.406300] btree_write_cache_pages+0x721/0x790
[ 7611.406303] ? __pfx_end_bio_extent_buffer_writepage+0x10/0x10
[ 7611.406306] ? btrfs_search_slot+0x8a5/0xc70
[ 7611.406309] do_writepages+0x99/0x180
[ 7611.406313] ? btrfs_read_extent_buffer+0x8a/0x130
[ 7611.406314] ? merge_state.part.0+0x41/0xf0
[ 7611.406317] filemap_fdatawrite_wbc+0x5a/0x80
[ 7611.406321] __filemap_fdatawrite_range+0x45/0x50
[ 7611.406323] btrfs_write_marked_extents+0x52/0x120
[ 7611.406326] btrfs_sync_log+0x1ce/0x9a0
[ 7611.406329] ? btrfs_unlock_up_safe+0x69/0xc0
[ 7611.406332] ? btrfs_search_forward+0x260/0x340
[ 7611.406334] ? log_new_dir_dentries.isra.0+0x36c/0x390
[ 7611.406335] ? __pfx_autoremove_wake_function+0x10/0x10
[ 7611.406339] ? log_new_dir_dentries.isra.0+0x36c/0x390
[ 7611.406340] ? btrfs_log_inode_parent+0x3e0/0xdf0
[ 7611.406342] ? pagevec_lookup_range_tag+0x1f/0x30
[ 7611.406345] ? __filemap_fdatawait_range+0x46/0xe0
[ 7611.406347] ? perf_event_exec+0xe0/0x310
[ 7611.406350] ? wait_current_trans+0x15/0xe0
[ 7611.406353] ? kmem_cache_alloc+0x226/0x380
[ 7611.406357] ? join_transaction+0x1b/0x3f0
[ 7611.406359] ? dput+0xaf/0x2d0
[ 7611.406361] btrfs_sync_file+0x31f/0x4e0
[ 7611.406364] __x64_sys_fsync+0x32/0x60
[ 7611.406367] do_syscall_64+0x42/0x90
[ 7611.406371] entry_SYSCALL_64_after_hwframe+0x72/0xdc
[ 7611.406375] RIP: 0033:0x7f440320651a
[ 7611.406377] Code: 48 3d 00 f0 ff ff 77 48 c3 0f 1f 80 00 00 00 00 48
83 ec 18 89 7c 24 0c e8 13 71 f8 ff 8b 7c 24 0c 89 c2 b8 4a 00 00 00 0f
05 <48> 3d 00 f0 ff ff 77 36 89 d7 89 44 24 0c e8 73 71 f8 ff 8b 44 24
[ 7611.406378] RSP: 002b:00007f43d7297170 EFLAGS: 00000293 ORIG_RAX:
000000000000004a
[ 7611.406381] RAX: ffffffffffffffda RBX: 00007f43ee222be8 RCX:
00007f440320651a
[ 7611.406382] RDX: 0000000000000000 RSI: 0000000000000000 RDI:
0000000000000090
[ 7611.406383] RBP: 0000000000000000 R08: 0000000000000000 R09:
00007f440255e000
[ 7611.406384] R10: 0000000000000000 R11: 0000000000000293 R12:
00007f43d63ed038
[ 7611.406385] R13: 0000000000000000 R14: 0000000000000002 R15:
0000000000000000
[ 7611.406387] </TASK>
[ 7611.406387] ---[ end trace 0000000000000000 ]---
[ 7611.459735] BTRFS error (device sda2: state AL): Transaction aborted
(error -5)
[ 7611.459742] BTRFS: error (device sda2: state AL) in
free_log_tree:3248: errno=-5 IO failure
[ 7611.459744] BTRFS info (device sda2: state EAL): forced readonly
[ 7611.463492] BTRFS warning (device sda2: state EAL): Skipping commit
of aborted transaction.
[ 7611.463498] BTRFS: error (device sda2: state EAL) in
cleanup_transaction:1984: errno=-5 IO failure

Thanks in advance,

David Arendt