Re: "bad tree block start" when trying to mount on ARM

[Qu Wenruo <quwenruo.btrfs@gmx.com>]

On 2021/2/18 下午3:59, Erik Jensen wrote:
> On Wed, Feb 17, 2021 at 11:24 PM Qu Wenruo <quwenruo.btrfs@gmx.com> wrote:
>> On 2021/2/18 下午2:59, Erik Jensen wrote:
>>> On Wed, Feb 17, 2021 at 10:09 PM Qu Wenruo <quwenruo.btrfs@gmx.com> wrote:
>>>> On 2021/2/18 下午1:49, Erik Jensen wrote:
>>>>> On Wed, Feb 17, 2021 at 9:24 PM Qu Wenruo <quwenruo.btrfs@gmx.com> wrote:
>>>>>> Got it now.
>>>>>>
>>>>>> [  295.249182] read_extent_buffer_pages: eb->start=26207780683776 mirror=0
>>>>>> [  295.249188] __btrfs_map_block: logical=8615594639360 chunk
>>>>>> start=8614760677376 len=4294967296 type=0x81
>>>>>> [  295.249189] __btrfs_map_block: stripe[0] devid=3 phy=2118735708160
>>>>>>
>>>>>> Note that, the initial request is to read from 26207780683776.
>>>>>> But inside btrfs_map_block(), we want to read from 8615594639360.
>>>>>>
>>>>>> This is totally screwed up in a unexpected way.
>>>>>>
>>>>>> 26207780683776 = 0x17d5f9754000
>>>>>> 8615594639360  = 0x07d5f9754000
>>>>>>
>>>>>> See the missing leading 1, which screws up the result.
>>>>>>
>>>>>> The problem should be the logical calculation part, which doesn't do
>>>>>> proper u64 conversion which could cause the problem.
>>>>>>
>>>>>> Would you like to test the single line fix below?
>>>>>>
>>>>>> Thanks,
>>>>>> Qu
>>>>>>
>>>>>> diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
>>>>>> index b8fab44394f5..69d728f5ff9e 100644
>>>>>> --- a/fs/btrfs/volumes.c
>>>>>> +++ b/fs/btrfs/volumes.c
>>>>>> @@ -6575,7 +6575,7 @@ blk_status_t btrfs_map_bio(struct btrfs_fs_info
>>>>>> *fs_info, struct bio *bio,
>>>>>>      {
>>>>>>             struct btrfs_device *dev;
>>>>>>             struct bio *first_bio = bio;
>>>>>> -       u64 logical = bio->bi_iter.bi_sector << 9;
>>>>>> +       u64 logical = ((u64)bio->bi_iter.bi_sector) << 9;
>>>>>>             u64 length = 0;
>>>>>>             u64 map_length;
>>>>>>             int ret;
>>>>>
>>>>> So… it appears my kernel tree (Arch32's 5.10.14-arch1) already has that:
>>>>>
>>>>
>>>> And I also noticed that since v5.2 kernel, we should already have
>>>> bi_sector as u64.
>>>>
>>>> So why that left shift would get higher bits missing is really strange.
>>>> Especially the missing part is just at the 45 bit, not 32 bit boundary.
>>>>
>>>> Then what about this diff? It goes multiplying other than using
>>>> dangerous left shift.
>>>>
>>>> (Also, it's recommended to still use previous debug diffs, so if it
>>>> doesn't work we still have a chance to know what's going wrong).
>>>>
>>>> Thanks,
>>>> Qu
>>>
>>> No change. I added an extra debug line in btrfs_map_bio, and get the following:
>>>
>>> btrfs_map_bio: bio->bi_iter.bi_sector=16827333280, logical=8615594639360
>>>
>>> bio->bi_iter.bi_sector is 16827333280, not 51187071648, so it looks
>>> like the top bit is already missing before the shift / multiplication.
>>>
>> Special thanks to Su, he points out that, page->index is still just
>> unsigned long, which is not ensured to be 64 bits.
>>
>> Thus page_offset(page) can easily go wrong, which takes page->index and
>> does left shift.
>>
>> Mind to test the following debug diff?
>>
>> Thanks,
>> Qu
>>
>> diff --git a/fs/btrfs/extent_io.c b/fs/btrfs/extent_io.c
>> index 4dfb3ead1175..794f97d6eda7 100644
>> --- a/fs/btrfs/extent_io.c
>> +++ b/fs/btrfs/extent_io.c
>> @@ -6001,6 +6001,8 @@ int read_extent_buffer_pages(struct extent_buffer
>> *eb, int wait, int mirror_num)
>>                           }
>>
>>                           ClearPageError(page);
>> +                       pr_info("%s: eb start=%llu i=%d page_offset=%llu\n",
>> +                               __func__, eb->start, i, page_offset(page));
>>                           err = submit_extent_page(REQ_OP_READ |
>> REQ_META, NULL,
>>                                            page, page_offset(page),
>> PAGE_SIZE, 0,
>>                                            &bio, end_bio_extent_readpage,
>
> Here's the new dmesg log:
> https://gist.github.com/rkjnsn/5153682d5be865c13966d342ea7cbe9e
>
> Relevant looking new lines:
>
> [   52.903379] read_extent_buffer_pages: eb->start=26207780683776 mirror=0
> [   52.903380] read_extent_buffer_pages: eb start=26207780683776 i=0
> page_offset=8615594639360
> [   52.903400] read_extent_buffer_pages: eb start=26207780683776 i=1
> page_offset=8615594643456
> [   52.903403] read_extent_buffer_pages: eb start=26207780683776 i=2
> page_offset=8615594647552
> [   52.903403] read_extent_buffer_pages: eb start=26207780683776 i=3
> page_offset=8615594651648
>
We got it!

The eb->start mismatch with page_offset(), this means something is wrong
with page->index.

Considering page->index is just unsigned long thus when we initialize
page->index using a real u64, we truncated some high bits.

And when we get it back to u64, the truncated bits leads to above result.

The fix would be pretty tricky and with MM guys involved, and may need a
much longer time.

I guess this is a known bug, as page->index limit means we can't handle
files over 4T on 32bit systems, even if the underlying fs can handle it
(just like what you hit).

Thanks,
Qu