On 2019/8/7 上午1:47, David Sterba wrote:
> On Tue, Aug 06, 2019 at 10:04:51PM +0800, Qu Wenruo wrote:
>>
>>
>> On 2019/8/6 下午9:58, David Sterba wrote:
>>> On Thu, Jul 25, 2019 at 02:12:20PM +0800, Qu Wenruo wrote:
>>>>
>>>> if (!first_key)
>>>> return 0;
>>>> + /* We have @first_key, so this @eb must have at least one item */
>>>> + if (btrfs_header_nritems(eb) == 0) {
>>>> + btrfs_err(fs_info,
>>>> + "invalid tree nritems, bytenr=%llu nritems=0 expect >0",
>>>> + eb->start);
>>>> + WARN_ON(IS_ENABLED(CONFIG_BTRFS_DEBUG));
>>>> + return -EUCLEAN;
>>>> + }
>>>
>>> generic/015 complains:
>>>
>>> generic/015 [13:51:40][ 5949.416657] run fstests generic/015 at
>>> 2019-08-06 13:51:40
>>
>> I hit this once, but not this test case.
>> The same backtrace for csum tree.
>>
>> Have you ever hit it again?
>
> Yes I found a few more occurences, the last one seems to be interesting so
> it's
> pasted as-is.
> Thanks for all the traces. Although they are all btrfs_search_slot(), I'm not sure if it's a unexposed a race or just false alert. Please discard that patch for now. I'll keep digging into the case. Thanks, Qu > generic/449 > > [21423.875017] read_block_for_search+0x144/0x380 [btrfs] > [21423.876433] btrfs_search_slot+0x297/0xfc0 [btrfs] > [21423.877830] ? btrfs_update_delayed_refs_rsv+0x59/0x70 [btrfs] > [21423.880038] btrfs_lookup_csum+0xa9/0x210 [btrfs] > [21423.881304] btrfs_csum_file_blocks+0x205/0x800 [btrfs] > [21423.882674] ? unpin_extent_cache+0x27/0xc0 [btrfs] > [21423.884050] add_pending_csums+0x50/0x70 [btrfs] > [21423.885285] btrfs_finish_ordered_io+0x403/0x7b0 [btrfs] > [21423.886781] ? _raw_spin_unlock_bh+0x30/0x40 > [21423.888164] normal_work_helper+0xe2/0x520 [btrfs] > [21423.889521] process_one_work+0x22f/0x5b0 > [21423.890332] worker_thread+0x50/0x3b0 > [21423.891001] ? process_one_work+0x5b0/0x5b0 > [21423.892025] kthread+0x11a/0x130 > > generic/511 > > [45857.582982] read_block_for_search+0x144/0x380 [btrfs] > [45857.584197] btrfs_search_slot+0x297/0xfc0 [btrfs] > [45857.585363] ? btrfs_update_delayed_refs_rsv+0x59/0x70 [btrfs] > [45857.586758] btrfs_lookup_csum+0xa9/0x210 [btrfs] > [45857.587919] btrfs_csum_file_blocks+0x205/0x800 [btrfs] > [45857.589023] ? unpin_extent_cache+0x27/0xc0 [btrfs] > [45857.590311] add_pending_csums+0x50/0x70 [btrfs] > [45857.591482] btrfs_finish_ordered_io+0x403/0x7b0 [btrfs] > [45857.592671] ? _raw_spin_unlock_bh+0x30/0x40 > [45857.593759] normal_work_helper+0xe2/0x520 [btrfs] > [45857.595274] process_one_work+0x22f/0x5b0 > [45857.596372] worker_thread+0x50/0x3b0 > [45857.597221] ? process_one_work+0x5b0/0x5b0 > [45857.598438] kthread+0x11a/0x130 > > generic/129 > > [ 7512.874839] BTRFS info (device vda): disk space caching is enabled > [ 7512.877660] BTRFS info (device vda): has skinny extents > [ 7512.951947] BTRFS: device fsid 815ae95d-a328-472d-8299-a373d67af54e devid > 1 transid 5 /dev/vdb > [ 7512.969169] BTRFS info (device vdb): turning on discard > [ 7512.971138] BTRFS info (device vdb): disk space caching is enabled > [ 7512.973506] BTRFS info (device vdb): has skinny extents > [ 7512.975497] BTRFS info (device vdb): flagging fs with big metadata feature > [ 7513.005926] BTRFS info (device vdb): checking UUID tree > [ 7513.395115] ------------[ cut here ]------------ > [ 7513.395120] BTRFS error (device vdb): invalid tree nritems, > bytenr=30736384 nritems=0 expect >0 > [ 7513.395122] ------------[ cut here ]------------ > [ 7513.395124] BTRFS error (device vdb): invalid tree nritems, > bytenr=30736384 nritems=0 expect >0 > [ 7513.395125] ------------[ cut here ]------------ > [ 7513.395185] WARNING: CPU: 1 PID: 17085 at fs/btrfs/disk-io.c:417 > btrfs_verify_level_key.cold+0x1e/0x2b [btrfs] > [ 7513.395186] Modules linked in: dm_snapshot dm_bufio dm_log_writes > dm_flakey dm_mod btrfs libcrc32c xor zstd_decompress zstd_compress xxhash > raid6_pq loop af_packet [last unloaded: scsi_debug] > [ 7513.395193] CPU: 1 PID: 17085 Comm: kworker/u8:4 Tainted: G W > 5.3.0-rc3-next-20190806-default #5 > [ 7513.395194] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS > rel-1.12.1-0-ga5cab58-prebuilt.qemu.org 04/01/2014 > [ 7513.395212] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs] > [ 7513.395230] RIP: 0010:btrfs_verify_level_key.cold+0x1e/0x2b [btrfs] > [ 7513.395232] Code: ff ff e8 9f c8 ff ff e9 4d 58 f5 ff 48 8b 13 48 c7 c6 48 > 9c 48 c0 48 89 ef e8 88 c8 ff ff 48 c7 c7 c0 95 48 c0 e8 c0 e9 c6 df <0f> 0b > 41 be 8b ff ff ff e9 dd 5a f5 ff be e9 05 00 00 48 c7 c7 40 > [ 7513.395232] RSP: 0018:ffffab1286483ab8 EFLAGS: 00010246 > [ 7513.395233] RAX: 0000000000000024 RBX: ffff9d4f06a493b0 RCX: > 0000000000000001 > [ 7513.395234] RDX: 0000000000000000 RSI: 0000000000000001 RDI: > ffffffffa00d1ca8 > [ 7513.395235] RBP: ffff9d4f069d4000 R08: 0000000000000000 R09: > 0000000000000000 > [ 7513.395235] R10: 0000000000000000 R11: 0000000000000000 R12: > 0000000000000006 > [ 7513.395247] R13: ffffab1286483b6e R14: ffff9d4f2267aaf0 R15: > 0000000000000000 > [ 7513.395251] FS: 0000000000000000(0000) GS:ffff9d4f7d800000(0000) > knlGS:0000000000000000 > [ 7513.395252] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 7513.395253] CR2: 00007f5d921edef4 CR3: 0000000014011000 CR4: > 00000000000006e0 > [ 7513.395254] Call Trace: > [ 7513.395277] read_block_for_search.isra.0+0x13d/0x3d0 [btrfs] > [ 7513.395300] btrfs_search_slot+0x25d/0xc10 [btrfs] > [ 7513.395325] btrfs_lookup_csum+0x6a/0x160 [btrfs] > [ 7513.395330] ? kmem_cache_alloc+0x1f2/0x280 > [ 7513.395354] btrfs_csum_file_blocks+0x198/0x6f0 [btrfs] > [ 7513.395378] add_pending_csums+0x50/0x70 [btrfs] > [ 7513.395403] btrfs_finish_ordered_io+0x3cb/0x7f0 [btrfs] > [ 7513.395432] normal_work_helper+0xd1/0x540 [btrfs] > [ 7513.395437] process_one_work+0x22d/0x580 > [ 7513.395440] worker_thread+0x50/0x3b0 > [ 7513.395443] kthread+0xfe/0x140 > [ 7513.395446] ? process_one_work+0x580/0x580 > [ 7513.395447] ? kthread_park+0x80/0x80 > [ 7513.395452] ret_from_fork+0x24/0x30 > [ 7513.395454] irq event stamp: 0 > [ 7513.395457] hardirqs last enabled at (0): [<0000000000000000>] 0x0 > [ 7513.395461] hardirqs last disabled at (0): [<ffffffffa005ff00>] > copy_process+0x6d0/0x1ac0 > [ 7513.395463] softirqs last enabled at (0): [<ffffffffa005ff00>] > copy_process+0x6d0/0x1ac0 > [ 7513.395465] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 7513.395466] ---[ end trace f6f3adf90f4ea411 ]--- > [ 7513.395470] ------------[ cut here ]------------ > [ 7513.395471] BTRFS: Transaction aborted (error -117) > [ 7513.395528] WARNING: CPU: 1 PID: 17085 at fs/btrfs/inode.c:3175 > btrfs_finish_ordered_io+0x781/0x7f0 [btrfs] > [ 7513.395529] Modules linked in: dm_snapshot dm_bufio dm_log_writes > dm_flakey dm_mod btrfs libcrc32c xor zstd_decompress zstd_compress xxhash > raid6_pq loop af_packet [last unloaded: scsi_debug] > [ 7513.395540] CPU: 1 PID: 17085 Comm: kworker/u8:4 Tainted: G W > 5.3.0-rc3-next-20190806-default #5 > [ 7513.395542] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS > rel-1.12.1-0-ga5cab58-prebuilt.qemu.org 04/01/2014 > [ 7513.395570] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs] > [ 7513.395588] RIP: 0010:btrfs_finish_ordered_io+0x781/0x7f0 [btrfs] > [ 7513.395590] Code: e9 aa fc ff ff 49 8b 47 50 f0 48 0f ba a8 e8 33 00 00 02 > 72 17 41 83 fd fb 74 5b 44 89 ee 48 c7 c7 08 b4 48 c0 e8 22 55 c9 df <0f> 0b > 44 89 e9 ba 67 0c 00 00 eb b0 88 5c 24 10 41 89 de 41 bd fb > [ 7513.395592] RSP: 0018:ffffab1286483d90 EFLAGS: 00010286 > [ 7513.395593] RAX: 0000000000000000 RBX: 0000000000000001 RCX: > 0000000000000001 > [ 7513.395594] RDX: 0000000000000002 RSI: 0000000000000001 RDI: > ffffffffa00d1ca8 > [ 7513.395596] RBP: ffff9d4f573d8c80 R08: 0000000000000000 R09: > 0000000000000000 > [ 7513.395597] R10: 0000000000000000 R11: 0000000000000000 R12: > ffff9d4f06120e80 > [ 7513.395598] R13: 00000000ffffff8b R14: ffff9d4f03e85000 R15: > ffff9d4f57763750 > [ 7513.395603] FS: 0000000000000000(0000) GS:ffff9d4f7d800000(0000) > knlGS:0000000000000000 > [ 7513.395605] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 7513.395606] CR2: 00007f5d921edef4 CR3: 0000000014011000 CR4: > 00000000000006e0 > [ 7513.395607] Call Trace: > [ 7513.395638] normal_work_helper+0xd1/0x540 [btrfs] > [ 7513.395642] process_one_work+0x22d/0x580 > [ 7513.395645] worker_thread+0x50/0x3b0 > [ 7513.395648] kthread+0xfe/0x140 > [ 7513.395651] ? process_one_work+0x580/0x580 > [ 7513.395653] ? kthread_park+0x80/0x80 > [ 7513.395656] ret_from_fork+0x24/0x30 > [ 7513.395658] irq event stamp: 0 > [ 7513.395659] hardirqs last enabled at (0): [<0000000000000000>] 0x0 > [ 7513.395662] hardirqs last disabled at (0): [<ffffffffa005ff00>] > copy_process+0x6d0/0x1ac0 > [ 7513.395665] softirqs last enabled at (0): [<ffffffffa005ff00>] > copy_process+0x6d0/0x1ac0 > [ 7513.395666] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 7513.395668] ---[ end trace f6f3adf90f4ea412 ]--- > [ 7513.395671] BTRFS: error (device vdb) in btrfs_finish_ordered_io:3175: > errno=-117 unknown > [ 7513.395674] BTRFS info (device vdb): forced readonly > [ 7513.396527] WARNING: CPU: 3 PID: 2709 at fs/btrfs/disk-io.c:417 > btrfs_verify_level_key.cold+0x1e/0x2b [btrfs] > [ 7513.399117] WARNING: CPU: 2 PID: 29478 at fs/btrfs/disk-io.c:417 > btrfs_verify_level_key.cold+0x1e/0x2b [btrfs] > [ 7513.400326] Modules linked in: dm_snapshot dm_bufio dm_log_writes > dm_flakey dm_mod btrfs libcrc32c xor zstd_decompress zstd_compress xxhash > raid6_pq loop af_packet [last unloaded: scsi_debug] > [ 7513.402828] Modules linked in: dm_snapshot dm_bufio dm_log_writes > dm_flakey dm_mod btrfs libcrc32c xor zstd_decompress zstd_compress xxhash > raid6_pq loop af_packet [last unloaded: scsi_debug] > [ 7513.404136] CPU: 3 PID: 2709 Comm: kworker/u8:8 Tainted: G W > 5.3.0-rc3-next-20190806-default #5 > [ 7513.406553] CPU: 2 PID: 29478 Comm: kworker/u8:14 Tainted: G W > 5.3.0-rc3-next-20190806-default #5 > [ 7513.411174] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS > rel-1.12.1-0-ga5cab58-prebuilt.qemu.org 04/01/2014 > [ 7513.413441] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS > rel-1.12.1-0-ga5cab58-prebuilt.qemu.org 04/01/2014 > [ 7513.413464] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs] > [ 7513.415124] Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs] > [ 7513.416431] RIP: 0010:btrfs_verify_level_key.cold+0x1e/0x2b [btrfs] > [ 7513.416433] Code: ff ff e8 9f c8 ff ff e9 4d 58 f5 ff 48 8b 13 48 c7 c6 48 > 9c 48 c0 48 89 ef e8 88 c8 ff ff 48 c7 c7 c0 95 48 c0 e8 c0 e9 c6 df <0f> 0b > 41 be 8b ff ff ff e9 dd 5a f5 ff be e9 05 00 00 48 c7 c7 40 > [ 7513.417412] RIP: 0010:btrfs_verify_level_key.cold+0x1e/0x2b [btrfs] > [ 7513.420742] RSP: 0000:ffffab1283b83ab8 EFLAGS: 00010246 > [ 7513.421912] Code: ff ff e8 9f c8 ff ff e9 4d 58 f5 ff 48 8b 13 48 c7 c6 48 > 9c 48 c0 48 89 ef e8 88 c8 ff ff 48 c7 c7 c0 95 48 c0 e8 c0 e9 c6 df <0f> 0b > 41 be 8b ff ff ff e9 dd 5a f5 ff be e9 05 00 00 48 c7 c7 40 > [ 7513.423177] RAX: 0000000000000024 RBX: ffff9d4f06a493b0 RCX: > 0000000000000001 > [ 7513.423178] RDX: 0000000000000000 RSI: 0000000000000001 RDI: > ffffffffa00d040b > [ 7513.424570] RSP: 0018:ffffab1287043ab8 EFLAGS: 00010246 > [ 7513.426005] RBP: ffff9d4f069d4000 R08: 0000000000000000 R09: > 0000000000000000 > [ 7513.427876] RAX: 0000000000000024 RBX: ffff9d4f06a493b0 RCX: > 0000000000000001 > [ 7513.429411] R10: 0000000000000000 R11: 0000000000000000 R12: > 0000000000000006 > [ 7513.429412] R13: ffffab1283b83b6e R14: ffff9d4f47b27150 R15: > 0000000000000000 > [ 7513.430963] RDX: 0000000000000000 RSI: 0000000000000001 RDI: > ffffffffa00d040b > [ 7513.432092] FS: 0000000000000000(0000) GS:ffff9d4f7da00000(0000) > knlGS:0000000000000000 > [ 7513.433535] RBP: ffff9d4f069d4000 R08: 0000000000000000 R09: > 0000000000000000 > [ 7513.434145] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 7513.434146] CR2: 00007f907ab328e0 CR3: 000000007d2cb000 CR4: > 00000000000006e0 > [ 7513.435037] R10: 0000000000000000 R11: 0000000000000000 R12: > 0000000000000006 > [ 7513.435038] R13: ffffab1287043b6e R14: ffff9d4f61e75af0 R15: > 0000000000000000 > [ 7513.436009] Call Trace: > [ 7513.436973] FS: 0000000000000000(0000) GS:ffff9d4f7dc00000(0000) > knlGS:0000000000000000 > [ 7513.437892] read_block_for_search.isra.0+0x13d/0x3d0 [btrfs] > [ 7513.438806] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 7513.439932] btrfs_search_slot+0x25d/0xc10 [btrfs] > [ 7513.441229] CR2: 00007f5d91fa7e40 CR3: 000000007d2cb000 CR4: > 00000000000006e0 > [ 7513.442323] btrfs_lookup_csum+0x6a/0x160 [btrfs] > [ 7513.442994] Call Trace: > [ 7513.443764] ? kmem_cache_alloc+0x1f2/0x280 > [ 7513.444346] read_block_for_search.isra.0+0x13d/0x3d0 [btrfs] > [ 7513.445182] btrfs_csum_file_blocks+0x198/0x6f0 [btrfs] > [ 7513.445815] btrfs_search_slot+0x25d/0xc10 [btrfs] > [ 7513.446570] add_pending_csums+0x50/0x70 [btrfs] > [ 7513.447126] btrfs_lookup_csum+0x6a/0x160 [btrfs] > [ 7513.448462] btrfs_finish_ordered_io+0x3cb/0x7f0 [btrfs] > [ 7513.450730] ? kmem_cache_alloc+0x1f2/0x280 > [ 7513.452643] normal_work_helper+0xd1/0x540 [btrfs] > [ 7513.454315] btrfs_csum_file_blocks+0x198/0x6f0 [btrfs] > [ 7513.455379] process_one_work+0x22d/0x580 > [ 7513.456451] add_pending_csums+0x50/0x70 [btrfs] > [ 7513.457570] worker_thread+0x50/0x3b0 > [ 7513.460066] btrfs_finish_ordered_io+0x3cb/0x7f0 [btrfs] > [ 7513.463658] kthread+0xfe/0x140 > [ 7513.465743] normal_work_helper+0xd1/0x540 [btrfs] > [ 7513.467701] ? process_one_work+0x580/0x580 > [ 7513.467703] ? kthread_park+0x80/0x80 > [ 7513.468978] process_one_work+0x22d/0x580 > [ 7513.470096] ret_from_fork+0x24/0x30 > [ 7513.473537] worker_thread+0x50/0x3b0 > [ 7513.474525] irq event stamp: 0 > [ 7513.475631] kthread+0xfe/0x140 > [ 7513.477203] hardirqs last enabled at (0): [<0000000000000000>] 0x0 > [ 7513.477207] hardirqs last disabled at (0): [<ffffffffa005ff00>] > copy_process+0x6d0/0x1ac0 > [ 7513.479011] ? process_one_work+0x580/0x580 > [ 7513.480541] softirqs last enabled at (0): [<ffffffffa005ff00>] > copy_process+0x6d0/0x1ac0 > [ 7513.480542] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 7513.482354] ? kthread_park+0x80/0x80 > [ 7513.484191] ---[ end trace f6f3adf90f4ea413 ]--- > [ 7513.591444] ret_from_fork+0x24/0x30 > [ 7513.592257] irq event stamp: 13768774 > [ 7513.592975] hardirqs last enabled at (13768773): [<ffffffffa06575b9>] > _raw_spin_unlock_irq+0x29/0x40 > [ 7513.594386] hardirqs last disabled at (13768774): [<ffffffffa064fb7e>] > __schedule+0xae/0x830 > [ 7513.595732] softirqs last enabled at (13768770): [<ffffffffa0a0035c>] > __do_softirq+0x35c/0x45c > [ 7513.597472] softirqs last disabled at (13768759): [<ffffffffa006a713>] > irq_exit+0xb3/0xc0 >
signature.asc
Description: OpenPGP digital signature
