Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]


Groups > linux.kernel > #1460084 > unrolled thread

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

Started byDave Chinner <david@fromorbit.com>
First post2016-08-11 01:10 +0200
Last post2016-08-11 02:00 +0200
Articles 20 on this page of 98 — 11 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.


Contents

  Re: [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-11 01:10 +0200
    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression "Huang\, Ying" <ying.huang@intel.com> - 2016-08-11 02:00 +0200
      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression "Huang\, Ying" <ying.huang@intel.com> - 2016-08-11 02:20 +0200
        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-11 02:30 +0200
          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression "Huang\, Ying" <ying.huang@intel.com> - 2016-08-11 02:40 +0200
            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-11 03:10 +0200
              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-11 06:50 +0200
                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression "Huang\, Ying" <ying.huang@intel.com> - 2016-08-15 19:30 +0200
                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-16 02:30 +0200
              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%  regression Christoph Hellwig <hch@lst.de> - 2016-08-11 18:00 +0200
                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-11 19:00 +0200
                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression "Huang\, Ying" <ying.huang@intel.com> - 2016-08-11 20:00 +0200
                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-11 22:00 +0200
                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%  regression Christoph Hellwig <hch@lst.de> - 2016-08-11 22:10 +0200
                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-11 22:40 +0200
                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Al Viro <viro@ZenIV.linux.org.uk> - 2016-08-12 00:20 +0200
                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-12 00:40 +0200
                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-11 23:50 +0200
                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%  regression Christoph Hellwig <hch@lst.de> - 2016-08-12 00:10 +0200
                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-12 03:00 +0200
                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-12 04:30 +0200
                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-12 06:00 +0200
                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-12 20:10 +0200
                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-14 11:00 +0200
                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-15 02:50 +0200
                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-15 03:40 +0200
                              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-15 04:40 +0200
                                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-15 05:00 +0200
                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-15 07:10 +0200
                                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-16 00:30 +0200
                                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-16 00:50 +0200
                                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-16 01:30 +0200
                                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-16 01:50 +0200
                                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-16 02:50 +0200
                                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Mel Gorman <mgorman@techsingularity.net> - 2016-08-16 17:10 +0200
                                              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-16 20:00 +0200
                                                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Michal Hocko <mhocko@kernel.org> - 2016-08-17 17:50 +0200
                                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Michal Hocko <mhocko@kernel.org> - 2016-08-17 18:50 +0200
                                                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Mel Gorman <mgorman@techsingularity.net> - 2016-08-17 17:50 +0200
                                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Mel Gorman <mgorman@techsingularity.net> - 2016-08-18 02:50 +0200
                                                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-18 09:20 +0200
                                                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Mel Gorman <mgorman@techsingularity.net> - 2016-08-18 15:30 +0200
                                                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-19 04:10 +0200
                                                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-19 04:40 +0200
                                                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Michal Hocko <mhocko@kernel.org> - 2016-08-19 11:10 +0200
                                                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Mel Gorman <mgorman@techsingularity.net> - 2016-08-19 13:00 +0200
                                                              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-20 01:50 +0200
                                                                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-20 03:10 +0200
                                                                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Mel Gorman <mgorman@techsingularity.net> - 2016-08-20 14:20 +0200
                                                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-19 06:10 +0200
                                                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Mel Gorman <mgorman@techsingularity.net> - 2016-08-19 17:10 +0200
                                                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression "Huang\, Ying" <ying.huang@intel.com> - 2016-08-24 17:50 +0200
                                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-18 04:50 +0200
                                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-16 02:20 +0200
                                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-16 02:40 +0200
                                              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-16 03:00 +0200
                                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-16 02:40 +0200
                                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-16 04:00 +0200
                                              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-17 00:10 +0200
                                                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-17 01:30 +0200
                                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-16 01:10 +0200
                                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-16 02:40 +0200
                                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-16 02:50 +0200
                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Ingo Molnar <mingo@kernel.org> - 2016-08-15 07:10 +0200
                                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Peter Zijlstra <peterz@infradead.org> - 2016-08-17 18:30 +0200
                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-15 15:10 +0200
                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-12 04:30 +0200
                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-12 04:40 +0200
                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%  regression Christoph Hellwig <hch@lst.de> - 2016-08-12 05:00 +0200
                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-12 05:30 +0200
                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-12 06:20 +0200
                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-12 07:10 +0200
                              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-12 08:10 +0200
                                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Ye Xiaolong <xiaolong.ye@intel.com> - 2016-08-12 08:40 +0200
                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Ye Xiaolong <xiaolong.ye@intel.com> - 2016-08-12 11:00 +0200
                                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-12 12:10 +0200
                                      Re: [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-12 12:50 +0200
                                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%  regression Christoph Hellwig <hch@lst.de> - 2016-08-13 02:40 +0200
                                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%  regression Christoph Hellwig <hch@lst.de> - 2016-08-14 10:30 +0200
                                          Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-14 10:40 +0200
                                            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%  regression Christoph Hellwig <hch@lst.de> - 2016-08-14 11:00 +0200
                                              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-14 11:30 +0200
                                                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%  regression Christoph Hellwig <hch@lst.de> - 2016-08-14 18:20 +0200
                                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-15 01:50 +0200
                                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-15 02:00 +0200
                                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-15 16:20 +0200
                                                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-15 23:30 +0200
                                                      Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-16 14:30 +0200
                                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression "Huang\, Ying" <ying.huang@intel.com> - 2016-08-15 22:40 +0200
                                                    Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6%     regression "Huang\, Ying" <ying.huang@intel.com> - 2016-08-23 00:10 +0200
                                                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Fengguang Wu <fengguang.wu@intel.com> - 2016-08-16 15:30 +0200
                                        Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-14 12:00 +0200
            Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-11 03:20 +0200
              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-11 03:40 +0200
                Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Ye Xiaolong <xiaolong.ye@intel.com> - 2016-08-11 04:50 +0200
                  Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-11 05:20 +0200
              Re: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Dave Chinner <david@fromorbit.com> - 2016-08-12 03:30 +0200
    Re: [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression Linus Torvalds <torvalds@linux-foundation.org> - 2016-08-11 02:00 +0200

Page 2 of 5 — ← Prev page 1 [2] 3 4 5  Next page →


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

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-08-12 04:30 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s5aop-44O-1@gated-at.bofh.it>
In reply to#1460883
On Thu, Aug 11, 2016 at 5:54 PM, Dave Chinner <david@fromorbit.com> wrote:
>
> So, removing mark_page_accessed() made the spinlock contention
> *worse*.
>
>   36.51%  [kernel]  [k] _raw_spin_unlock_irqrestore
>    6.27%  [kernel]  [k] copy_user_generic_string
>    3.73%  [kernel]  [k] _raw_spin_unlock_irq
>    3.55%  [kernel]  [k] get_page_from_freelist
>    1.97%  [kernel]  [k] do_raw_spin_lock
>    1.72%  [kernel]  [k] __block_commit_write.isra.30

I don't recall having ever seen the mapping tree_lock as a contention
point before, but it's not like I've tried that load either. So it
might be a regression (going back long, I suspect), or just an unusual
load that nobody has traditionally tested much.

Single-threaded big file write one page at a time, was it?

The mapping tree lock has been around forever (it used to be a rw-lock
long long ago), but I wonder if we might have moved more stuff into it
(memory accounting comes to mind) causing much worse contention or
something.

Hmm. Just for fun, I googled "tree_lock contention". It's shown up
before - back in 2006, and it was you hitting it back then too.

There was an even older one (related to AIM7, interesting) which was
what caused the tree_lock to become a rw-lock back in 2005 (but then
Nick Piggin made it a spinlock again in 2008).

So it's not unheard of, but it certainly hasn't been a big issue.

That's the only obvious ones I found (apart from some btrfs issues,
but btrfs has a completely different notion of tree locking, so those
are not about the same thing).

                 Linus

[toc] | [prev] | [next] | [standalone]


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

FromDave Chinner <david@fromorbit.com>
Date2016-08-12 06:00 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s5bNw-4Os-3@gated-at.bofh.it>
In reply to#1460898
On Thu, Aug 11, 2016 at 07:27:52PM -0700, Linus Torvalds wrote:
> On Thu, Aug 11, 2016 at 5:54 PM, Dave Chinner <david@fromorbit.com> wrote:
> >
> > So, removing mark_page_accessed() made the spinlock contention
> > *worse*.
> >
> >   36.51%  [kernel]  [k] _raw_spin_unlock_irqrestore
> >    6.27%  [kernel]  [k] copy_user_generic_string
> >    3.73%  [kernel]  [k] _raw_spin_unlock_irq
> >    3.55%  [kernel]  [k] get_page_from_freelist
> >    1.97%  [kernel]  [k] do_raw_spin_lock
> >    1.72%  [kernel]  [k] __block_commit_write.isra.30
> 
> I don't recall having ever seen the mapping tree_lock as a contention
> point before, but it's not like I've tried that load either. So it
> might be a regression (going back long, I suspect), or just an unusual
> load that nobody has traditionally tested much.
> 
> Single-threaded big file write one page at a time, was it?

Yup. On a 4 node NUMA system.

So when memory reclaim kicks in, there's a write process, a
writeback kworker and 4 kswapd kthreads all banging on the
mapping->tree_lock. There's an awful lot of concurrency happening
behind the scenes of that single user process writing to a file...

> The mapping tree lock has been around forever (it used to be a rw-lock
> long long ago), but I wonder if we might have moved more stuff into it
> (memory accounting comes to mind) causing much worse contention or
> something.

Yeah, there is now a crapton of accounting updated in
account_page_dirtied under the tree lock - memcg, writeback, node,
zone, task, etc. And there's a *lot* of code that
__delete_from_page_cache() can execute under the tree lock.

> Hmm. Just for fun, I googled "tree_lock contention". It's shown up
> before - back in 2006, and it was you hitting it back then too.

Of course! That, however, would have been when I was playing with
real big SGI machines, not a tiddly little 16p VM.... :P

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

[toc] | [prev] | [next] | [standalone]


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

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-08-12 20:10 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s5p46-59c-29@gated-at.bofh.it>
In reply to#1460939

[Multipart message — attachments visible in raw view] — view raw

On Thu, Aug 11, 2016 at 8:56 PM, Dave Chinner <david@fromorbit.com> wrote:
> On Thu, Aug 11, 2016 at 07:27:52PM -0700, Linus Torvalds wrote:
>>
>> I don't recall having ever seen the mapping tree_lock as a contention
>> point before, but it's not like I've tried that load either. So it
>> might be a regression (going back long, I suspect), or just an unusual
>> load that nobody has traditionally tested much.
>>
>> Single-threaded big file write one page at a time, was it?
>
> Yup. On a 4 node NUMA system.

Ok, I can't see any real contention on my single-node workstation
(running ext4 too, so there may be filesystem differences), but I
guess that shouldn't surprise me. The cacheline bouncing just isn't
expensive enough when it all stays on-die.

I can see the tree_lock in my profiles (just not very high), and at
least for ext4 the main caller ssems to be
__set_page_dirty_nobuffers().

And yes, looking at that, the biggest cost by _far_ inside the
spinlock seems to be the accounting.

Which doesn't even have to be inside the mapping lock, as far as I can
tell, and as far as comments go.

So a stupid patch to just move the dirty page accounting to outside
the spinlock might help a lot.

Does this attached patch help your contention numbers?

Adding a few people who get blamed for account_page_dirtied() and
inode_attach_wb() just to make sure that nobody expected the
mapping_lock spinlock to be held when calling account_page_dirtied().

I realize that this has nothing to do with the AIM7 regression (the
spinlock just isn't high enough in that profile), but your contention
numbers just aren't right, and updating accounting statistics inside a
critical spinlock when not needed is just wrong.

                Linus

[toc] | [prev] | [next] | [standalone]


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

FromFengguang Wu <fengguang.wu@intel.com>
Date2016-08-14 11:00 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s5ZqX-5AD-51@gated-at.bofh.it>
In reply to#1461361
Hi Linus,

On Fri, Aug 12, 2016 at 11:03:33AM -0700, Linus Torvalds wrote:
>On Thu, Aug 11, 2016 at 8:56 PM, Dave Chinner <david@fromorbit.com> wrote:
>> On Thu, Aug 11, 2016 at 07:27:52PM -0700, Linus Torvalds wrote:
>>>
>>> I don't recall having ever seen the mapping tree_lock as a contention
>>> point before, but it's not like I've tried that load either. So it
>>> might be a regression (going back long, I suspect), or just an unusual
>>> load that nobody has traditionally tested much.
>>>
>>> Single-threaded big file write one page at a time, was it?
>>
>> Yup. On a 4 node NUMA system.
>
>Ok, I can't see any real contention on my single-node workstation
>(running ext4 too, so there may be filesystem differences), but I
>guess that shouldn't surprise me. The cacheline bouncing just isn't
>expensive enough when it all stays on-die.
>
>I can see the tree_lock in my profiles (just not very high), and at
>least for ext4 the main caller ssems to be
>__set_page_dirty_nobuffers().
>
>And yes, looking at that, the biggest cost by _far_ inside the
>spinlock seems to be the accounting.
>
>Which doesn't even have to be inside the mapping lock, as far as I can
>tell, and as far as comments go.
>
>So a stupid patch to just move the dirty page accounting to outside
>the spinlock might help a lot.
>
>Does this attached patch help your contention numbers?
>
>Adding a few people who get blamed for account_page_dirtied() and
>inode_attach_wb() just to make sure that nobody expected the
>mapping_lock spinlock to be held when calling account_page_dirtied().
>
>I realize that this has nothing to do with the AIM7 regression (the
>spinlock just isn't high enough in that profile), but your contention
>numbers just aren't right, and updating accounting statistics inside a
>critical spinlock when not needed is just wrong.

I'm testing this patch on top of 9909170065 ("Merge tag 'nfs-for-4.8-2'
of git://git.linux-nfs.org/projects/trondmy/linux-nfs").

The BRD (Ram backed block device, drivers/block/brd.c) tests enables
pretty fast IO. And the fsmark-generic-brd-raid.yaml on lkp-hsx02 will
simulate 8 RAID disks on a 4-node NUMA machine.

queue -q vip -t ivb44 -b wfg/account_page_dirtied-linus aim7-fs-1brd.yaml  -R3 -k 1b5f2eb4a752e1fa7102f37545f92e64fabd0cf8 -k 99091700659f4df965e138b38b4fa26a29b7eade

queue -q vip -t ivb43 -b wfg/account_page_dirtied-linus fsmark-stress-journal-1hdd.yaml fsmark-stress-journal-1brd.yaml  -R3 -k 1b5f2eb4a752e1fa7102f37545f92e64fabd0cf8 -k 99091700659f4df965e138b38b4fa26a29b7eade

queue -q vip -t ivb44 -b wfg/account_page_dirtied-linus fsmark-generic-1brd.yaml dd-write-1hdd.yaml  fsmark-generic-1hdd.yaml   -R3 -k 1b5f2eb4a752e1fa7102f37545f92e64fabd0cf8 -k 99091700659f4df965e138b38b4fa26a29b7eade

queue -q vip -t lkp-hsx02 -b wfg/account_page_dirtied-linus fsmark-generic-brd-raid.yaml  -R3 -k 1b5f2eb4a752e1fa7102f37545f92e64fabd0cf8 -k 99091700659f4df965e138b38b4fa26a29b7eade

queue -q vip -t lkp-hsw-ep4 -b wfg/account_page_dirtied-linus fsmark-1ssd-nvme-small.yaml  -R3 -k 1b5f2eb4a752e1fa7102f37545f92e64fabd0cf8 -k 99091700659f4df965e138b38b4fa26a29b7eade

queue -q vip -t lkp-hsw-ep4 -b wfg/account_page_dirtied-linus fsmark-1ssd-nvme-small.yaml  -R3 -k 1b5f2eb4a752e1fa7102f37545f92e64fabd0cf8 -k 99091700659f4df965e138b38b4fa26a29b7eade

Thanks,
Fengguang

> fs/buffer.c         | 5 ++++-
> fs/xfs/xfs_aops.c   | 5 ++++-
> mm/page-writeback.c | 2 +-
> 3 files changed, 9 insertions(+), 3 deletions(-)
>
>diff --git a/fs/buffer.c b/fs/buffer.c
>index 9c8eb9b6db6a..f79a9d241589 100644
>--- a/fs/buffer.c
>+++ b/fs/buffer.c
>@@ -628,15 +628,18 @@ static void __set_page_dirty(struct page *page, struct address_space *mapping,
> 			     int warn)
> {
> 	unsigned long flags;
>+	bool account = false;
>
> 	spin_lock_irqsave(&mapping->tree_lock, flags);
> 	if (page->mapping) {	/* Race with truncate? */
> 		WARN_ON_ONCE(warn && !PageUptodate(page));
>-		account_page_dirtied(page, mapping);
> 		radix_tree_tag_set(&mapping->page_tree,
> 				page_index(page), PAGECACHE_TAG_DIRTY);
>+		account = true;
> 	}
> 	spin_unlock_irqrestore(&mapping->tree_lock, flags);
>+	if (account)
>+		account_page_dirtied(page, mapping);
> }
>
> /*
>diff --git a/fs/xfs/xfs_aops.c b/fs/xfs/xfs_aops.c
>index 7575cfc3ad15..59169c36765e 100644
>--- a/fs/xfs/xfs_aops.c
>+++ b/fs/xfs/xfs_aops.c
>@@ -1490,15 +1490,18 @@ xfs_vm_set_page_dirty(
> 	if (newly_dirty) {
> 		/* sigh - __set_page_dirty() is static, so copy it here, too */
> 		unsigned long flags;
>+		bool account = false;
>
> 		spin_lock_irqsave(&mapping->tree_lock, flags);
> 		if (page->mapping) {	/* Race with truncate? */
> 			WARN_ON_ONCE(!PageUptodate(page));
>-			account_page_dirtied(page, mapping);
> 			radix_tree_tag_set(&mapping->page_tree,
> 					page_index(page), PAGECACHE_TAG_DIRTY);
>+			account = true;
> 		}
> 		spin_unlock_irqrestore(&mapping->tree_lock, flags);
>+		if (account)
>+			account_page_dirtied(page, mapping);
> 	}
> 	unlock_page_memcg(page);
> 	if (newly_dirty)
>diff --git a/mm/page-writeback.c b/mm/page-writeback.c
>index f4cd7d8005c9..9a6a6b99acfe 100644
>--- a/mm/page-writeback.c
>+++ b/mm/page-writeback.c
>@@ -2517,10 +2517,10 @@ int __set_page_dirty_nobuffers(struct page *page)
> 		spin_lock_irqsave(&mapping->tree_lock, flags);
> 		BUG_ON(page_mapping(page) != mapping);
> 		WARN_ON_ONCE(!PagePrivate(page) && !PageUptodate(page));
>-		account_page_dirtied(page, mapping);
> 		radix_tree_tag_set(&mapping->page_tree, page_index(page),
> 				   PAGECACHE_TAG_DIRTY);
> 		spin_unlock_irqrestore(&mapping->tree_lock, flags);
>+		account_page_dirtied(page, mapping);
> 		unlock_page_memcg(page);
>
> 		if (mapping->host) {

[toc] | [prev] | [next] | [standalone]


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

FromDave Chinner <david@fromorbit.com>
Date2016-08-15 02:50 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6egh-6V0-1@gated-at.bofh.it>
In reply to#1461361
On Fri, Aug 12, 2016 at 11:03:33AM -0700, Linus Torvalds wrote:
> On Thu, Aug 11, 2016 at 8:56 PM, Dave Chinner <david@fromorbit.com> wrote:
> > On Thu, Aug 11, 2016 at 07:27:52PM -0700, Linus Torvalds wrote:
> >>
> >> I don't recall having ever seen the mapping tree_lock as a contention
> >> point before, but it's not like I've tried that load either. So it
> >> might be a regression (going back long, I suspect), or just an unusual
> >> load that nobody has traditionally tested much.
> >>
> >> Single-threaded big file write one page at a time, was it?
> >
> > Yup. On a 4 node NUMA system.
> 
> Ok, I can't see any real contention on my single-node workstation
> (running ext4 too, so there may be filesystem differences), but I
> guess that shouldn't surprise me. The cacheline bouncing just isn't
> expensive enough when it all stays on-die.
> 
> I can see the tree_lock in my profiles (just not very high), and at
> least for ext4 the main caller ssems to be
> __set_page_dirty_nobuffers().
> 
> And yes, looking at that, the biggest cost by _far_ inside the
> spinlock seems to be the accounting.
> 
> Which doesn't even have to be inside the mapping lock, as far as I can
> tell, and as far as comments go.
> 
> So a stupid patch to just move the dirty page accounting to outside
> the spinlock might help a lot.
> 
> Does this attached patch help your contention numbers?

No. If anything, it makes it worse. Without the patch, I was
measuring 36-37% in _raw_spin_unlock_irqrestore. With the patch, it
is 42-43%. Write throughtput is the same at ~505MB/s.

There's a couple of interesting things showing up in the profile:

  41.64%  [kernel]  [k] _raw_spin_unlock_irqrestore
   7.92%  [kernel]  [k] copy_user_generic_string
   5.87%  [kernel]  [k] _raw_spin_unlock_irq
   3.18%  [kernel]  [k] do_raw_spin_lock
   2.51%  [kernel]  [k] cancel_dirty_page         <<<<<<<<<<<<<<<
   2.35%  [kernel]  [k] get_page_from_freelist
   2.22%  [kernel]  [k] shrink_page_list
   2.04%  [kernel]  [k] __block_commit_write.isra.30
   1.40%  [kernel]  [k] xfs_vm_releasepage
   1.21%  [kernel]  [k] free_hot_cold_page
   1.17%  [kernel]  [k] delay_tsc
   1.12%  [kernel]  [k] __wake_up_bit
   0.92%  [kernel]  [k] __slab_free
   0.91%  [kernel]  [k] clear_page_dirty_for_io
   0.82%  [kernel]  [k] __radix_tree_lookup
   0.76%  [kernel]  [k] node_dirty_ok
   0.68%  [kernel]  [k] page_evictable
   0.63%  [kernel]  [k] do_raw_spin_unlock
   0.62%  [kernel]  [k] up_write
.....

Why are we even calling into cancel_dirty_page() if the page isn't
dirty? xfs_vm_release_page() won't let dirty pages through to
try_to_free_buffers(), so all this is just pure overhead for XFS.


FWIW, this is not under the mapping->tree_lock, but the profile shows
that reclaiming bufferheads is roughly 20% of all the work kswapd is
doing. If we take away the mapping->tree_lock contention from the
usage totals, it's actually closer to 50% of the real work kswapd is
doing. The call graph profile is pretty grim:

-   41.89%     0.00%  [kernel]          [k] kswapd
   - kswapd
      - 41.84% shrink_node
         - 41.61% shrink_node_memcg.isra.75
            - 41.50% shrink_inactive_list
               - 40.21% shrink_page_list
                  - 26.47% __remove_mapping
                       26.30% _raw_spin_unlock_irqrestore
                  + 9.03% try_to_release_page
                     - 8.82% try_to_release_page
                        - 8.80% xfs_vm_releasepage
                             7.55% try_to_free_buffers
                  + 1.56% free_hot_cold_page_list
                    0.73% page_evictable
                 0.88% _raw_spin_unlock_irq

I guess now that the iomap code is in and we no longer really depend
on bufferheads in the writeback path, it's time to take the next
step in removing bufferheads from XFS altogether....

> I realize that this has nothing to do with the AIM7 regression (the
> spinlock just isn't high enough in that profile), but your contention
> numbers just aren't right, and updating accounting statistics inside a
> critical spinlock when not needed is just wrong.

Yup, but the above profile shows that the lock contention is mainly
coming from concurrent access in memory reclaim so I don't think the
accounting has anything to do with it.

Perhaps some kind of per-mapping reclaim batching reduce the
__remove_mapping() locking overhead is in order here. Especially as
this problem will only get worse on larger NUMA machines....

Cheers,

Dave.

-- 
Dave Chinner
david@fromorbit.com

[toc] | [prev] | [next] | [standalone]


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

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-08-15 03:40 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6f2G-7rv-7@gated-at.bofh.it>
In reply to#1462515
On Sun, Aug 14, 2016 at 5:48 PM, Dave Chinner <david@fromorbit.com> wrote:
>>
>> Does this attached patch help your contention numbers?
>
> No. If anything, it makes it worse. Without the patch, I was
> measuring 36-37% in _raw_spin_unlock_irqrestore. With the patch, it
> is 42-43%. Write throughtput is the same at ~505MB/s.

Not helping any I can see, but I don't see how it could hurt...

Did you perhaps test it together with the other patches that improved
xfs performance? If other things improve, then I'd expect the
contention to get worse.

Not that it matters. Clearly that patch isn't even a stop-gap solution.

> There's a couple of interesting things showing up in the profile:
>
>   41.64%  [kernel]  [k] _raw_spin_unlock_irqrestore

Actually, you didn't point this one out, but *this* is the real kicker.

There's no way a *unlock* should show up that high. It's not spinning.
It's doing a single store and a pushq/popfq sequence.

Sure, it's going to take a cross-node cachemiss in the presence of
contention, but even then it should never be more expensive than the
locking side - which will *also* do the node changes.

So there's something really odd in your profile. I don't think that's valid.

Maybe your symbol table came from a old kernel, and functions moved
around enough that the profile attributions ended up bogus.

I suspect it's actually supposed to be _raw_spin_lock_irqrestore()
which is right next to that function. Although I'd actually expect
that if it's lock contention, you should see the contention mostly in
queued_spin_lock_slowpath().

Unless you have spinlock debugging turned on, in which case your
contention is all from *that*. That's possible, of course.

>    7.92%  [kernel]  [k] copy_user_generic_string
>    5.87%  [kernel]  [k] _raw_spin_unlock_irq
>    3.18%  [kernel]  [k] do_raw_spin_lock
>    2.51%  [kernel]  [k] cancel_dirty_page         <<<<<<<<<<<<<<<
...
> Why are we even calling into cancel_dirty_page() if the page isn't
> dirty? xfs_vm_release_page() won't let dirty pages through to
> try_to_free_buffers(), so all this is just pure overhead for XFS.

See above: there's something screwy with your profile, you should
check that first. Maybe it's not actually cancel_dirty_page() but
something close-by.

(Although I don't see anything closeby normally, so even if the
spin_unlock_irq is bogus, I think *that* part may be incorrect.

Anyway, the reason you'd get cancel_dirty_page() is either due to
truncate, or due to try_to_free_buffers() having dropped the buffers
successfully because the filesystem had already written them out, but
the page is still marked dirty.

> FWIW, this is not under the mapping->tree_lock, but the profile shows
> that reclaiming bufferheads is roughly 20% of all the work kswapd is
> doing.

Well, that may not actually be wrong. That's the most expensive part
of reclaiming memory.

But please double-check your profile, because something is seriously
wrong in it.

            Linus

[toc] | [prev] | [next] | [standalone]


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

FromDave Chinner <david@fromorbit.com>
Date2016-08-15 04:40 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6fYJ-85I-5@gated-at.bofh.it>
In reply to#1462518
On Sun, Aug 14, 2016 at 06:37:33PM -0700, Linus Torvalds wrote:
> On Sun, Aug 14, 2016 at 5:48 PM, Dave Chinner <david@fromorbit.com> wrote:
> >>
> >> Does this attached patch help your contention numbers?
> >
> > No. If anything, it makes it worse. Without the patch, I was
> > measuring 36-37% in _raw_spin_unlock_irqrestore. With the patch, it
> > is 42-43%. Write throughtput is the same at ~505MB/s.
> 
> Not helping any I can see, but I don't see how it could hurt...
> 
> Did you perhaps test it together with the other patches that improved
> xfs performance? If other things improve, then I'd expect the
> contention to get worse.
> 
> Not that it matters. Clearly that patch isn't even a stop-gap solution.

Tried it with and without. Same result.

> > There's a couple of interesting things showing up in the profile:
> >
> >   41.64%  [kernel]  [k] _raw_spin_unlock_irqrestore
> 
> Actually, you didn't point this one out, but *this* is the real kicker.
> 
> There's no way a *unlock* should show up that high. It's not spinning.
> It's doing a single store and a pushq/popfq sequence.
> 
> Sure, it's going to take a cross-node cachemiss in the presence of
> contention, but even then it should never be more expensive than the
> locking side - which will *also* do the node changes.
> 
> So there's something really odd in your profile. I don't think that's valid.
> 
> Maybe your symbol table came from a old kernel, and functions moved
> around enough that the profile attributions ended up bogus.

No, I don't think so. I don't install symbol tables on my test VMs,
I let /proc/kallsyms do that work for me. From an strace of 'perf
top -U -g":

18916 open("vmlinux", O_RDONLY)         = -1 ENOENT (No such file or directory)
18916 open("/boot/vmlinux", O_RDONLY)   = -1 ENOENT (No such file or directory)
18916 open("/boot/vmlinux-4.8.0-rc1-dgc+", O_RDONLY) = -1 ENOENT (No such file or directory)
18916 open("/usr/lib/debug/boot/vmlinux-4.8.0-rc1-dgc+", O_RDONLY) = -1 ENOENT (No such file or directory)
18916 open("/lib/modules/4.8.0-rc1-dgc+/build/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
18916 open("/usr/lib/debug/lib/modules/4.8.0-rc1-dgc+/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
18916 open("/usr/lib/debug/boot/vmlinux-4.8.0-rc1-dgc+.debug", O_RDONLY) = -1 ENOENT (No such file or directory)
18916 open("/root/.debug/.build-id/63/aab665ce90bd81763b90ff2cf103d8e8e823bc", O_RDONLY) = -1 ENOENT (No such file or directory)
18916 open("/sys/kernel/notes", O_RDONLY) = 56
18916 read(56, "\4\0\0\0\24\0\0\0\3\0\0\0", 12) = 12
18916 read(56, "GNU\0", 4)              = 4
18916 read(56, "c\252\266e\316\220\275\201v;\220\377,\361\3\330\350\350#\274", 20) = 20
18916 close(56)                         = 0
18916 open("/root/.debug/[kernel.kcore]/63aab665ce90bd81763b90ff2cf103d8e8e823bc", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
18916 open("/proc/kallsyms", O_RDONLY)  = 56
18916 fstat(56, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
18916 read(56, "0000000000000000 A irq_stack_uni"..., 1024) = 1024
18916 read(56, "a\n000000000000b8c0 A rsp_scratch"..., 1024) = 1024
18916 read(56, "0000000c6e0 A cmci_storm_state\n0"..., 1024) = 1024
18916 read(56, "000000ccd8 A sd_llc_id\n000000000"..., 1024) = 1024

You can see that perf is pulling the symbol table from the running
kernel, so I don't think there's a symbol mismatch here at all.

> I suspect it's actually supposed to be _raw_spin_lock_irqrestore()
> which is right next to that function. Although I'd actually expect
> that if it's lock contention, you should see the contention mostly in
> queued_spin_lock_slowpath().
> 
> Unless you have spinlock debugging turned on, in which case your
> contention is all from *that*. That's possible, of course.

$ grep SPINLOCK .config
CONFIG_ARCH_USE_QUEUED_SPINLOCKS=y
CONFIG_QUEUED_SPINLOCKS=y
CONFIG_PARAVIRT_SPINLOCKS=y
CONFIG_DEBUG_SPINLOCK=y
$

So, turn off CONFIG_DEBUG_SPINLOCK, and:

  41.06%  [kernel]  [k] _raw_spin_unlock_irqrestore
   7.68%  [kernel]  [k] copy_user_generic_string
   4.52%  [kernel]  [k] _raw_spin_unlock_irq
   2.78%  [kernel]  [k] _raw_spin_lock
   2.30%  [kernel]  [k] get_page_from_freelist
   2.21%  [kernel]  [k] native_queued_spin_lock_slowpath
   2.16%  [kernel]  [k] __slab_free
   2.12%  [kernel]  [k] __block_commit_write.isra.29
   1.55%  [kernel]  [k] __list_add
   1.49%  [kernel]  [k] shrink_page_list
   1.23%  [kernel]  [k] free_hot_cold_page
   1.14%  [kernel]  [k] __wake_up_bit
   1.01%  [kernel]  [k] try_to_release_page
   1.00%  [kernel]  [k] page_evictable
   0.90%  [kernel]  [k] cancel_dirty_page
   0.80%  [kernel]  [k] unlock_page
   0.80%  [kernel]  [k] up_write
   0.73%  [kernel]  [k] ___might_sleep
   0.68%  [kernel]  [k] clear_page_dirty_for_io
   0.64%  [kernel]  [k] __radix_tree_lookup
   0.61%  [kernel]  [k] __block_write_begin_int
   0.60%  [kernel]  [k] xfs_do_writepage
   0.59%  [kernel]  [k] node_dirty_ok
   0.55%  [kernel]  [k] down_write
   0.50%  [kernel]  [k] page_mapping
   0.47%  [kernel]  [k] iomap_write_actor


-   38.29%     0.01%  [kernel]            [k] kswapd
   - 38.28% kswapd
      - 38.23% shrink_node
         - 38.14% shrink_node_memcg.isra.75
            - 38.09% shrink_inactive_list
               - 36.90% shrink_page_list
                  - 24.41% __remove_mapping
                       24.16% _raw_spin_unlock_irqrestore
                  - 7.42% try_to_release_page
                     - 6.77% xfs_vm_releasepage
                        - 4.76% try_to_free_buffers
                           - 2.05% free_buffer_head
                              - 2.01% kmem_cache_free
                                   1.94% __slab_free
                           - 1.24% _raw_spin_lock
                                native_queued_spin_lock_slowpath
                             0.89% cancel_dirty_page
                          1.61% _raw_spin_lock
                  + 1.53% free_hot_cold_page_list
                    1.03% __list_add
                    0.74% page_evictable
                 0.86% _raw_spin_unlock_irq

No change in behaviour, and there's no obvious problems with the
call chain.

> >    7.92%  [kernel]  [k] copy_user_generic_string
> >    5.87%  [kernel]  [k] _raw_spin_unlock_irq
> >    3.18%  [kernel]  [k] do_raw_spin_lock
> >    2.51%  [kernel]  [k] cancel_dirty_page         <<<<<<<<<<<<<<<
> ...
> > Why are we even calling into cancel_dirty_page() if the page isn't
> > dirty? xfs_vm_release_page() won't let dirty pages through to
> > try_to_free_buffers(), so all this is just pure overhead for XFS.
> 
> See above: there's something screwy with your profile, you should
> check that first. Maybe it's not actually cancel_dirty_page() but
> something close-by.

No. try_to_free_buffers() calls drop_buffers(), which returns 1 when
the buffers are to be dropped. And when that happens, it *always*
calls cancel_dirty_page(), regardless of whether the page is
actually dirty or not.

fmeh. This was all screwed up by the memcg aware writeback. Starting
with commit 11f81be ("page_writeback: revive cancel_dirty_page() in a
restricted form") and then adding unconditional functionality that
can, in fact, *take the mapping->tree_lock* under the covers. i.e
unlocked_inode_to_wb_begin() hides that gem, which appears to be
neceessary for the accounting done when cleaning up a dirty page in
this location.

Still, why is it doing all this work on *clean pages*?

> > FWIW, this is not under the mapping->tree_lock, but the profile shows
> > that reclaiming bufferheads is roughly 20% of all the work kswapd is
> > doing.
> 
> Well, that may not actually be wrong. That's the most expensive part
> of reclaiming memory.

All the more reason for not using them.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

[toc] | [prev] | [next] | [standalone]


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

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-08-15 05:00 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6gi5-8bY-3@gated-at.bofh.it>
In reply to#1462526
On Sun, Aug 14, 2016 at 7:28 PM, Dave Chinner <david@fromorbit.com> wrote:
>>
>> Maybe your symbol table came from a old kernel, and functions moved
>> around enough that the profile attributions ended up bogus.
>
> No, I don't think so. I don't install symbol tables on my test VMs,
> I let /proc/kallsyms do that work for me. From an strace of 'perf
> top -U -g":

Ok. But something is definitely wrong with your profile.

What does it say if you annotate that _raw_spin_unlock_irqrestore() function?

I guarantee you that no, it's not spending 41% of time in
spin_unlock_irqrestore. That just isn't a valid profile. There's
something seriously wrong somewhere.

The fact that you then get the same profile when you turn _off_
CONFIG_DEBUG_SPINLOCK only proves there is something going on that is
pure garbage.

I suspect that what you did was to edit the .config file, remove
DEBUG_SPINLOCK, and then do "make oldconfig" again.

And it got turned on again, because you have one of the lock debugging
options on that force spinlock debuggin on again:

 - DEBUG_WW_MUTEX_SLOWPATH
 - DEBUG_LOCK_ALLOC
 - PROVE_LOCKING

all of which would make any profiles entirely pointless.

[ Light goes on ]

Oh, no, I can see another possibility: you're not doing proper CPU
profiles, you're doing some timer-irq profile, and the reason you get
41% on spin_unlock_irq_restore() is that that is where the interrupts
are enabled again.

Timer-interrupt based profiles are not useful either.

Make sure you actually use "perf record -e cycles:pp" or something
that uses PEBS to get real profiles using CPU performance counters.

Because right now the profile data is worthless.

            Linus

[toc] | [prev] | [next] | [standalone]


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

FromDave Chinner <david@fromorbit.com>
Date2016-08-15 07:10 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6ijU-1fL-21@gated-at.bofh.it>
In reply to#1462530
On Sun, Aug 14, 2016 at 07:53:40PM -0700, Linus Torvalds wrote:
> On Sun, Aug 14, 2016 at 7:28 PM, Dave Chinner <david@fromorbit.com> wrote:
> >>
> >> Maybe your symbol table came from a old kernel, and functions moved
> >> around enough that the profile attributions ended up bogus.
> >
> > No, I don't think so. I don't install symbol tables on my test VMs,
> > I let /proc/kallsyms do that work for me. From an strace of 'perf
> > top -U -g":
> 
> Ok. But something is definitely wrong with your profile.
> 
> What does it say if you annotate that _raw_spin_unlock_irqrestore() function?
....

raw_spin_unlock_irqrestore  /proc/kcore
       ¿
       ¿
       ¿
       ¿    Disassembly of section load0:
       ¿
       ¿    ffffffff81e628b0 <load0>:
       ¿      nop
       ¿      push   %rbp
       ¿      mov    %rsp,%rbp
       ¿      movb   $0x0,(%rdi)
       ¿      nop
       ¿      mov    %rsi,%rdi
       ¿      push   %rdi
       ¿      popfq
 99.35 ¿      nop
       ¿      decl   %gs:0x7e1a9bc7(%rip)
  0.65 ¿    ¿ je     25
       ¿      pop    %rbp
       ¿    ¿ retq
       ¿25:   callq  0xffffffff81002000
       ¿      pop    %rbp
       ¿    ¿ retq


> I guarantee you that no, it's not spending 41% of time in
> spin_unlock_irqrestore. That just isn't a valid profile. There's
> something seriously wrong somewhere.
> 
> The fact that you then get the same profile when you turn _off_
> CONFIG_DEBUG_SPINLOCK only proves there is something going on that is
> pure garbage.
> 
> I suspect that what you did was to edit the .config file, remove
> DEBUG_SPINLOCK, and then do "make oldconfig" again.

Yes.

> And it got turned on again,

No. I'm not that stupid - I checked:

$ grep SPINLOCK .config
CONFIG_ARCH_USE_QUEUED_SPINLOCKS=y
CONFIG_QUEUED_SPINLOCKS=y
CONFIG_PARAVIRT_SPINLOCKS=y
# CONFIG_DEBUG_SPINLOCK is not set
$

> because you have one of the lock debugging
> options on that force spinlock debuggin on again:

>  - DEBUG_WW_MUTEX_SLOWPATH
>  - DEBUG_LOCK_ALLOC
>  - PROVE_LOCKING

None of which are set:

$ grep 'DEBUG\|PROVE' .config |grep -v '#'
CONFIG_ARCH_SUPPORTS_DEBUG_PAGEALLOC=y
CONFIG_DEBUG_RODATA=y
CONFIG_SLUB_DEBUG=y
CONFIG_HAVE_DMA_API_DEBUG=y
CONFIG_X86_DEBUGCTLMSR=y
CONFIG_PM_DEBUG=y
CONFIG_PM_SLEEP_DEBUG=y
CONFIG_DEBUG_DEVRES=y
CONFIG_PNP_DEBUG_MESSAGES=y
CONFIG_XFS_DEBUG=y
CONFIG_OCFS2_DEBUG_MASKLOG=y
CONFIG_CIFS_DEBUG=y
CONFIG_DEBUG_INFO=y
CONFIG_DEBUG_FS=y
CONFIG_DEBUG_KERNEL=y
CONFIG_HAVE_DEBUG_KMEMLEAK=y
CONFIG_DEBUG_STACK_USAGE=y
CONFIG_HAVE_DEBUG_STACKOVERFLOW=y
CONFIG_SCHED_DEBUG=y
CONFIG_DEBUG_MUTEXES=y
CONFIG_DEBUG_ATOMIC_SLEEP=y
CONFIG_DEBUG_BUGVERBOSE=y
CONFIG_DEBUG_LIST=y
CONFIG_FAULT_INJECTION_DEBUG_FS=y
CONFIG_ARCH_HAS_DEBUG_STRICT_USER_COPY_CHECKS=y
CONFIG_DEBUG_BOOT_PARAMS=y
$

> [ Light goes on ]
> 
> Oh, no, I can see another possibility: you're not doing proper CPU
> profiles, you're doing some timer-irq profile, and the reason you get
> 41% on spin_unlock_irq_restore() is that that is where the interrupts
> are enabled again.
> 
> Timer-interrupt based profiles are not useful either.

I've just been using whatever perf defaults to. Defaults are
supposed to be useful - if they aren't then perf needs to be fixed.
perf top reports this by default:

Samples: 118K of event 'cpu-clock', Event count (approx.): 793748915
Overhead  Shared O  Symbol                                                                                                                                             ¿
  34.48%  [kernel]  [k] _raw_spin_unlock_irqrestore                                                                                                                    ¿
   7.89%  [kernel]  [k] copy_user_generic_string                                                                                                                       ¿
   5.08%  [kernel]  [k] _raw_spin_unlock_irq

...

> Make sure you actually use "perf record -e cycles:pp" or something
> that uses PEBS to get real profiles using CPU performance counters.

WTF is PEBS? I'm not a CPU nerd, and I certainly don't expect to
have to learn all the intricacies of hardware performance counters
just to profile the kernel in a correct and sane manner. That's what
the *perf defaults* are supposed to do.


Anyway: `perf top -U -e cycles:pp`:

Samples: 301K of event 'cpu-clock:ppH', Event count (approx.): 69364814
Overhead  Shared O  Symbol                                                                                                                                             ¿
  30.89%  [kernel]  [k] _raw_spin_unlock_irqrestore                                                                                                                    ¿
   7.04%  [kernel]  [k] _raw_spin_unlock_irq                                                                                                                           ¿
   4.08%  [kernel]  [k] copy_user_generic_string                                                                                                                       ¿
   2.44%  [kernel]  [k] get_page_from_freelist                                                                                                                         ¿
   1.81%  [kernel]  [k] _raw_spin_lock

No change.

$ sudo perf record -e cycles:pp -a --all-kernel -- xfs_io -f -c "pwrite 0 47g" /mnt/scratch/fooey

# Samples: 2M of event 'cpu-clock:khppH'
# Event count (approx.): 588517250000
#
# Overhead  Command          Shared Object      Symbol                                    
# ........  ...............  .................  ..........................................
#
    83.09%  swapper          [kernel.kallsyms]  [k] native_safe_halt
     1.42%  xfs_io           [kernel.kallsyms]  [k] copy_user_generic_string
     1.26%  kswapd3          [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
     1.24%  kswapd1          [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
     1.09%  kswapd2          [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
     0.98%  kswapd0          [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
     0.80%  xfs_io           [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
     0.77%  kworker/u34:2    [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
     0.73%  xfs_io           [kernel.kallsyms]  [k] _raw_spin_unlock_irq
     0.51%  xfs_io           [kernel.kallsyms]  [k] get_page_from_freelist
     0.39%  xfs_io           [kernel.kallsyms]  [k] __block_commit_write.isra.29
     0.16%  xfs_io           [kernel.kallsyms]  [k] _raw_spin_lock
     0.14%  xfs_io           [kernel.kallsyms]  [k] up_write
     0.14%  kworker/u34:2    [kernel.kallsyms]  [k] clear_page_dirty_for_io
     0.14%  kworker/u34:2    [kernel.kallsyms]  [k] xfs_do_writepage
....

It's exactly the same profile, just reported as a percentage of 16
CPUs rather than normalised to a single CPU.  From my ignorant
viewpoing, I'd say that's expected because perf is still using
"cpu-clock" event configuration.

The hardware event counters are undocumented in the perf man pages,
perf-list doesn't output a single "cpu" or "cycles" event counter,
or even what hardware event counters are available. Hence I've got
no idea if it's broken, why "cycles" (or "cpu-cycles") doesn't
apparently record "cycle" triggered events, or even what perf is
supposed to tell me is it's recording cycle triggered events.

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

[toc] | [prev] | [next] | [standalone]


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

FromDave Chinner <david@fromorbit.com>
Date2016-08-16 00:30 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6yyl-38I-7@gated-at.bofh.it>
In reply to#1462550
On Sun, Aug 14, 2016 at 10:12:20PM -0700, Linus Torvalds wrote:
> On Aug 14, 2016 10:00 PM, "Dave Chinner" <david@fromorbit.com> wrote:
> >
> > > What does it say if you annotate that _raw_spin_unlock_irqrestore()
> function?
> > ....
> >        ¿
> >        ¿    Disassembly of section load0:
> >        ¿
> >        ¿    ffffffff81e628b0 <load0>:
> >        ¿      nop
> >        ¿      push   %rbp
> >        ¿      mov    %rsp,%rbp
> >        ¿      movb   $0x0,(%rdi)
> >        ¿      nop
> >        ¿      mov    %rsi,%rdi
> >        ¿      push   %rdi
> >        ¿      popfq
> >  99.35 ¿      nop
> 
> Yeah, that's a good disassembly of a non-debug spin unlock, and the symbols
> are fine, but the profile is not valid. That's an interrupt point, right
> after the popf that enables interiors again.
> 
> I don't know why 'perf' isn't working on your machine, but it clearly
> isn't.
> 
> Has it ever worked on that machine?

It's working the same as it's worked since I started using it many
years ago.

> What cpu is it?

Intel(R) Xeon(R) CPU E5-4620 0 @ 2.20GHz

> Are you running in some
> virtualized environment without performance counters, perhaps?

I've mentioned a couple of times in this thread that I'm testing
inside a VM. It's the same VM I've been running performance tests in
since early 2010. Nobody has complained that the profiles I've
posted are useless before, and not once in all that time have they
been wrong in indicating a spinning lock contention point.

i.e. In previous cases where I've measured double digit CPU usage
numbers in a spin_unlock variant, it's always been a result of
spinlock contention. And fixing the algorithmic problem that lead to
the spinlock showing up in the profile in the first place has always
substantially improved performance and scalability.

As such, I'm always going to treat a locking profile like that as
contention because even if it isn't contending *on my machine*,
that amount of work being done under a spinning lock is /way too
much/ and it *will* cause contention problems with larger machines.

> It's not actually the unlock that is expensive, and there is no contention
> on the lock (if there had been, the numbers would have been entirely
> different for the debug case, which makes locking an order of magnitude
> more expensive). All the cost of everything that happened while interrupts
> were disabled is just accounted to the instruction after they were enabled
> again.

Right, but that does not make the profile data useless, nor you
should shoot the messenger because they weren't supplied with
information you think should have been in the message. The message
still says that the majority of the overhead is in
__remove_mapping(), and it's an excessive amount of work being done
inside the tree_lock with interrupts disabled....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

[toc] | [prev] | [next] | [standalone]


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

FromDave Chinner <david@fromorbit.com>
Date2016-08-16 00:50 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6yRI-3f5-13@gated-at.bofh.it>
In reply to#1463223
On Tue, Aug 16, 2016 at 08:22:11AM +1000, Dave Chinner wrote:
> On Sun, Aug 14, 2016 at 10:12:20PM -0700, Linus Torvalds wrote:
> > On Aug 14, 2016 10:00 PM, "Dave Chinner" <david@fromorbit.com> wrote:
> > >
> > > > What does it say if you annotate that _raw_spin_unlock_irqrestore()
> > function?
> > > ....
> > >        ¿
> > >        ¿    Disassembly of section load0:
> > >        ¿
> > >        ¿    ffffffff81e628b0 <load0>:
> > >        ¿      nop
> > >        ¿      push   %rbp
> > >        ¿      mov    %rsp,%rbp
> > >        ¿      movb   $0x0,(%rdi)
> > >        ¿      nop
> > >        ¿      mov    %rsi,%rdi
> > >        ¿      push   %rdi
> > >        ¿      popfq
> > >  99.35 ¿      nop
> > 
> > Yeah, that's a good disassembly of a non-debug spin unlock, and the symbols
> > are fine, but the profile is not valid. That's an interrupt point, right
> > after the popf that enables interiors again.
> > 
> > I don't know why 'perf' isn't working on your machine, but it clearly
> > isn't.
> > 
> > Has it ever worked on that machine?
> 
> It's working the same as it's worked since I started using it many
> years ago.
> 
> > What cpu is it?
> 
> Intel(R) Xeon(R) CPU E5-4620 0 @ 2.20GHz
> 
> > Are you running in some
> > virtualized environment without performance counters, perhaps?
> 
> I've mentioned a couple of times in this thread that I'm testing
> inside a VM. It's the same VM I've been running performance tests in
> since early 2010. Nobody has complained that the profiles I've
> posted are useless before, and not once in all that time have they
> been wrong in indicating a spinning lock contention point.
> 
> i.e. In previous cases where I've measured double digit CPU usage
> numbers in a spin_unlock variant, it's always been a result of
> spinlock contention. And fixing the algorithmic problem that lead to
> the spinlock showing up in the profile in the first place has always
> substantially improved performance and scalability.
> 
> As such, I'm always going to treat a locking profile like that as
> contention because even if it isn't contending *on my machine*,
> that amount of work being done under a spinning lock is /way too
> much/ and it *will* cause contention problems with larger machines.

And, so, after helpfully being pointed at the magic kvm "-cpu host"
flag to enable access to the performance counters from the guest
(using "-e cycles", because more precise counters aren't available),
the profile looks like this:

  31.18%  [kernel]  [k] __pv_queued_spin_lock_slowpath
   9.90%  [kernel]  [k] copy_user_generic_string
   3.65%  [kernel]  [k] __raw_callee_save___pv_queued_spin_unlock
   2.62%  [kernel]  [k] __block_commit_write.isra.29
   2.26%  [kernel]  [k] _raw_spin_lock_irqsave
   1.72%  [kernel]  [k] _raw_spin_lock    
   1.33%  [kernel]  [k] __wake_up_bit
   1.20%  [kernel]  [k] __radix_tree_lookup
   1.19%  [kernel]  [k] __remove_mapping  
   1.12%  [kernel]  [k] __delete_from_page_cache
   0.97%  [kernel]  [k] xfs_do_writepage  
   0.91%  [kernel]  [k] get_page_from_freelist
   0.90%  [kernel]  [k] up_write          
   0.88%  [kernel]  [k] clear_page_dirty_for_io
   0.83%  [kernel]  [k] radix_tree_tag_set
   0.81%  [kernel]  [k] radix_tree_tag_clear
   0.80%  [kernel]  [k] down_write
   0.78%  [kernel]  [k] _raw_spin_unlock_irqrestore
   0.77%  [kernel]  [k] shrink_page_list
   0.76%  [kernel]  [k] ___might_sleep
   0.76%  [kernel]  [k] unlock_page
   0.74%  [kernel]  [k] __list_del_entry
   0.67%  [kernel]  [k] __add_to_page_cache_locked
   0.65%  [kernel]  [k] node_dirty_ok
   0.61%  [kernel]  [k] __rmqueue
   0.61%  [kernel]  [k] __block_write_begin_int
   0.61%  [kernel]  [k] cancel_dirty_page
   0.61%  [kernel]  [k] __test_set_page_writeback
   0.59%  [kernel]  [k] page_mapping
   0.57%  [kernel]  [k] __list_add
   0.56%  [kernel]  [k] free_pcppages_bulk
   0.54%  [kernel]  [k] _raw_spin_lock_irq
   0.54%  [kernel]  [k] generic_write_end
   0.51%  [kernel]  [k] drop_buffers

The call graph should be familiar by now:

   36.60%     0.00%  [kernel]            [k] kswapd
   - 30.29% kswapd  
      - 30.23% shrink_node
         - 30.07% shrink_node_memcg.isra.75
            - 30.15% shrink_inactive_list
               - 29.49% shrink_page_list
                  - 22.79% __remove_mapping
                     - 22.27% _raw_spin_lock_irqsave
                          __pv_queued_spin_lock_slowpath
                     + 1.86% __delete_from_page_cache
                     + 1.27% _raw_spin_unlock_irqrestore
                  + 4.31% try_to_release_page
                  + 1.21% free_hot_cold_page_list
                    0.56% page_evictable
                 0.77% isolate_lru_pages.isra.72

That sure looks like spin lock contention to me....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

[toc] | [prev] | [next] | [standalone]


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

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-08-16 01:30 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6zup-3Hz-9@gated-at.bofh.it>
In reply to#1463238
On Mon, Aug 15, 2016 at 3:42 PM, Dave Chinner <david@fromorbit.com> wrote:
>
>   31.18%  [kernel]  [k] __pv_queued_spin_lock_slowpath
>    9.90%  [kernel]  [k] copy_user_generic_string
>    3.65%  [kernel]  [k] __raw_callee_save___pv_queued_spin_unlock
>    2.62%  [kernel]  [k] __block_commit_write.isra.29
>    2.26%  [kernel]  [k] _raw_spin_lock_irqsave
>    1.72%  [kernel]  [k] _raw_spin_lock

Ok, this is more like it.

I'd still like to see it on raw hardware, just to see if we may have a
bug in the PV code. Because that code has been buggy before. I
*thought* we fixed it, but ...

In fact, you don't even need to do it outside of virtualization, but
with paravirt disabled (so that it runs the native non-pv locking in
the virtual machine).

>    36.60%     0.00%  [kernel]            [k] kswapd
>    - 30.29% kswapd
>       - 30.23% shrink_node
>          - 30.07% shrink_node_memcg.isra.75
>             - 30.15% shrink_inactive_list
>                - 29.49% shrink_page_list
>                   - 22.79% __remove_mapping
>                      - 22.27% _raw_spin_lock_irqsave
>                           __pv_queued_spin_lock_slowpath

How I dislike the way perf shows the call graph data... Just last week
I was talking to Arnaldo about how to better visualize the cost of
spinlocks, because the normal way "perf" shows costs is so nasty.

What happens is that you see that 36% of CPU time is attributed to
kswapd, and then you can drill down and see where that 36% comes from.
So far so good, and that's what perf does fairly well.

But then when you find the spinlock, you actually want to go the other
way, and instead ask it to show "who were the callers to this routine
and what were the percentages", so that you can then see whether (for
example) it's just that __remove_mapping() use that contends with
itself, or whether it's contending with the page additions or
whatever..

And perf makes that unnecessarily much too hard to see.

So what I'd like to see (and this is where it becomes *so* much more
useful to be able to recreate it myself so that I can play with the
perf data several different ways) is to see what the profile looks
like in that spinlocked region.

Hmm. I guess you could just send me the "perf.data" and "vmlinux"
files, and I can look at it that way. But I'll try to see what happens
on my profile, even if I can't recreate the contention itself, just
trying to see what happens inside of that region.

None of this code is all that new, which is annoying. This must have
gone on forever,

               Linus

[toc] | [prev] | [next] | [standalone]


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

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-08-16 01:50 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6zNL-3Px-3@gated-at.bofh.it>
In reply to#1463272
On Mon, Aug 15, 2016 at 4:20 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> None of this code is all that new, which is annoying. This must have
> gone on forever,

... ooh.

Wait, I take that back.

We actually have some very recent changes that I didn't even think
about that went into this very merge window.

In particular, I wonder if it's all (or at least partly) due to the
new per-node LRU lists.

So in shrink_page_list(), when kswapd is encountering a page that is
under page writeback due to page reclaim, it does:

                        if (current_is_kswapd() &&
                            PageReclaim(page) &&
                            test_bit(PGDAT_WRITEBACK, &pgdat->flags)) {
                                nr_immediate++;
                                goto keep_locked;

which basically ignores that page and puts it back on the LRU list.

But that "is this node under writeback" is new - it now does that per
node, and it *used* to do it per zone (so it _used_ to test "is this
zone under writeback").

All the mapping pages used to be in the same zone, so I think it
effectively single-threaded the kswapd reclaim for one mapping under
reclaim writeback. But in your cases, you have multiple nodes...

Ok, that's a lot of hand-wavy new-age crystal healing thinking.

Really, I haven't looked at it more than "this is one thing that has
changed recently, I wonder if it changes the patterns and could
explain much higher spin_lock contention on the mapping->tree_lock".

I'm adding Mel Gorman and his band of miscreants to the cc, so that
they can tell me that I'm full of shit, and completely missed on what
that zone->node change actually ends up meaning.

Mel? The issue is that Dave Chinner is seeing some nasty spinlock
contention on "mapping->tree_lock":

>   31.18%  [kernel]  [k] __pv_queued_spin_lock_slowpath

and one of the main paths is this:

>    - 30.29% kswapd
>       - 30.23% shrink_node
>          - 30.07% shrink_node_memcg.isra.75
>             - 30.15% shrink_inactive_list
>                - 29.49% shrink_page_list
>                   - 22.79% __remove_mapping
>                      - 22.27% _raw_spin_lock_irqsave
>                           __pv_queued_spin_lock_slowpath

so there's something ridiculously bad going on with a fairly simple benchmark.

Dave's benchmark is literally just a "write a new 48GB file in
single-page chunks on a 4-node machine". Nothing odd - not rewriting
files, not seeking around, no nothing.

You can probably recreate it with a silly

  dd bs=4096 count=$((12*1024*1024)) if=/dev/zero of=bigfile

although Dave actually had something rather fancier, I think.

             Linus

[toc] | [prev] | [next] | [standalone]


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

FromDave Chinner <david@fromorbit.com>
Date2016-08-16 02:50 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6AJP-4pI-3@gated-at.bofh.it>
In reply to#1463282
On Mon, Aug 15, 2016 at 04:48:36PM -0700, Linus Torvalds wrote:
> On Mon, Aug 15, 2016 at 4:20 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> >
> > None of this code is all that new, which is annoying. This must have
> > gone on forever,
> 
> ... ooh.
> 
> Wait, I take that back.
> 
> We actually have some very recent changes that I didn't even think
> about that went into this very merge window.
....
> Mel? The issue is that Dave Chinner is seeing some nasty spinlock
> contention on "mapping->tree_lock":
> 
> >   31.18%  [kernel]  [k] __pv_queued_spin_lock_slowpath
> 
> and one of the main paths is this:
> 
> >    - 30.29% kswapd
> >       - 30.23% shrink_node
> >          - 30.07% shrink_node_memcg.isra.75
> >             - 30.15% shrink_inactive_list
> >                - 29.49% shrink_page_list
> >                   - 22.79% __remove_mapping
> >                      - 22.27% _raw_spin_lock_irqsave
> >                           __pv_queued_spin_lock_slowpath
> 
> so there's something ridiculously bad going on with a fairly simple benchmark.
> 
> Dave's benchmark is literally just a "write a new 48GB file in
> single-page chunks on a 4-node machine". Nothing odd - not rewriting
> files, not seeking around, no nothing.
> 
> You can probably recreate it with a silly
> 
>   dd bs=4096 count=$((12*1024*1024)) if=/dev/zero of=bigfile
> 
> although Dave actually had something rather fancier, I think.

16p, 16GB RAM, fake_numa=4. Overwrite a 47GB file on a 48GB
filesystem:

# mkfs.xfs -f -d size=48g /dev/vdc
# mount /dev/vdc /mnt/scratch
# xfs_io -f -c "pwrite 0 47g" /mnt/scratch/fooey

Wait for memory to fill and reclaim to kick in, then look at the
profile. If you run it a second time, reclaim kicks in straight
away.

It's not the new code in 4.8 - it reproduces on 4.7 just fine, and
probably will reproduce all the way back to when the memcg-aware
writeback code was added....

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

[toc] | [prev] | [next] | [standalone]


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

FromMel Gorman <mgorman@techsingularity.net>
Date2016-08-16 17:10 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6Oa5-4Fc-15@gated-at.bofh.it>
In reply to#1463282
On Mon, Aug 15, 2016 at 04:48:36PM -0700, Linus Torvalds wrote:
> On Mon, Aug 15, 2016 at 4:20 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> >
> > None of this code is all that new, which is annoying. This must have
> > gone on forever,
> 
> ... ooh.
> 
> Wait, I take that back.
> 
> We actually have some very recent changes that I didn't even think
> about that went into this very merge window.
> 
> In particular, I wonder if it's all (or at least partly) due to the
> new per-node LRU lists.
> 
> So in shrink_page_list(), when kswapd is encountering a page that is
> under page writeback due to page reclaim, it does:
> 
>                         if (current_is_kswapd() &&
>                             PageReclaim(page) &&
>                             test_bit(PGDAT_WRITEBACK, &pgdat->flags)) {
>                                 nr_immediate++;
>                                 goto keep_locked;
> 

I have a limited view of the full topic as I've been in meetings all day
and have another 3 hours to go. I'll set time aside tomorrow to look closer
but there is a theory at the end of the mail.

Node-lru does alter what locks are contended and affects the timing of some
issues but this spot feels like a bad fit. That logic controls whether kswapd
will stall due to dirty/writeback pages reaching the tail of the LRU too
quickly. It can affect lru_lock contention that may be worse with node-lru,
particularly on single-node machines but a workload of a streaming writer
is unlikely to hit that unless the underlying storage is extremely slow.

Another alternation of node-lru potentially affects when buffer heads get
stripped but that's also a poor fit.

I'm not willing to rule out node-lru because it may be wishful thinking
but it feels unlikely.

> which basically ignores that page and puts it back on the LRU list.
> 
> But that "is this node under writeback" is new - it now does that per
> node, and it *used* to do it per zone (so it _used_ to test "is this
> zone under writeback").
> 

Superficially, a small high zone would affect the timing of when a zone
got marked congested and triggered a sleep. Sleeping avoids new pages being
allocated/dirties and may reduce contention. However, quick sleeps due to
small zones was offset by the fair zone allocation policy and is still
offset by GFP_WRITE distributing dirty pages on different zones. The
timing of when sleeps occur due to excessive dirty pages at the tail of
the LRU should be roughly similar with either zone-lru or node-lru.

> All the mapping pages used to be in the same zone, so I think it
> effectively single-threaded the kswapd reclaim for one mapping under
> reclaim writeback. But in your cases, you have multiple nodes...
> 
> Ok, that's a lot of hand-wavy new-age crystal healing thinking.
> 
> Really, I haven't looked at it more than "this is one thing that has
> changed recently, I wonder if it changes the patterns and could
> explain much higher spin_lock contention on the mapping->tree_lock".
> 
> I'm adding Mel Gorman and his band of miscreants to the cc, so that
> they can tell me that I'm full of shit, and completely missed on what
> that zone->node change actually ends up meaning.
> 
> Mel? The issue is that Dave Chinner is seeing some nasty spinlock
> contention on "mapping->tree_lock":
> 

Band Of Miscreants may be the new name for the MM track at LSF/MM.  In the
meantime lets try some hand waving;

A single-threaded file write on a 4-node system is going to have 4 kswapd
instances, writeback and potentially the writer itself all reclaiming.
Given the workload, it's likely that almost all pages have the same
mapping. As they are contending on __remove_mapping, the pages must be
clean when the attempt to reclaim was made and buffers stripped.

The throttling mechanisms for kswapd and direct reclaim rely on either
too many pages being isolated (unlikely to fire in this case) or too many
dirty/writeback pages reaching the end of the LRU. There is not a direct
throttling mechanism for excessive lock contention

However, historically there have been multiple indirect throttling mechanism
that were branded as congestion control but basically said "I don't know
what's going on so it's nap time". Many of these have been removed over
time and the last major one was ede37713737 ("mm: throttle on IO only when
there are too many dirty and writeback pages").

Before that commit, a process that entered direct reclaim and failed to make
progress would sleep before retrying. It's possible that sleep was enough
to reduce contention by temporarily stalling the writer and letting reclaim
make progress. After that commit, it may only do a cond_resched() check
and go back to allocating/reclaiming as quickly as possible. This active
writer may be enough to increase contention. If so, it also means it
stops kswapd making forward progress, leading to more direct reclaim and
more contention.

It's not a perfect theory and assumes;

1. The writer is direct reclaiming
2. The writer was previously failing to __remove_mapping
3. The writer calling congestion_wait due to __remove_mapping failing
   was enough to allow kswapd or writeback to make enough progress to
   avoid contention
4. The writer staying awake allocating and dirtying pages is keeping all
   the kswapd instances awake and writeback continually active and
   increasing the contention overall.

If it was possible to trigger this problem in 4.7 then it would also be
worth checking 4.6. If 4.6 is immune, check that before and after commit
ede37713737.

-- 
Mel Gorman
SUSE Labs

[toc] | [prev] | [next] | [standalone]


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

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-08-16 20:00 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s6QOB-686-3@gated-at.bofh.it>
In reply to#1463875
Mel,
 thanks for taking a look. Your theory sounds more complete than mine,
and since Dave is able to see the problem with 4.7, it would be nice
to hear about the 4.6 behavior and commit ede37713737 in particular.

That one seems more likely to affect contention than the zone/node one
I found during the merge window anyway, since it actually removes a
sleep in kswapd during congestion.

I've always preferred to see direct reclaim as the primary model for
reclaim, partly in order to throttle the actual "bad" process, but
also because "kswapd uses lots of CPU time" is such a nasty thing to
even begin guessing about.

So I have to admit to liking that "make kswapd sleep a bit if it's
just looping" logic that got removed in that commit.

And looking at DaveC's numbers, it really feels like it's not even
what we do inside the locked region that is the problem. Sure,
__delete_from_page_cache() (which is most of it) is at 1.86% of CPU
time (when including all the things it calls), but that still isn't
all that much. Especially when compared to just:

   0.78%  [kernel]  [k] _raw_spin_unlock_irqrestore

from his flat profile. That's not some spinning wait, that's just
releasing the lock with a single write (and the popf, but while that's
an expensive instruction, it's just tens of cpu cycles).

So I'm more and more getting the feeling that it's not what we do
inside the lock that is problematic. I started out blaming memcg
accounting or something, but none of the numbers seem to back that up.
So it's primarily really just the fact that kswapd is simply hammering
on that lock way too much.

So yeah, I'm blaming kswapd itself doing something wrong. It's not a
problem in a single-node environment (since there's only one), but
with multiple nodes it clearly just devolves.

Yes, we could try to batch the locking like DaveC already suggested
(ie we could move the locking to the caller, and then make
shrink_page_list() just try to keep the lock held for a few pages if
the mapping doesn't change), and that might result in fewer crazy
cacheline ping-pongs overall. But that feels like exactly the wrong
kind of workaround.

I'd much rather re-instate some "if kswapd is just spinning on CPU
time and not actually improving IO parallelism, kswapd should just get
the hell out" logic.

Adding Michal Hocko to the participant list too, I think he's one of
the gang in this area. Who else should be made aware of this thread?
Minchan? Vladimir?

[ I'm assuming the new people can look up this thread on lkml. Note to
new people: the subject line (and about 75% of the posts) are about an
unrelated AIM7 regression, but there's this sub-thread about nasty
lock contention on mapping->tree_lock within that bigger context ]

              Linus

On Tue, Aug 16, 2016 at 8:05 AM, Mel Gorman <mgorman@techsingularity.net> wrote:
>
> However, historically there have been multiple indirect throttling mechanism
> that were branded as congestion control but basically said "I don't know
> what's going on so it's nap time". Many of these have been removed over
> time and the last major one was ede37713737 ("mm: throttle on IO only when
> there are too many dirty and writeback pages").
>
> Before that commit, a process that entered direct reclaim and failed to make
> progress would sleep before retrying. It's possible that sleep was enough
> to reduce contention by temporarily stalling the writer and letting reclaim
> make progress. After that commit, it may only do a cond_resched() check
> and go back to allocating/reclaiming as quickly as possible. This active
> writer may be enough to increase contention. If so, it also means it
> stops kswapd making forward progress, leading to more direct reclaim and
> more contention.
>
> It's not a perfect theory and assumes;
>
> 1. The writer is direct reclaiming
> 2. The writer was previously failing to __remove_mapping
> 3. The writer calling congestion_wait due to __remove_mapping failing
>    was enough to allow kswapd or writeback to make enough progress to
>    avoid contention
> 4. The writer staying awake allocating and dirtying pages is keeping all
>    the kswapd instances awake and writeback continually active and
>    increasing the contention overall.
>
> If it was possible to trigger this problem in 4.7 then it would also be
> worth checking 4.6. If 4.6 is immune, check that before and after commit
> ede37713737.
>
> --
> Mel Gorman
> SUSE Labs

[toc] | [prev] | [next] | [standalone]


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

FromMichal Hocko <mhocko@kernel.org>
Date2016-08-17 17:50 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s7bgl-2YP-1@gated-at.bofh.it>
In reply to#1463975
On Tue 16-08-16 10:47:36, Linus Torvalds wrote:
> Mel,
>  thanks for taking a look. Your theory sounds more complete than mine,
> and since Dave is able to see the problem with 4.7, it would be nice
> to hear about the 4.6 behavior and commit ede37713737 in particular.
> 
> That one seems more likely to affect contention than the zone/node one
> I found during the merge window anyway, since it actually removes a
> sleep in kswapd during congestion.

Hmm, the patch removes a short sleep from wait_iff_congested for
kworkers but that cannot affect kswapd context. Then it removes
wait_iff_congested from should_reclaim_retry but that is not kswapd path
and the sleep was added in the same merge window so it wasn't in 4.6 so
it shouldn't make any difference as well.

So I am not really sure how it could make any difference.

I will try to catch up with the rest of the email thread but from a
quick glance it just feels like we are doing more more work under the
lock.

-- 
Michal Hocko
SUSE Labs

[toc] | [prev] | [next] | [standalone]


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

FromMichal Hocko <mhocko@kernel.org>
Date2016-08-17 18:50 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s7ccp-3AT-11@gated-at.bofh.it>
In reply to#1464627
On Wed 17-08-16 17:48:25, Michal Hocko wrote:
[...]
> I will try to catch up with the rest of the email thread but from a
> quick glance it just feels like we are doing more more work under the
> lock.

Hmm, so it doesn't seem to be more work in __remove_mapping as pointed
out in http://lkml.kernel.org/r/20160816220250.GI16044@dastard

As Mel already pointed out the LRU will be basically single mapping for
this workload so any subtle change in timing might make a difference.
I was looking through 4.6..4.7 and one thing that has changed is the
inactive vs. active LRU size ratio. See 59dc76b0d4df ("mm: vmscan:
reduce size of inactive file list"). The machine has quite a lot of
memory and so the LRUs will be large as well so I guess this could have
change the timing somehow, but it feels like a wild guess so I would be
careful to blame this commit...
-- 
Michal Hocko
SUSE Labs

[toc] | [prev] | [next] | [standalone]


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

FromMel Gorman <mgorman@techsingularity.net>
Date2016-08-17 17:50 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s7bgl-2YP-13@gated-at.bofh.it>
In reply to#1463975
On Tue, Aug 16, 2016 at 10:47:36AM -0700, Linus Torvalds wrote:
> I've always preferred to see direct reclaim as the primary model for
> reclaim, partly in order to throttle the actual "bad" process, but
> also because "kswapd uses lots of CPU time" is such a nasty thing to
> even begin guessing about.
> 

While I agree that bugs with high CPU usage from kswapd are a pain,
I'm reluctant to move towards direct reclaim being the primary mode. The
stalls can be severe and there is no guarantee that the process punished
is the process responsible. I'm basing this assumption on observations
of severe performance regressions when I accidentally broke kswapd during
the development of node-lru.

> So I have to admit to liking that "make kswapd sleep a bit if it's
> just looping" logic that got removed in that commit.
> 

It's primarily the direct reclaimer that is affected by that patch.

> And looking at DaveC's numbers, it really feels like it's not even
> what we do inside the locked region that is the problem. Sure,
> __delete_from_page_cache() (which is most of it) is at 1.86% of CPU
> time (when including all the things it calls), but that still isn't
> all that much. Especially when compared to just:
> 
>    0.78%  [kernel]  [k] _raw_spin_unlock_irqrestore
> 

The profile is shocking for such a basic workload. I automated what Dave
described with xfs_io except that the file size is 2*RAM. The filesystem
is sized to be roughly the same size as the file to minimise variances
due to block layout. A call-graph profile collected on bare metal UMA with
numa=fake=4 and paravirt spinlocks showed

     1.40%     0.16%  kswapd1          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     1.36%     0.16%  kswapd2          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     1.21%     0.12%  kswapd0          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     1.12%     0.13%  kswapd3          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.81%     0.45%  xfs_io           [kernel.vmlinux]            [k] _raw_spin_lock_irqsave

Those contention figures are not great but they are not terrible either. The
vmstats told me there was no direct reclaim activity so either my theory
is wrong or this machine is not reproducing the same problem Dave is seeing.

I have partial results from a 2-socket and 4-socket machine. 2-socket spends
roughtly 1.8% in _raw_spin_lock_irqsave and 4-socket spends roughtly 3%,
both with no direct reclaim. Clearly the problem gets worse the more NUMA
nodes there are but not to the same extent Dave reports.

I believe potential reasons why I do not see the same problem as Dave are;

1. Different memory sizes changing timing
2. Dave has fast storage and I'm using a spinning disk
3. Lock contention problems are magnified inside KVM

I think 3 is a good possibility if contended locks result in expensive
exiting and reentery of the guest. I have a vague recollection that a
spinning vcpu exits the guest but I did not confirm that. I can setup a
KVM instance and run the tests but it'll take a few hours and possibly
will be pushed out until tomorrow.

> So I'm more and more getting the feeling that it's not what we do
> inside the lock that is problematic. I started out blaming memcg
> accounting or something, but none of the numbers seem to back that up.
> So it's primarily really just the fact that kswapd is simply hammering
> on that lock way too much.
> 

Agreed.

> So yeah, I'm blaming kswapd itself doing something wrong. It's not a
> problem in a single-node environment (since there's only one), but
> with multiple nodes it clearly just devolves.
> 
> Yes, we could try to batch the locking like DaveC already suggested
> (ie we could move the locking to the caller, and then make
> shrink_page_list() just try to keep the lock held for a few pages if
> the mapping doesn't change), and that might result in fewer crazy
> cacheline ping-pongs overall. But that feels like exactly the wrong
> kind of workaround.
> 

Even if such batching was implemented, it would be very specific to the
case of a single large file filling LRUs on multiple nodes.

> I'd much rather re-instate some "if kswapd is just spinning on CPU
> time and not actually improving IO parallelism, kswapd should just get
> the hell out" logic.
> 

I'm having trouble right now thinking of a good way of identifying when
kswapd should give up and force direct reclaim to take a hit.

I'd like to pass something else by the wtf-o-meter. I had a prototype
patch lying around that replaced a congestion_wait if too many LRU pages
were isolated with a waitqueue for an unrelated theoretical problem. It's
the bulk of the patch below but can be trivially extended for the case of
tree_lock contention.

The interesting part is the change to __remove_mapping. It stalls a
reclaimer (direct or kswapd) if the lock is contended for either a
timeout or a local reclaimer finishing some reclaim. This stalls for a
"real" reason instead of blindly calling congestion_wait.  The downside
is that I do see xfs_io briefly enter direct reclaim when kswapd stalled
on contention but the overall impact to completion times was 0.01 seconds
in the UMA with fake NUMA nodes case.

This could be made specific to direct reclaimers but it makes a certain
amount of sense to stall kswapd instances contending with each other.
With the patch applied I see a drop in cycles spent in spin_lock_irqsave

Before
     1.40%     0.16%  kswapd1          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     1.36%     0.16%  kswapd2          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     1.21%     0.12%  kswapd0          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     1.12%     0.13%  kswapd3          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.81%     0.45%  xfs_io           [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.26%     0.23%  kworker/u20:1    [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.25%     0.19%  kworker/3:2      [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.23%     0.19%  rm               [kernel.vmlinux]            [k] _raw_spin_lock_irqsave

After
     0.57%     0.50%  xfs_io           [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.24%     0.20%  rm               [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.24%     0.21%  kthreadd         [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.21%     0.17%  kworker/6:1      [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.12%     0.09%  kworker/2:1      [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.11%     0.10%  kworker/u20:0    [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.10%     0.10%  swapper          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.09%     0.08%  kworker/7:2      [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
....
     0.01%     0.00%  kswapd0          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.01%     0.00%  kswapd1          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.01%     0.00%  kswapd3          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave
     0.01%     0.00%  kswapd2          [kernel.vmlinux]            [k] _raw_spin_lock_irqsave

kswapd time on locking is almost eliminated.

diff --git a/include/linux/mmzone.h b/include/linux/mmzone.h
index d572b78b65e1..72f92f67bd0c 100644
--- a/include/linux/mmzone.h
+++ b/include/linux/mmzone.h
@@ -653,6 +653,7 @@ typedef struct pglist_data {
 	int node_id;
 	wait_queue_head_t kswapd_wait;
 	wait_queue_head_t pfmemalloc_wait;
+	wait_queue_head_t contention_wait;
 	struct task_struct *kswapd;	/* Protected by
 					   mem_hotplug_begin/end() */
 	int kswapd_order;
diff --git a/mm/compaction.c b/mm/compaction.c
index 9affb2908304..57351dddcd9a 100644
--- a/mm/compaction.c
+++ b/mm/compaction.c
@@ -1616,6 +1616,10 @@ static enum compact_result compact_zone(struct zone *zone, struct compact_contro
 			zone->compact_cached_free_pfn = free_pfn;
 	}
 
+	/* Page reclaim could have stalled due to isolated pages */
+	if (waitqueue_active(&zone->zone_pgdat->contention_wait))
+		wake_up(&zone->zone_pgdat->contention_wait);
+
 	trace_mm_compaction_end(start_pfn, cc->migrate_pfn,
 				cc->free_pfn, end_pfn, sync, ret);
 
diff --git a/mm/page_alloc.c b/mm/page_alloc.c
index 3fbe73a6fe4b..5af4eecdb4c9 100644
--- a/mm/page_alloc.c
+++ b/mm/page_alloc.c
@@ -5825,6 +5825,7 @@ static void __paginginit free_area_init_core(struct pglist_data *pgdat)
 #endif
 	init_waitqueue_head(&pgdat->kswapd_wait);
 	init_waitqueue_head(&pgdat->pfmemalloc_wait);
+	init_waitqueue_head(&pgdat->contention_wait);
 #ifdef CONFIG_COMPACTION
 	init_waitqueue_head(&pgdat->kcompactd_wait);
 #endif
diff --git a/mm/vmscan.c b/mm/vmscan.c
index 374d95d04178..42c37bf88cb7 100644
--- a/mm/vmscan.c
+++ b/mm/vmscan.c
@@ -633,7 +633,25 @@ static int __remove_mapping(struct address_space *mapping, struct page *page,
 	BUG_ON(!PageLocked(page));
 	BUG_ON(mapping != page_mapping(page));
 
-	spin_lock_irqsave(&mapping->tree_lock, flags);
+	if (!reclaimed) {
+		spin_lock_irqsave(&mapping->tree_lock, flags);
+	} else {
+		/*
+		 * If a reclaimer encounters a contended tree_lock then briefly
+		 * stall and allow the parallel reclaim to make progress. The
+		 * full HZ/10 penalty is incurred if the lock holder is
+		 * reclaiming on a remote node.
+		 */
+		if (!spin_trylock_irqsave(&mapping->tree_lock, flags)) {
+			pg_data_t *pgdat = page_pgdat(page);
+
+			try_to_unmap_flush();
+			wait_event_interruptible_timeout(pgdat->contention_wait,
+				spin_is_locked(&mapping->tree_lock), HZ/10);
+			spin_lock_irqsave(&mapping->tree_lock, flags);
+		}
+	}
+
 	/*
 	 * The non racy check for a busy page.
 	 *
@@ -1554,16 +1572,16 @@ int isolate_lru_page(struct page *page)
  * the LRU list will go small and be scanned faster than necessary, leading to
  * unnecessary swapping, thrashing and OOM.
  */
-static int too_many_isolated(struct pglist_data *pgdat, int file,
+static bool safe_to_isolate(struct pglist_data *pgdat, int file,
 		struct scan_control *sc)
 {
 	unsigned long inactive, isolated;
 
 	if (current_is_kswapd())
-		return 0;
+		return true;
 
-	if (!sane_reclaim(sc))
-		return 0;
+	if (sane_reclaim(sc))
+		return true;
 
 	if (file) {
 		inactive = node_page_state(pgdat, NR_INACTIVE_FILE);
@@ -1581,7 +1599,7 @@ static int too_many_isolated(struct pglist_data *pgdat, int file,
 	if ((sc->gfp_mask & (__GFP_IO | __GFP_FS)) == (__GFP_IO | __GFP_FS))
 		inactive >>= 3;
 
-	return isolated > inactive;
+	return isolated < inactive;
 }
 
 static noinline_for_stack void
@@ -1701,12 +1719,15 @@ shrink_inactive_list(unsigned long nr_to_scan, struct lruvec *lruvec,
 	if (!inactive_reclaimable_pages(lruvec, sc, lru))
 		return 0;
 
-	while (unlikely(too_many_isolated(pgdat, file, sc))) {
-		congestion_wait(BLK_RW_ASYNC, HZ/10);
+	while (!safe_to_isolate(pgdat, file, sc)) {
+		wait_event_interruptible_timeout(pgdat->contention_wait,
+			safe_to_isolate(pgdat, file, sc), HZ/10);
 
 		/* We are about to die and free our memory. Return now. */
-		if (fatal_signal_pending(current))
-			return SWAP_CLUSTER_MAX;
+		if (fatal_signal_pending(current)) {
+			nr_reclaimed = SWAP_CLUSTER_MAX;
+			goto out;
+		}
 	}
 
 	lru_add_drain();
@@ -1819,6 +1840,10 @@ shrink_inactive_list(unsigned long nr_to_scan, struct lruvec *lruvec,
 	trace_mm_vmscan_lru_shrink_inactive(pgdat->node_id,
 			nr_scanned, nr_reclaimed,
 			sc->priority, file);
+
+out:
+	if (waitqueue_active(&pgdat->contention_wait))
+		wake_up(&pgdat->contention_wait);
 	return nr_reclaimed;
 }
 

[toc] | [prev] | [next] | [standalone]


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

FromMel Gorman <mgorman@techsingularity.net>
Date2016-08-18 02:50 +0200
SubjectRe: [LKP] [lkp] [xfs] 68a9f5e700: aim7.jobs-per-min -13.6% regression
Message-ID<s7jGV-t1-7@gated-at.bofh.it>
In reply to#1464631
On Wed, Aug 17, 2016 at 04:49:07PM +0100, Mel Gorman wrote:
> > Yes, we could try to batch the locking like DaveC already suggested
> > (ie we could move the locking to the caller, and then make
> > shrink_page_list() just try to keep the lock held for a few pages if
> > the mapping doesn't change), and that might result in fewer crazy
> > cacheline ping-pongs overall. But that feels like exactly the wrong
> > kind of workaround.
> > 
> 
> Even if such batching was implemented, it would be very specific to the
> case of a single large file filling LRUs on multiple nodes.
> 

The latest Jason Bourne movie was sufficiently bad that I spent time
thinking how the tree_lock could be batched during reclaim. It's not
straight-forward but this prototype did not blow up on UMA and may be
worth considering if Dave can test either approach has a positive impact.

diff --git a/mm/vmscan.c b/mm/vmscan.c
index 374d95d04178..926110219cd9 100644
--- a/mm/vmscan.c
+++ b/mm/vmscan.c
@@ -621,19 +621,39 @@ static pageout_t pageout(struct page *page, struct address_space *mapping,
 	return PAGE_CLEAN;
 }
 
+static void finalise_remove_mapping(struct list_head *swapcache,
+				    struct list_head *filecache,
+				    void (*freepage)(struct page *))
+{
+	struct page *page;
+
+	while (!list_empty(swapcache)) {
+		swp_entry_t swap = { .val = page_private(page) };
+		page = lru_to_page(swapcache);
+		list_del(&page->lru);
+		swapcache_free(swap);
+		set_page_private(page, 0);
+	}
+
+	while (!list_empty(filecache)) {
+		page = lru_to_page(swapcache);
+		list_del(&page->lru);
+		freepage(page);
+	}
+}
+
 /*
  * Same as remove_mapping, but if the page is removed from the mapping, it
  * gets returned with a refcount of 0.
  */
-static int __remove_mapping(struct address_space *mapping, struct page *page,
-			    bool reclaimed)
+static int __remove_mapping_page(struct address_space *mapping,
+				 struct page *page, bool reclaimed,
+				 struct list_head *swapcache,
+				 struct list_head *filecache)
 {
-	unsigned long flags;
-
 	BUG_ON(!PageLocked(page));
 	BUG_ON(mapping != page_mapping(page));
 
-	spin_lock_irqsave(&mapping->tree_lock, flags);
 	/*
 	 * The non racy check for a busy page.
 	 *
@@ -668,16 +688,18 @@ static int __remove_mapping(struct address_space *mapping, struct page *page,
 	}
 
 	if (PageSwapCache(page)) {
-		swp_entry_t swap = { .val = page_private(page) };
+		unsigned long swapval = page_private(page);
+		swp_entry_t swap = { .val = swapval };
 		mem_cgroup_swapout(page, swap);
 		__delete_from_swap_cache(page);
-		spin_unlock_irqrestore(&mapping->tree_lock, flags);
-		swapcache_free(swap);
+		set_page_private(page, swapval);
+		list_add(&page->lru, swapcache);
 	} else {
-		void (*freepage)(struct page *);
 		void *shadow = NULL;
+		void (*freepage)(struct page *);
 
 		freepage = mapping->a_ops->freepage;
+
 		/*
 		 * Remember a shadow entry for reclaimed file cache in
 		 * order to detect refaults, thus thrashing, later on.
@@ -698,16 +720,13 @@ static int __remove_mapping(struct address_space *mapping, struct page *page,
 		    !mapping_exiting(mapping) && !dax_mapping(mapping))
 			shadow = workingset_eviction(mapping, page);
 		__delete_from_page_cache(page, shadow);
-		spin_unlock_irqrestore(&mapping->tree_lock, flags);
-
-		if (freepage != NULL)
-			freepage(page);
+		if (freepage)
+			list_add(&page->lru, filecache);
 	}
 
 	return 1;
 
 cannot_free:
-	spin_unlock_irqrestore(&mapping->tree_lock, flags);
 	return 0;
 }
 
@@ -719,16 +738,68 @@ static int __remove_mapping(struct address_space *mapping, struct page *page,
  */
 int remove_mapping(struct address_space *mapping, struct page *page)
 {
-	if (__remove_mapping(mapping, page, false)) {
+	unsigned long flags;
+	LIST_HEAD(swapcache);
+	LIST_HEAD(filecache);
+	void (*freepage)(struct page *);
+	int ret = 0;
+
+	spin_lock_irqsave(&mapping->tree_lock, flags);
+	freepage = mapping->a_ops->freepage;
+
+	if (__remove_mapping_page(mapping, page, false, &swapcache, &filecache)) {
 		/*
 		 * Unfreezing the refcount with 1 rather than 2 effectively
 		 * drops the pagecache ref for us without requiring another
 		 * atomic operation.
 		 */
 		page_ref_unfreeze(page, 1);
-		return 1;
+		ret = 1;
+	}
+	spin_unlock_irqrestore(&mapping->tree_lock, flags);
+	finalise_remove_mapping(&swapcache, &filecache, freepage);
+	return ret;
+}
+
+static void remove_mapping_list(struct list_head *mapping_list,
+				struct list_head *free_pages,
+				struct list_head *ret_pages)
+{
+	unsigned long flags;
+	struct address_space *mapping = NULL;
+	void (*freepage)(struct page *);
+	LIST_HEAD(swapcache);
+	LIST_HEAD(filecache);
+	struct page *page;
+
+	while (!list_empty(mapping_list)) {
+		page = lru_to_page(mapping_list);
+		list_del(&page->lru);
+
+		if (!mapping || page->mapping != mapping) {
+			if (mapping) {
+				spin_unlock_irqrestore(&mapping->tree_lock, flags);
+				finalise_remove_mapping(&swapcache, &filecache, freepage);
+			}
+
+			mapping = page->mapping;
+			spin_lock_irqsave(&mapping->tree_lock, flags);
+			freepage = mapping->a_ops->freepage;
+		}
+
+		if (!__remove_mapping_page(mapping, page, true, &swapcache, &filecache)) {
+			unlock_page(page);
+			list_add(&page->lru, ret_pages);
+		} else {
+			__ClearPageLocked(page);
+			list_add(&page->lru, free_pages);
+		}
+	}
+
+	if (mapping) {
+		spin_unlock_irqrestore(&mapping->tree_lock, flags);
+		finalise_remove_mapping(&swapcache, &filecache, freepage);
 	}
-	return 0;
 }
 
 /**
@@ -910,6 +981,7 @@ static unsigned long shrink_page_list(struct list_head *page_list,
 {
 	LIST_HEAD(ret_pages);
 	LIST_HEAD(free_pages);
+	LIST_HEAD(mapping_pages);
 	int pgactivate = 0;
 	unsigned long nr_unqueued_dirty = 0;
 	unsigned long nr_dirty = 0;
@@ -1206,17 +1278,14 @@ static unsigned long shrink_page_list(struct list_head *page_list,
 		}
 
 lazyfree:
-		if (!mapping || !__remove_mapping(mapping, page, true))
+		if (!mapping)
 			goto keep_locked;
 
-		/*
-		 * At this point, we have no other references and there is
-		 * no way to pick any more up (removed from LRU, removed
-		 * from pagecache). Can use non-atomic bitops now (and
-		 * we obviously don't have to worry about waking up a process
-		 * waiting on the page lock, because there are no references.
-		 */
-		__ClearPageLocked(page);
+		list_add(&page->lru, &mapping_pages);
+		if (ret == SWAP_LZFREE)
+			count_vm_event(PGLAZYFREED);
+		continue;
+
 free_it:
 		if (ret == SWAP_LZFREE)
 			count_vm_event(PGLAZYFREED);
@@ -1251,6 +1320,7 @@ static unsigned long shrink_page_list(struct list_head *page_list,
 		VM_BUG_ON_PAGE(PageLRU(page) || PageUnevictable(page), page);
 	}
 
+	remove_mapping_list(&mapping_pages, &free_pages, &ret_pages);
 	mem_cgroup_uncharge_list(&free_pages);
 	try_to_unmap_flush();
 	free_hot_cold_page_list(&free_pages, true);

[toc] | [prev] | [next] | [standalone]


Page 2 of 5 — ← Prev page 1 [2] 3 4 5  Next page →

Back to top | Article view | linux.kernel


csiph-web