Hi Willy, linux-btrfs@vger, Matthew Wilcox (Oracle) wrote on Sun, Jun 19, 2022 at 04:11:41PM +0100: > We had an off-by-one error which meant that we never marked the first page > in a read as accessed. This was visible as a slowdown when re-reading > a file as pages were being evicted from cache too soon. In reviewing > this code, we noticed a second bug where a multi-page folio would be > marked as accessed multiple times when doing reads that were less than > the size of the folio. when debugging an unrelated issue (short reads on btrfs with io_uring and O_DIRECT[1]), I noticed that my horrible big file copy speeds fell down from ~2GB/s (there's compression and lots of zeroes) to ~100MB/s the second time I was copying it with cp. I've taken a moment to bisect this and came down to this patch. [1] https://lore.kernel.org/all/YrrFGO4A1jS0GI0G@atmark-techno.com/T/#u Dropping caches (echo 3 > /proc/sys/vm/drop_caches) restore the speed, so there appears to be some bad effect to having the file in cache for fiemap? To be fair that file is pretty horrible: --- # compsize bigfile Processed 1 file, 194955 regular extents (199583 refs), 0 inline. Type Perc Disk Usage Uncompressed Referenced TOTAL 15% 3.7G 23G 23G none 100% 477M 477M 514M zstd 14% 3.2G 23G 23G --- Here's what perf has to say about it on top of this patch when running `cp bigfile /dev/null` the first time: 98.97% 0.00% cp [kernel.kallsyms] [k] entry_SYSCALL_64_after_hwframe entry_SYSCALL_64_after_hwframe do_syscall_64 - 93.40% ksys_read - 93.36% vfs_read - 93.25% new_sync_read - 93.20% filemap_read - 83.38% filemap_get_pages - 82.76% page_cache_ra_unbounded + 59.72% folio_alloc + 13.43% read_pages + 8.75% filemap_add_folio 0.64% xa_load 0.52% filemap_get_read_batch + 8.75% copy_page_to_iter - 4.73% __x64_sys_ioctl - 4.72% do_vfs_ioctl - btrfs_fiemap - 4.70% extent_fiemap + 3.95% btrfs_check_shared + 0.70% get_extent_skip_holes and second time: 99.90% 0.00% cp [kernel.kallsyms] [k] entry_SYSCALL_64_after_hwfram entry_SYSCALL_64_after_hwframe do_syscall_64 - 94.62% __x64_sys_ioctl do_vfs_ioctl btrfs_fiemap - extent_fiemap - 50.01% get_extent_skip_holes - 50.00% btrfs_get_extent_fiemap - 49.97% count_range_bits rb_next + 28.72% lock_extent_bits + 15.55% __clear_extent_bit - 5.21% ksys_read + 5.21% vfs_read (if this isn't readable, 95% of the time is spent on fiemap the second time around) I've also been observing RCU stalls on my laptop with the same workload (cp to /dev/null), but unfortunately I could not reproduce in qemu so I could not take traces to confirm they are caused by the same commit but given the workload I'd say that is it? I can rebuild a kernel for my laptop and confirm if you think it should be something else. I didn't look at the patch itself (yet) so have no suggestion at this point - it's plausible the patch fixed something and just exposed slow code that had been there all along so it might be better to look at the btrfs side first, I don't know. If you don't manage to reproduce I'll be happy to test anything thrown at me at the very least. Thanks, -- Dominique Martinet | Asmadeus
On Thu, Jun 30, 2022 at 04:29:05PM +0900, Dominique MARTINET wrote:
> Hi Willy, linux-btrfs@vger,
>
> Matthew Wilcox (Oracle) wrote on Sun, Jun 19, 2022 at 04:11:41PM +0100:
> > We had an off-by-one error which meant that we never marked the first page
> > in a read as accessed. This was visible as a slowdown when re-reading
> > a file as pages were being evicted from cache too soon. In reviewing
> > this code, we noticed a second bug where a multi-page folio would be
> > marked as accessed multiple times when doing reads that were less than
> > the size of the folio.
>
> when debugging an unrelated issue (short reads on btrfs with io_uring
> and O_DIRECT[1]), I noticed that my horrible big file copy speeds fell
> down from ~2GB/s (there's compression and lots of zeroes) to ~100MB/s
> the second time I was copying it with cp.
>
> I've taken a moment to bisect this and came down to this patch.
I think you may have forgotten to include the commit-id that was the
results of your bisect.... ?
- Ted
Theodore Ts'o wrote on Thu, Jun 30, 2022 at 10:37:58AM -0400:
> On Thu, Jun 30, 2022 at 04:29:05PM +0900, Dominique MARTINET wrote:
> > Hi Willy, linux-btrfs@vger,
> >
> > Matthew Wilcox (Oracle) wrote on Sun, Jun 19, 2022 at 04:11:41PM +0100:
> > > We had an off-by-one error which meant that we never marked the first page
> > > in a read as accessed. This was visible as a slowdown when re-reading
> > > a file as pages were being evicted from cache too soon. In reviewing
> > > this code, we noticed a second bug where a multi-page folio would be
> > > marked as accessed multiple times when doing reads that were less than
> > > the size of the folio.
> >
> > when debugging an unrelated issue (short reads on btrfs with io_uring
> > and O_DIRECT[1]), I noticed that my horrible big file copy speeds fell
> > down from ~2GB/s (there's compression and lots of zeroes) to ~100MB/s
> > the second time I was copying it with cp.
> >
> > I've taken a moment to bisect this and came down to this patch.
>
> I think you may have forgotten to include the commit-id that was the
> results of your bisect.... ?
Sorry, this is the patch I replied to and it was recent enough that I
assumed it'd still be in mailboxes, but you're right it's better with a
commit id. This is was merged as 5ccc944dce3d ("filemap: Correct the
conditions for marking a folio as accessed")
Thanks,
--
Dominique
在 2022/06/30 15:29, Dominique MARTINET 写道: > Hi Willy, linux-btrfs@vger, > > Matthew Wilcox (Oracle) wrote on Sun, Jun 19, 2022 at 04:11:41PM +0100: >> We had an off-by-one error which meant that we never marked the first page >> in a read as accessed. This was visible as a slowdown when re-reading >> a file as pages were being evicted from cache too soon. In reviewing >> this code, we noticed a second bug where a multi-page folio would be >> marked as accessed multiple times when doing reads that were less than >> the size of the folio. > > when debugging an unrelated issue (short reads on btrfs with io_uring > and O_DIRECT[1]), I noticed that my horrible big file copy speeds fell > down from ~2GB/s (there's compression and lots of zeroes) to ~100MB/s > the second time I was copying it with cp. > Hi, With this patch ctive_page() will be called the second time that page is mark accessed, which has some extra overhead, however, 2GB/s -> 100MB/s is insane, I'm not sure how this is possible, but it seems like it has something to do with this change.(Noted that it's problematic that page will not mark accessed before this patch). BTW, during my test, the speed of buffer read in ext4 only fell down a little. Thanks, Kuai > I've taken a moment to bisect this and came down to this patch. > > [1] https://lore.kernel.org/all/YrrFGO4A1jS0GI0G@atmark-techno.com/T/#u > > > > Dropping caches (echo 3 > /proc/sys/vm/drop_caches) restore the speed, > so there appears to be some bad effect to having the file in cache for > fiemap? > To be fair that file is pretty horrible: > --- > # compsize bigfile > Processed 1 file, 194955 regular extents (199583 refs), 0 inline. > Type Perc Disk Usage Uncompressed Referenced > TOTAL 15% 3.7G 23G 23G > none 100% 477M 477M 514M > zstd 14% 3.2G 23G 23G > --- > > Here's what perf has to say about it on top of this patch when running > `cp bigfile /dev/null` the first time: > > 98.97% 0.00% cp [kernel.kallsyms] [k] > entry_SYSCALL_64_after_hwframe > entry_SYSCALL_64_after_hwframe > do_syscall_64 > - 93.40% ksys_read > - 93.36% vfs_read > - 93.25% new_sync_read > - 93.20% filemap_read > - 83.38% filemap_get_pages > - 82.76% page_cache_ra_unbounded > + 59.72% folio_alloc > + 13.43% read_pages > + 8.75% filemap_add_folio > 0.64% xa_load > 0.52% filemap_get_read_batch > + 8.75% copy_page_to_iter > - 4.73% __x64_sys_ioctl > - 4.72% do_vfs_ioctl > - btrfs_fiemap > - 4.70% extent_fiemap > + 3.95% btrfs_check_shared > + 0.70% get_extent_skip_holes > > and second time: > 99.90% 0.00% cp [kernel.kallsyms] [k] > entry_SYSCALL_64_after_hwfram > entry_SYSCALL_64_after_hwframe > do_syscall_64 > - 94.62% __x64_sys_ioctl > do_vfs_ioctl > btrfs_fiemap > - extent_fiemap > - 50.01% get_extent_skip_holes > - 50.00% btrfs_get_extent_fiemap > - 49.97% count_range_bits > rb_next > + 28.72% lock_extent_bits > + 15.55% __clear_extent_bit > - 5.21% ksys_read > + 5.21% vfs_read > > (if this isn't readable, 95% of the time is spent on fiemap the second > time around) > > > > > I've also been observing RCU stalls on my laptop with the same workload > (cp to /dev/null), but unfortunately I could not reproduce in qemu so I > could not take traces to confirm they are caused by the same commit but > given the workload I'd say that is it? > I can rebuild a kernel for my laptop and confirm if you think it should > be something else. > > > I didn't look at the patch itself (yet) so have no suggestion at this > point - it's plausible the patch fixed something and just exposed slow > code that had been there all along so it might be better to look at the > btrfs side first, I don't know. > If you don't manage to reproduce I'll be happy to test anything thrown > at me at the very least. > > > Thanks, >
(added btrfs maintainers in direct cc) Yu Kuai wrote on Fri, Jul 01, 2022 at 09:55:31AM +0800: > With this patch ctive_page() will be called the second time that page is > mark accessed, which has some extra overhead, however, 2GB/s -> 100MB/s > is insane, I'm not sure how this is possible, but it seems like it has > something to do with this change.(Noted that it's problematic that page > will not mark accessed before this patch). I honestly don't understand why folio being marked as accessed affects how fiemap is processed... My guess would be that this indeed "just fixes" that pages didn't get marked as accessed -> were dropped from cache -> it kept the inode io_tree small -> fiemap was fast ; and it really just a problem that the fiemap algorithm doesn't scale, but I haven't really checked if I'm right here. So I don't think we should focus so much on the regression part as to figure out what's actually different the second time around and make that faster. checking with 'perf script' btrfs_get_extent_fiemap() spends most of its time on this: delalloc_len = count_range_bits(&inode->io_tree, &delalloc_start, end, len, EXTENT_DELALLOC, 1); I have no idea what delalloc is supposed to be, but I can guess there is just way too many nodes in the io_tree: why is that and why wasn't there so many the first time around? I would assumed that as the file gets read it is put into cache, so the end of the first read should slow down as well but it didn't, so I'm sure I misunderstood something and I'm wasting everyone's time. Feel free to ignore me and find the issue instead :) > BTW, during my test, the speed of buffer read in ext4 only fell down a > little. For "normal" files that don't have ~200k extents full of holes and compression changes and whatever else this has gone through, I can confirm the slowdown is not as bad -- almost unnoticeable when few extents. but I still have my laptop cashing when I'm copying this file twice (well, I -could- just turn off panic_on_stall...) so it can go from a little to infinity... Thanks, (Leaving rest of the message for anyone catching up now; if there's anything you'd like me to do feel free to ask.) > > I've taken a moment to bisect this and came down to this patch. > > (5ccc944dce3d ("filemap: Correct the conditions for marking a folio > > as accessed")) > > > > [1] https://lore.kernel.org/all/YrrFGO4A1jS0GI0G@atmark-techno.com/T/#u > > > > > > > > Dropping caches (echo 3 > /proc/sys/vm/drop_caches) restore the speed, > > so there appears to be some bad effect to having the file in cache for > > fiemap? > > To be fair that file is pretty horrible: > > --- > > # compsize bigfile > > Processed 1 file, 194955 regular extents (199583 refs), 0 inline. > > Type Perc Disk Usage Uncompressed Referenced > > TOTAL 15% 3.7G 23G 23G > > none 100% 477M 477M 514M > > zstd 14% 3.2G 23G 23G > > --- > > > > Here's what perf has to say about it on top of this patch when running > > `cp bigfile /dev/null` the first time: > > > > 98.97% 0.00% cp [kernel.kallsyms] [k] > > entry_SYSCALL_64_after_hwframe > > entry_SYSCALL_64_after_hwframe > > do_syscall_64 > > - 93.40% ksys_read > > - 93.36% vfs_read > > - 93.25% new_sync_read > > - 93.20% filemap_read > > - 83.38% filemap_get_pages > > - 82.76% page_cache_ra_unbounded > > + 59.72% folio_alloc > > + 13.43% read_pages > > + 8.75% filemap_add_folio > > 0.64% xa_load > > 0.52% filemap_get_read_batch > > + 8.75% copy_page_to_iter > > - 4.73% __x64_sys_ioctl > > - 4.72% do_vfs_ioctl > > - btrfs_fiemap > > - 4.70% extent_fiemap > > + 3.95% btrfs_check_shared > > + 0.70% get_extent_skip_holes > > > > and second time: > > 99.90% 0.00% cp [kernel.kallsyms] [k] > > entry_SYSCALL_64_after_hwfram > > entry_SYSCALL_64_after_hwframe > > do_syscall_64 > > - 94.62% __x64_sys_ioctl > > do_vfs_ioctl > > btrfs_fiemap > > - extent_fiemap > > - 50.01% get_extent_skip_holes > > - 50.00% btrfs_get_extent_fiemap > > - 49.97% count_range_bits > > rb_next > > + 28.72% lock_extent_bits > > + 15.55% __clear_extent_bit > > - 5.21% ksys_read > > + 5.21% vfs_read > > > > (if this isn't readable, 95% of the time is spent on fiemap the second > > time around) > > > > > > > > > > I've also been observing RCU stalls on my laptop with the same workload > > (cp to /dev/null), but unfortunately I could not reproduce in qemu so I > > could not take traces to confirm they are caused by the same commit but > > given the workload I'd say that is it? > > I can rebuild a kernel for my laptop and confirm if you think it should > > be something else. > > > > > > I didn't look at the patch itself (yet) so have no suggestion at this > > point - it's plausible the patch fixed something and just exposed slow > > code that had been there all along so it might be better to look at the > > btrfs side first, I don't know. > > If you don't manage to reproduce I'll be happy to test anything thrown > > at me at the very least. -- Dominique