Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression

[Dave Chinner <david@fromorbit.com>]

On Mon, Aug 15, 2016 at 10:14:55PM +0800, Fengguang Wu wrote:
> Hi Christoph,
> 
> On Sun, Aug 14, 2016 at 06:17:24PM +0200, Christoph Hellwig wrote:
> >Snipping the long contest:
> >
> >I think there are three observations here:
> >
> >(1) removing the mark_page_accessed (which is the only significant
> >    change in the parent commit)  hurts the
> >    aim7/1BRD_48G-xfs-disk_rr-3000-performance/ivb44 test.
> >    I'd still rather stick to the filemap version and let the
> >    VM people sort it out.  How do the numbers for this test
> >    look for XFS vs say ext4 and btrfs?
> >(2) lots of additional spinlock contention in the new case.  A quick
> >    check shows that I fat-fingered my rewrite so that we do
> >    the xfs_inode_set_eofblocks_tag call now for the pure lookup
> >    case, and pretty much all new cycles come from that.
> >(3) Boy, are those xfs_inode_set_eofblocks_tag calls expensive, and
> >    we're already doing way to many even without my little bug above.
> >
> >So I've force pushed a new version of the iomap-fixes branch with
> >(2) fixed, and also a little patch to xfs_inode_set_eofblocks_tag a
> >lot less expensive slotted in before that.  Would be good to see
> >the numbers with that.
> 
> The aim7 1BRD tests finished and there are ups and downs, with overall
> performance remain flat.
> 
> 99091700659f4df9  74a242ad94d13436a1644c0b45  bf4dc6e4ecc2a3d042029319bc  testcase/testparams/testbox
> ----------------  --------------------------  --------------------------  ---------------------------

What do these commits refer to, please? They mean nothing without
the commit names....

/me goes searching. Ok:

99091700659 is the top of Linus' tree
74a242ad94d is ????
bf4dc6e4ecc is the latest in Christoph's tree (because it's
		mentioned below)

>         %stddev     %change         %stddev     %change         %stddev
>             \          |                \          |
> \     159926                      157324                      158574
> GEO-MEAN aim7.jobs-per-min
>     70897               5%      74137               4%      73775        aim7/1BRD_48G-xfs-creat-clo-1500-performance/ivb44
>    485217 ±  3%                492431                      477533        aim7/1BRD_48G-xfs-disk_rd-9000-performance/ivb44
>    360451             -19%     292980             -17%     299377        aim7/1BRD_48G-xfs-disk_rr-3000-performance/ivb44

So, why does random read go backwards by 20%? The iomap IO path
patches we are testing only affect the write path, so this
doesn't make a whole lot of sense.

>    338114                      338410               5%     354078        aim7/1BRD_48G-xfs-disk_rw-3000-performance/ivb44
>     60130 ±  5%         4%      62438               5%      62923        aim7/1BRD_48G-xfs-disk_src-3000-performance/ivb44
>    403144                      397790                      410648        aim7/1BRD_48G-xfs-disk_wrt-3000-performance/ivb44

And this is the test the original regression was reported for:

gcc-6/performance/profile/1BRD_48G/xfs/x86_64-rhel/3000/debian-x86_64-2015-02-07.cgz/ivb44/disk_wrt/aim7

And that shows no improvement at all. The orginal regression was:

	484435 ±  0%     -13.3%     420004 ±  0%  aim7.jobs-per-min

So it's still 15% down on the orginal performance which, again,
doesn't make a whole lot of sense given the improvement in so many
other tests I've run....

>     26327                       26534                       26128        aim7/1BRD_48G-xfs-sync_disk_rw-600-performance/ivb44
> 
> The new commit bf4dc6e ("xfs: rewrite and optimize the delalloc write
> path") improves the aim7/1BRD_48G-xfs-disk_rw-3000-performance/ivb44
> case by 5%. Here are the detailed numbers:
> 
> aim7/1BRD_48G-xfs-disk_rw-3000-performance/ivb44

Not important at all. We need the results for the disk_wrt regression
we are chasing (disk_wrt-3000) so we can see how the code change
affected behaviour.

> Here are the detailed numbers for the slowed down case:
> 
> aim7/1BRD_48G-xfs-disk_rr-3000-performance/ivb44
> 
> 99091700659f4df9  bf4dc6e4ecc2a3d042029319bc
> ----------------  --------------------------
>         %stddev      change         %stddev
>             \          |                \
>    360451             -17%     299377        aim7.jobs-per-min
>     12806             481%      74447        aim7.time.involuntary_context_switches
.....
>     19377             459%     108364        vmstat.system.cs
.....
>       487 ± 89%      3e+04      26448 ± 57%  latency_stats.max.down.xfs_buf_lock._xfs_buf_find.xfs_buf_get_map.xfs_buf_read_map.xfs_trans_read_buf_map.xfs_read_agf.xfs_alloc_read_agf.xfs_alloc_fix_freelist.xfs_free_extent_fix_freelist.xfs_free_extent.xfs_trans_free_extent
>      1823 ± 82%      2e+06    1913796 ± 38%  latency_stats.sum.down.xfs_buf_lock._xfs_buf_find.xfs_buf_get_map.xfs_buf_read_map.xfs_trans_read_buf_map.xfs_read_agf.xfs_alloc_read_agf.xfs_alloc_fix_freelist.xfs_free_extent_fix_freelist.xfs_free_extent.xfs_trans_free_extent
>    208475 ± 43%      1e+06    1409494 ±  5%  latency_stats.sum.wait_on_page_bit.truncate_inode_pages_range.truncate_inode_pages_final.evict.iput.dentry_unlink_inode.__dentry_kill.dput.__fput.____fput.task_work_run.exit_to_usermode_loop
>      6884 ± 73%      8e+04      90790 ±  9%  latency_stats.sum.call_rwsem_down_read_failed.xfs_log_commit_cil.__xfs_trans_commit.xfs_trans_commit.xfs_vn_update_time.file_update_time.xfs_file_aio_write_checks.xfs_file_buffered_aio_write.xfs_file_write_iter.__vfs_write.vfs_write.SyS_write
>      1598 ± 20%      3e+04      35015 ± 27%  latency_stats.sum.call_rwsem_down_read_failed.xfs_log_commit_cil.__xfs_trans_commit.__xfs_trans_roll.xfs_trans_roll.xfs_itruncate_extents.xfs_free_eofblocks.xfs_release.xfs_file_release.__fput.____fput.task_work_run
>      2006 ± 25%      3e+04      31143 ± 35%  latency_stats.sum.call_rwsem_down_read_failed.xfs_log_commit_cil.__xfs_trans_commit.__xfs_trans_roll.xfs_trans_roll.xfs_itruncate_extents.xfs_inactive_truncate.xfs_inactive.xfs_fs_destroy_inode.destroy_inode.evict.iput
>        29 ±101%      1e+04      10214 ± 29%  latency_stats.sum.call_rwsem_down_read_failed.xfs_log_commit_cil.__xfs_trans_commit.__xfs_trans_roll.xfs_trans_roll.xfs_defer_trans_roll.xfs_defer_finish.xfs_itruncate_extents.xfs_inactive_truncate.xfs_inactive.xfs_fs_destroy_inode.destroy_inode
>      1206 ± 51%      9e+03       9919 ± 25%  latency_stats.sum.call_rwsem_down_read_failed.xfs_log_commit_cil.__xfs_trans_commit.xfs_trans_commit.xfs_vn_update_time.touch_atime.generic_file_read_iter.xfs_file_buffered_aio_read.xfs_file_read_iter.__vfs_read.vfs_read.SyS_read

Significant increase in blocking delays in the journal during atime
updates. There's nothing in Christoph's tree that would affect that
behaviour.  This smells like either a mount option change or
individual tests not being 100% isolated and the previous test run
is affecting this one?

-Dave.
-- 
Dave Chinner
david@fromorbit.com