Re: [regression, 3.16-rc] rwsem: optimistic spinning causing performance degradation

[Jason Low <jason.low2@hp.com>]

On Fri, 2014-07-04 at 11:01 +1000, Dave Chinner wrote:
> [re-added lkml]
> 
> On Thu, Jul 03, 2014 at 11:50:20AM -0700, Jason Low wrote:
> > On Wed, Jul 2, 2014 at 7:32 PM, Dave Chinner <david@fromorbit.com> wrote:
> > > This is what the kernel profile looks like on the strided run:
> > >
> > > -  83.06%  [kernel]  [k] osq_lock
> > >    - osq_lock
> > >       - 100.00% rwsem_down_write_failed
> > >          - call_rwsem_down_write_failed
> > >             - 99.55% sys_mprotect
> > >                  tracesys
> > >                  __GI___mprotect
> > > -  12.02%  [kernel]  [k] rwsem_down_write_failed
> > 
> > Hi Dave,
> > 
> > So with no sign of rwsem_spin_on_owner(), yet with such heavy contention in
> > osq_lock, this makes me wonder if it's spending most of its time spinning
> > on !owner while a reader has the lock? (We don't set sem->owner for the readers.)
> > 
> > If that's an issue, maybe the below is worth a test, in which we'll just
> > avoid spinning if rwsem_can_spin_on_owner() finds that there is no owner.
> > If we just had to enter the slowpath yet there is no owner, we'll be conservative
> > and assume readers have the lock.
> 
> That makes it quite a bit faster:
> 
>         XFS_REPAIR Summary    Fri Jul  4 10:39:32 2014
> 
> Phase           Start           End             Duration
> Phase 1:        07/04 10:38:04  07/04 10:38:05  1 second
> Phase 2:        07/04 10:38:05  07/04 10:38:08  3 seconds
> Phase 3:        07/04 10:38:08  07/04 10:39:12  1 minute, 4 seconds
> Phase 4:        07/04 10:39:12  07/04 10:39:21  9 seconds
> Phase 5:        07/04 10:39:21  07/04 10:39:22  1 second
> Phase 6:        07/04 10:39:22  07/04 10:39:30  8 seconds
> Phase 7:        07/04 10:39:30  07/04 10:39:30  
> 
> Total run time: 1 minute, 26 seconds
> done
> 
> real    1m28.504s
> user    1m23.990s
> sys     3m20.132s
> 
> So system time goes down massively, and speed comes up to within 30%
> of the single AG run.  But it's still 2-3000 IOPS down, but it's
> acceptible for the moment.
> 
> FWIW, the kernel profile ifor the multi-AG run now looks like:
> 
>   29.64%  [kernel]  [k] _raw_spin_unlock_irq
>    - _raw_spin_unlock_irq
>       + 35.34% __schedule
>       - 34.15% call_rwsem_down_write_failed
>          + 99.27% sys_mprotect
>       - 30.02% call_rwsem_down_read_failed
>            95.59% __do_page_fault
> -  24.65%  [kernel]  [k] _raw_spin_unlock_irqrestore
>    - _raw_spin_unlock_irqrestore
>       - 69.38% rwsem_wake
>          - call_rwsem_wake
>             - 83.32% sys_mprotect
>             + 15.54% __do_page_fault
>       + 22.55% try_to_wake_up
> +   9.77%  [kernel]  [k] default_send_IPI_mask_sequence_phys
> -   3.21%  [kernel]  [k] smp_call_function_many
>    - smp_call_function_many
>       - 99.22% flush_tlb_page
> +   2.51%  [kernel]  [k] rwsem_down_write_failed
> 
> It's much more like the 3.15 profile - it's only wasting half the
> CPU spinning on the internal spinlock and it's now going fast enough
> to be blowing another 10-12% of the CPU time sending tlb flushes to
> other CPUs....
> 
> One thing I did notice, even with the single-AG-at-a-time run, is
> that the system time is *significantly* reduced with this patch,
> even though it doesn't change performance.
> 
> ie unpatched:
> 
> 	unpatched	patched
> runtime   0m58s		  1m2s
> systime   4m55s		  1m1s
> 
> So not spinning when there are read holders is a major win even
> when there are few threads contending on read/write.
> 
> FWIW, the rwsems in the struct xfs_inode are often heavily
> read/write contended, so there are lots of IO related workloads that
> are going to regress on XFS without this optimisation...
> 
> Anyway, consider the patch:
> 
> Tested-by: Dave Chinner <dchinner@redhat.com>

Hi Dave,

Thanks for testing. I'll update the patch with an actual changelog.