Re: Performance regression with async inode inactivation

[Jan Kara <jack@suse.cz>]

On Tue 05-10-21 08:15:08, Dave Chinner wrote:
> On Mon, Oct 04, 2021 at 12:06:53PM +0200, Jan Kara wrote:
> > Hello,
> > 
> > our performance testing grid has detected a performance regression caused
> > by commit ab23a77687 ("xfs: per-cpu deferred inode inactivation queues")
> > with reaim benchmark running 'disk' and 'disk-large' workloads. The
> > regression has been so far detected on two machines - marvin7 (48 cpus, 64
> > GB ram, SATA SSD), dobby (64 cpus, 192 GB ram, rotating disk behind
> > megaraid_sas controller).
> 
> Yup, large cpu count, single slow disk, and the cause will likely be
> exclusive rwsem lock contention on a directory inode that concurrent
> openat and unlink are occuring in.
> 
> Basically, that commit removed a bunch of userspace overhead in
> unlinks, when mean they run as fast as the unlink() call can remove
> the directory entry. There is effectively nothing throttling
> unlink() in XFS now except for available log space and it mostly
> runs to completion without blocking. Hence the front end unlink
> performance can run in much faster bursts before delayed
> inactivation needs to run.
> 
> Given most of the added CPU overhead is in the rwsem spin_on_owner
> path, it implies that the write lock holder is, indeed, not sleeping
> with the lock held. Hence reaim is hitting a borderline contended
> rwsem much harder and with different behaviour, resulting in
> catastrophic breakdown of lock performance and hence unlink
> performance goes backwards.
> 
> I can't see any other new sleeping lock contention in the workload
> profiles - the context switch rate goes down substantially (by 35%!)
> with commit ab23a77687, which also implies that the lock contention
> is resulting in much longer spin and/or sleep times on the lock.
> 
> I'm not sure we can do anything about this in the filesystem. The
> contended lock is a core, high level VFS lock which is the first
> point of unlinkat() syscall serialisation. This is the lock that is
> directly exposed to userspace concurrency, so the scalability of
> this lock determines concurrency performance of the userspace
> application.....

Thanks for explanation! It makes sense, except one difference I can see in
vmstat on both marvin7 and dobby which I don't understand:

Dobby:
Ops Sector Reads                     1009081.00     1009081.00
Ops Sector Writes                   11550795.00    18753764.00

Marvin7:
Ops Sector Reads                      887951.00      887951.00
Ops Sector Writes                    8248822.00    11135086.00

So after the change reaim ends up doing noticeably more writes. I had a
look at iostat comparison as well but there wasn't anything particular
standing out besides higher amount of writes on the test disk. I guess,
I'll limit the number of clients to a single number showing the regression,
enable some more detailed monitoring and see whether something interesting
pops up.

> > The regression reports from mmtests on marvin7 (which from my experience I
> > find more reliable than dobby) look like:
> > 
> > reaim-io-disk-xfs
> > Hmean     disk-1       3597.12 (   0.00%)     3636.37 (   1.09%)
> > Hmean     disk-25    125000.00 (   0.00%)   121753.25 (  -2.60%)
> > Hmean     disk-49    218424.96 (   0.00%)   193421.05 * -11.45%*
> > Hmean     disk-73    286649.22 (   0.00%)   240131.58 * -16.23%*
> > Hmean     disk-97    349339.74 (   0.00%)   285854.62 * -18.17%*
> > Hmean     disk-121   373456.79 (   0.00%)   309199.32 * -17.21%*
> > Hmean     disk-145   399449.04 (   0.00%)   330547.11 * -17.25%*
> > Hmean     disk-169   420049.71 (   0.00%)   345132.74 * -17.84%*
> > Hmean     disk-193   458795.56 (   0.00%)   375243.03 * -18.21%*
> > Stddev    disk-1        102.32 (   0.00%)      117.93 ( -15.25%)
> > Stddev    disk-25      6981.08 (   0.00%)     4285.17 (  38.62%)
> > Stddev    disk-49      9523.63 (   0.00%)    10723.44 ( -12.60%)
> > Stddev    disk-73      9704.22 (   0.00%)     7946.73 (  18.11%)
> > Stddev    disk-97     10059.91 (   0.00%)     6111.28 (  39.25%)
> > Stddev    disk-121     5730.56 (   0.00%)    11714.34 (-104.42%)
> > Stddev    disk-145    11154.40 (   0.00%)     8129.06 (  27.12%)
> > Stddev    disk-169     4477.30 (   0.00%)     3558.86 (  20.51%)
> > Stddev    disk-193     8785.70 (   0.00%)    13258.89 ( -50.91%)
> > 
> > reaim-io-disk-large-xfs
> > Hmean     disk-1        722.72 (   0.00%)      721.85 (  -0.12%)
> > Hmean     disk-25     24177.95 (   0.00%)    24319.06 (   0.58%)
> > Hmean     disk-49     35294.12 (   0.00%)    34361.85 (  -2.64%)
> > Hmean     disk-73     43042.45 (   0.00%)    40896.36 *  -4.99%*
> > Hmean     disk-97     48403.19 (   0.00%)    46044.30 *  -4.87%*
> > Hmean     disk-121    52230.22 (   0.00%)    49347.47 *  -5.52%*
> > Hmean     disk-145    54613.94 (   0.00%)    52333.98 *  -4.17%*
> > Hmean     disk-169    57178.30 (   0.00%)    54745.71 *  -4.25%*
> > Hmean     disk-193    60230.94 (   0.00%)    57106.22 *  -5.19%*
> > Stddev    disk-1         18.74 (   0.00%)       30.19 ( -61.11%)
> > Stddev    disk-25       439.49 (   0.00%)      809.58 ( -84.21%)
> > Stddev    disk-49      1416.65 (   0.00%)      603.55 (  57.40%)
> > Stddev    disk-73       949.45 (   0.00%)      584.61 (  38.43%)
> > Stddev    disk-97       689.51 (   0.00%)      602.76 (  12.58%)
> > Stddev    disk-121      485.22 (   0.00%)      612.79 ( -26.29%)
> > Stddev    disk-145      147.37 (   0.00%)      442.99 (-200.60%)
> > Stddev    disk-169      282.25 (   0.00%)      613.42 (-117.33%)
> > Stddev    disk-193      970.05 (   0.00%)      572.59 (  40.97%)
> > 
> > Note that numbers behind dash (disk-xx) denote the number of reaim
> > "clients" - i.e., the number of processes reaim runs in parallel.
> > 
> > This reaim workload will create quite some small files, fsync them, do a
> > few operations on them like read, write, etc. and quickly delete them. This
> > happens in many processes in parallel so I can imagine the unlink workload
> > is rather heavy.
> 
> Yup, which is why I've largely been ignoring it. reaim is a *very
> old* benchmark that doesn't do anything we'd normally do to scale
> out independent workloads effectively.

Yes, I agree reaim is a stupid workload for today's standards so I'm not
much worried about it as such. Just occasionally it tends to highlight
problems that are valid also for more relevant workloads (just less visible
there) so we still run it.

> > To reproduce the workload the easiest is probably to clone mmtests [1],
> > there's README.md and docs/Tutorial.md about how to run tests. Relevant
> > configurations are in configs/config-reaim-io-disk-large and
> > configs/config-reaim-io-disk, you will need to edit these files to set
> > appropriate test partition (will get wiped) and filesystem. Note that
> > mmtests do somewhat modify standard reaim benchmark so that it does not
> > call system("sync") after each operation (you can see modifications we
> > apply in [2] if you're interested).
> > 
> > I can probably find some time to better understand what's going on on these
> > machines later this week but if you have some suggestions what to look for,
> > you're welcome.
> 
> You should be able to reproduce the concurrent unlink contention
> simply by running a bunch of concurrent unlinks in a directory and
> watching the directory i_rwsem get absolutely hammered up in
> do_unlinkat().

OK, thanks for suggestion. I can try that as well.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR