Btrfs_read_block_groups() delay (Was Re: BTRFS Mount Delay Time Graph)

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

Now with a little larger fs (257G used, backed by HDD), the result is
much more obvious:

$ sudo perf ftrace -t function_graph \
                   -T open_ctree \
                   -T btrfs_read_block_groups \
                   -T check_chunk_block_group_mappings \
                   -T btrfs_read_chunk_tree \
                   -T btrfs_verify_dev_extents \
                   mount /dev/vdc /mnt/btrfs/

 3)               |  open_ctree [btrfs]() {
 3)               |    btrfs_read_chunk_tree [btrfs]() {
 3) * 69033.31 us |    }
 3)               |    btrfs_verify_dev_extents [btrfs]() {
 3) * 90376.15 us |    }
 3)               |    btrfs_read_block_groups [btrfs]() {
 2) $ 2733853 us  |    } /* btrfs_read_block_groups [btrfs] */
 2) $ 3168384 us  |  } /* open_ctree [btrfs] */

For btrfs_read_chunk_tree() and btrfs_verify_dev_extents(), combined
they take less than 160ms.
While for btrfs_read_block_groups() it take 2.7s while the total mount
time is 3.1s, meaning btrfs_read_block_groups() is already taking 87% of
the mount time.


I'll try to make btrfs BLOCK_GROUP_ITEM into one separate tree to make
they iterate just like chunks tree, and see how it will end up.

Thanks,
Qu

On 2018/12/20 下午1:47, Qu Wenruo wrote:
> 
> 
> On 2018/12/5 下午2:55, Nikolay Borisov wrote:
>>
>>
>> On 4.12.18 г. 22:14 ч., Wilson, Ellis wrote:
>>
>> A command that would be good is :
>>
>> perf record --all-kernel -g mount /dev/vdc /media/scratch/
> 
> 
> In fact, if we're just going to verify if it's btrfs_read_block_groups()
> causing the biggest problem, we could use ftrace directly (wrapped by
> "perf ftrace"):
> 
> perf ftrace -t function_graph -T open_ctree \
> 	-T btrfs_read_block_groups \
> 	mount $dev $mnt
> 
> The result will be super easy to read, something like:
> 
>  2)               |  open_ctree [btrfs]() {
>  2)               |    btrfs_read_block_groups [btrfs]() {
>  2) # 1726.598 us |    }
>  2) * 21817.28 us |  }
> 
> 
> Since I'm just using a small fs, with 4G data copied from /usr, we won't
> populate extent tree with enough backrefs, thus
> btrfs_read_block_groups() won't be a big problem. (only 7.9%)
> 
> However when I populate the fs with small inline files along with small
> data extents, and 4K nodesize to bump up extent tree size, the same 4G
> data would result a different story:
> 
>  3)               |  open_ctree [btrfs]() {
>  3)               |    btrfs_read_block_groups [btrfs]() {
>  3) # 4567.645 us |    }
>  3) * 22520.95 us |  }
> 
> Now it's 20.3% of the total mount time.
> I believe the percentage will just increase and go over 70% when the fs
> is larger and larger.
> 
> 
> So, Wilson, would you please use above "perf ftrace" command to get the
> function duration?
> 
> Thanks,
> Qu
> 
>>
>> of course replace device/mount path appropriately. This will result in a
>> perf.data file which contains stacktraces of the hottest paths executed
>> during invocation of mount. If you could send this file to the mailing
>> list or upload it somwhere for interested people (me and perhaps) Qu to
>> inspect would be appreciated.
>>
>> If the file turned out way too big you can use
>>
>> perf report --stdio  to create a text output and you could send that as
>> well.