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

From: Filipe Manana
Date: Mon Jan 23 2023 - 05:29:36 EST


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.


>
> [ 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
>