Re: [4.2, Regression] Queued spinlocks cause major XFS performance regression

[Linus Torvalds <torvalds@linux-foundation.org>]

On Thu, Sep 3, 2015 at 10:48 PM, Dave Chinner <david@fromorbit.com> wrote:
>
> When I turned spinlock debugging off on 4.2 to get some perf numbers
> a request from Linus, I got this:

[ ugly numbers deleted ]

> And then a quick call graph sample to find the lock:
>
>    37.19%    37.19%  [kernel]         [k] queued_spin_lock_slowpath
>    - queued_spin_lock_slowpath
>       - 99.98% _raw_spin_lock
>          - 89.16% xfs_log_commit_cil
[ snip ]
>
> This shows that we have catastrophic spinlock contention in the
> transaction commit path. The cil->xc_cil_lock spin lock as it's the
> only spinlock in that path. And while it's the hot lock in the
> commit path, turning spinlock debugging back on (and no other
> changes) shows that it shouldn't be contended:
>
>    8.92%  [kernel]  [k] _xfs_buf_find
[ snip ]

So you basically have almost no spinlock overhead at all even when
debugging is on.

That's unusual, as usually the debug code makes the contention much much worse.

> To confirm that this is indeed caused by the queued spinlocks, I
> removed the the spinlock debugging and did this to arch/x86/Kconfig:
>
> -       select ARCH_USE_QUEUED_SPINLOCK
>
> And the results are:

Ok, that's pretty conclusive. It doesn't seem to make much _sense_,
but numbers talk, BS walks.

If I read things right, the actual spinlock is the "cil->xc_cil_lock"
that is taken in xlog_cil_insert_items(), and it justr shows up in
xfs_log_commit_cil() in the call graph due to inlining. Correct?

There doesn't seem to be anything even remotely strange going on in that area.

Is this a PARAVIRT configuration? There were issues with PV
interaction at some point. If it is PV, and you don't actually use PV,
can you test with PV support disabled?

Also, if you look at the instruction-level profile for
queued_spin_lock_slowpath itself, does anything stand out? For
example, I note that the for-loop with the atomic_cmpxchg() call in it
doesn't ever do a cpu_relax(). It doesn't look like that should
normally loop, but obviously that function also shouldn't normally use
2/3rds of the cpu, so.. Maybe some part of queued_spin_lock_slowpath()
stands out as "it's spending 99% of the time in _that_ particular
part, and it gives some clue what goes wrong.

Ugh. Added Ingo to the cc. I *hate* locking problems, to the point
where I think we need to seriously consider undoing the queued
spinlocks if they have these kinds of odd issues..

Anybody have any ideas?

                         Linus