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

Groups > linux.kernel > #1530846 > unrolled thread

Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and `mem_cgroup_shrink_node`

Started byDonald Buczek <buczek@molgen.mpg.de>
First post2016-11-27 10:20 +0100
Last post2016-11-30 18:10 +0100
Articles 20 on this page of 28 — 5 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: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Donald Buczek <buczek@molgen.mpg.de> - 2016-11-27 10:20 +0100
    Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Michal Hocko <mhocko@kernel.org> - 2016-11-28 12:10 +0100
      Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Paul Menzel <pmenzel@molgen.mpg.de> - 2016-11-28 13:30 +0100
        Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Donald Buczek <buczek@molgen.mpg.de> - 2016-11-30 11:30 +0100
          Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Michal Hocko <mhocko@kernel.org> - 2016-11-30 12:20 +0100
            Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Donald Buczek <buczek@molgen.mpg.de> - 2016-11-30 12:50 +0100
              Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Donald Buczek <buczek@molgen.mpg.de> - 2016-12-02 10:20 +0100
                Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Donald Buczek <buczek@molgen.mpg.de> - 2016-12-06 09:40 +0100
            Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-11-30 13:00 +0100
              Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Paul Menzel <pmenzel@molgen.mpg.de> - 2016-11-30 13:40 +0100
                Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-11-30 15:40 +0100
            Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-11-30 13:00 +0100
              Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Michal Hocko <mhocko@kernel.org> - 2016-11-30 14:20 +0100
                Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-11-30 15:40 +0100
                  Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Peter Zijlstra <peterz@infradead.org> - 2016-11-30 17:40 +0100
                    Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Michal Hocko <mhocko@kernel.org> - 2016-11-30 18:10 +0100
                      Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-11-30 18:30 +0100
                        Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Michal Hocko <mhocko@kernel.org> - 2016-11-30 18:40 +0100
                      Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Peter Zijlstra <peterz@infradead.org> - 2016-11-30 19:00 +0100
                        Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-11-30 22:40 +0100
                          Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Peter Zijlstra <peterz@infradead.org> - 2016-12-01 06:40 +0100
                            Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-12-01 13:50 +0100
                              Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Peter Zijlstra <peterz@infradead.org> - 2016-12-01 17:40 +0100
                                Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-12-01 18:00 +0100
                                  Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Peter Zijlstra <peterz@infradead.org> - 2016-12-01 19:20 +0100
                                    Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-12-01 19:50 +0100
                                      Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` Peter Zijlstra <peterz@infradead.org> - 2016-12-01 20:00 +0100
                    Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and  `mem_cgroup_shrink_node` "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-11-30 18:10 +0100

Page 1 of 2  [1] 2  Next page →

#1530846 — Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and `mem_cgroup_shrink_node`

FromDonald Buczek <buczek@molgen.mpg.de>
Date2016-11-27 10:20 +0100
SubjectRe: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and `mem_cgroup_shrink_node`
Message-ID<sI3MR-2o2-3@gated-at.bofh.it>
On 24.11.2016 11:15, Michal Hocko wrote:
> On Mon 21-11-16 16:35:53, Donald Buczek wrote:
> [...]
>> Hello,
>>
>> thanks a lot for looking into this!
>>
>> Let me add some information from the reporting site:
>>
>> * We've tried the patch from Paul E. McKenney (the one posted Wed, 16 Nov
>> 2016)  and it doesn't shut up the rcu stall warnings.
>>
>> * Log file from a boot with the patch applied ( grep kernel
>> /var/log/messages ) is here :
>> http://owww.molgen.mpg.de/~buczek/321322/2016-11-21_syslog.txt
>>
>> * This system is a backup server and walks over thousands of files sometimes
>> with multiple parallel rsync processes.
>>
>> * No rcu_* warnings on that machine with 4.7.2, but with 4.8.4 , 4.8.6 ,
>> 4.8.8 and now 4.9.0-rc5+Pauls patch
> I assume you haven't tried the Linus 4.8 kernel without any further
> stable patches? Just to be sure we are not talking about some later
> regression which found its way to the stable tree.

We've tried v4.8 and got the first rcu stall warnings with this, too. 
First one after about 20 hours uptime.


>> * When the backups are actually happening there might be relevant memory
>> pressure from inode cache and the rsync processes. We saw the oom-killer
>> kick in on another machine with same hardware and similar (a bit higher)
>> workload. This other machine also shows a lot of rcu stall warnings since
>> 4.8.4.
>>
>> * We see "rcu_sched detected stalls" also on some other machines since we
>> switched to 4.8 but not as frequently as on the two backup servers. Usually
>> there's "shrink_node" and "kswapd" on the top of the stack. Often
>> "xfs_reclaim_inodes" variants on top of that.
> I would be interested to see some reclaim tracepoints enabled. Could you
> try that out? At least mm_shrink_slab_{start,end} and
> mm_vmscan_lru_shrink_inactive. This should tell us more about how the
> reclaim behaved.

http://owww.molgen.mpg.de/~buczek/321322/2016-11-26.dmesg.txt  (80K)
http://owww.molgen.mpg.de/~buczek/321322/2016-11-26.trace.txt (50M)

Traces wrapped, but the last event is covered. all vmscan events were 
enabled


-- 
Donald Buczek
buczek@molgen.mpg.de
Tel: +49 30 8413 1433

[toc] | [next] | [standalone]

#1531212

FromMichal Hocko <mhocko@kernel.org>
Date2016-11-28 12:10 +0100
Message-ID<sIrYT-1kN-65@gated-at.bofh.it>
In reply to#1530846
On Sun 27-11-16 10:19:06, Donald Buczek wrote:
> On 24.11.2016 11:15, Michal Hocko wrote:
> > On Mon 21-11-16 16:35:53, Donald Buczek wrote:
> > [...]
> > > Hello,
> > > 
> > > thanks a lot for looking into this!
> > > 
> > > Let me add some information from the reporting site:
> > > 
> > > * We've tried the patch from Paul E. McKenney (the one posted Wed, 16 Nov
> > > 2016)  and it doesn't shut up the rcu stall warnings.
> > > 
> > > * Log file from a boot with the patch applied ( grep kernel
> > > /var/log/messages ) is here :
> > > http://owww.molgen.mpg.de/~buczek/321322/2016-11-21_syslog.txt
> > > 
> > > * This system is a backup server and walks over thousands of files sometimes
> > > with multiple parallel rsync processes.
> > > 
> > > * No rcu_* warnings on that machine with 4.7.2, but with 4.8.4 , 4.8.6 ,
> > > 4.8.8 and now 4.9.0-rc5+Pauls patch
> > I assume you haven't tried the Linus 4.8 kernel without any further
> > stable patches? Just to be sure we are not talking about some later
> > regression which found its way to the stable tree.
> 
> We've tried v4.8 and got the first rcu stall warnings with this, too. First
> one after about 20 hours uptime.
> 
> 
> > > * When the backups are actually happening there might be relevant memory
> > > pressure from inode cache and the rsync processes. We saw the oom-killer
> > > kick in on another machine with same hardware and similar (a bit higher)
> > > workload. This other machine also shows a lot of rcu stall warnings since
> > > 4.8.4.
> > > 
> > > * We see "rcu_sched detected stalls" also on some other machines since we
> > > switched to 4.8 but not as frequently as on the two backup servers. Usually
> > > there's "shrink_node" and "kswapd" on the top of the stack. Often
> > > "xfs_reclaim_inodes" variants on top of that.
> > I would be interested to see some reclaim tracepoints enabled. Could you
> > try that out? At least mm_shrink_slab_{start,end} and
> > mm_vmscan_lru_shrink_inactive. This should tell us more about how the
> > reclaim behaved.
> 
> http://owww.molgen.mpg.de/~buczek/321322/2016-11-26.dmesg.txt  (80K)
> http://owww.molgen.mpg.de/~buczek/321322/2016-11-26.trace.txt (50M)
> 
> Traces wrapped, but the last event is covered. all vmscan events were
> enabled

OK, so one of the stall is reported at
[118077.988410] INFO: rcu_sched detected stalls on CPUs/tasks:
[118077.988416] 	1-...: (181 ticks this GP) idle=6d5/140000000000000/0 softirq=46417663/46417663 fqs=10691 
[118077.988417] 	(detected by 4, t=60002 jiffies, g=11845915, c=11845914, q=46475)
[118077.988421] Task dump for CPU 1:
[118077.988421] kswapd1         R  running task        0    86      2 0x00000008
[118077.988424]  ffff88080ad87c58 ffff88080ad87c58 ffff88080ad87cf8 ffff88100c1e5200
[118077.988426]  0000000000000003 0000000000000000 ffff88080ad87e60 ffff88080ad87d90
[118077.988428]  ffffffff811345f5 ffff88080ad87da0 ffff88100c1e5200 ffff88080ad87dd0
[118077.988430] Call Trace:
[118077.988436]  [<ffffffff811345f5>] ? shrink_node_memcg+0x605/0x870
[118077.988438]  [<ffffffff8113491f>] ? shrink_node+0xbf/0x1c0
[118077.988440]  [<ffffffff81135642>] ? kswapd+0x342/0x6b0

the interesting part of the traces would be around the same time:
        clusterd-989   [009] .... 118023.654491: mm_vmscan_direct_reclaim_end: nr_reclaimed=193
         kswapd1-86    [001] dN.. 118023.987475: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239830 nr_taken=0 file=1
         kswapd1-86    [001] dN.. 118024.320968: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239844 nr_taken=0 file=1
         kswapd1-86    [001] dN.. 118024.654375: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239858 nr_taken=0 file=1
         kswapd1-86    [001] dN.. 118024.987036: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239872 nr_taken=0 file=1
         kswapd1-86    [001] dN.. 118025.319651: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239886 nr_taken=0 file=1
         kswapd1-86    [001] dN.. 118025.652248: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239900 nr_taken=0 file=1
         kswapd1-86    [001] dN.. 118025.984870: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239914 nr_taken=0 file=1
[...]
         kswapd1-86    [001] dN.. 118084.274403: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4241133 nr_taken=0 file=1

Note the Need resched flag. The IRQ off part is expected because we are
holding the LRU lock which is IRQ safe. That is not a problem because
the lock is only held for SWAP_CLUSTER_MAX pages at maximum. It is also
interesing to see that we have scanned only 1303 pages during that 1
minute. That would be dead slow. None of them were good enough for the
reclaim but that doesn't sound like a problem. The trace simply suggests
that the reclaim was preempted by something else. Otherwise I cannot
imagine such a slow scanning.

Is it possible that something else is hogging the CPU and the RCU just
happens to blame kswapd which is running in the standard user process
context?

-- 
Michal Hocko
SUSE Labs

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

#1531266

FromPaul Menzel <pmenzel@molgen.mpg.de>
Date2016-11-28 13:30 +0100
Message-ID<sIteh-22H-15@gated-at.bofh.it>
In reply to#1531212
+linux-mm@kvack.org
-linux-xfs@vger.kernel.org

Dear Michal,


Thank you for your reply, and for looking at the log files.

On 11/28/16 12:04, Michal Hocko wrote:
> On Sun 27-11-16 10:19:06, Donald Buczek wrote:
>> On 24.11.2016 11:15, Michal Hocko wrote:
>>> On Mon 21-11-16 16:35:53, Donald Buczek wrote:
>>> [...]
>>>> Hello,
>>>>
>>>> thanks a lot for looking into this!
>>>>
>>>> Let me add some information from the reporting site:
>>>>
>>>> * We've tried the patch from Paul E. McKenney (the one posted Wed, 16 Nov
>>>> 2016)  and it doesn't shut up the rcu stall warnings.
>>>>
>>>> * Log file from a boot with the patch applied ( grep kernel
>>>> /var/log/messages ) is here :
>>>> http://owww.molgen.mpg.de/~buczek/321322/2016-11-21_syslog.txt
>>>>
>>>> * This system is a backup server and walks over thousands of files sometimes
>>>> with multiple parallel rsync processes.
>>>>
>>>> * No rcu_* warnings on that machine with 4.7.2, but with 4.8.4 , 4.8.6 ,
>>>> 4.8.8 and now 4.9.0-rc5+Pauls patch
>>> I assume you haven't tried the Linus 4.8 kernel without any further
>>> stable patches? Just to be sure we are not talking about some later
>>> regression which found its way to the stable tree.
>>
>> We've tried v4.8 and got the first rcu stall warnings with this, too. First
>> one after about 20 hours uptime.
>>
>>
>>>> * When the backups are actually happening there might be relevant memory
>>>> pressure from inode cache and the rsync processes. We saw the oom-killer
>>>> kick in on another machine with same hardware and similar (a bit higher)
>>>> workload. This other machine also shows a lot of rcu stall warnings since
>>>> 4.8.4.
>>>>
>>>> * We see "rcu_sched detected stalls" also on some other machines since we
>>>> switched to 4.8 but not as frequently as on the two backup servers. Usually
>>>> there's "shrink_node" and "kswapd" on the top of the stack. Often
>>>> "xfs_reclaim_inodes" variants on top of that.
>>> I would be interested to see some reclaim tracepoints enabled. Could you
>>> try that out? At least mm_shrink_slab_{start,end} and
>>> mm_vmscan_lru_shrink_inactive. This should tell us more about how the
>>> reclaim behaved.
>>
>> http://owww.molgen.mpg.de/~buczek/321322/2016-11-26.dmesg.txt  (80K)
>> http://owww.molgen.mpg.de/~buczek/321322/2016-11-26.trace.txt (50M)
>>
>> Traces wrapped, but the last event is covered. all vmscan events were
>> enabled
>
> OK, so one of the stall is reported at
> [118077.988410] INFO: rcu_sched detected stalls on CPUs/tasks:
> [118077.988416] 	1-...: (181 ticks this GP) idle=6d5/140000000000000/0 softirq=46417663/46417663 fqs=10691
> [118077.988417] 	(detected by 4, t=60002 jiffies, g=11845915, c=11845914, q=46475)
> [118077.988421] Task dump for CPU 1:
> [118077.988421] kswapd1         R  running task        0    86      2 0x00000008
> [118077.988424]  ffff88080ad87c58 ffff88080ad87c58 ffff88080ad87cf8 ffff88100c1e5200
> [118077.988426]  0000000000000003 0000000000000000 ffff88080ad87e60 ffff88080ad87d90
> [118077.988428]  ffffffff811345f5 ffff88080ad87da0 ffff88100c1e5200 ffff88080ad87dd0
> [118077.988430] Call Trace:
> [118077.988436]  [<ffffffff811345f5>] ? shrink_node_memcg+0x605/0x870
> [118077.988438]  [<ffffffff8113491f>] ? shrink_node+0xbf/0x1c0
> [118077.988440]  [<ffffffff81135642>] ? kswapd+0x342/0x6b0
>
> the interesting part of the traces would be around the same time:
>         clusterd-989   [009] .... 118023.654491: mm_vmscan_direct_reclaim_end: nr_reclaimed=193
>          kswapd1-86    [001] dN.. 118023.987475: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239830 nr_taken=0 file=1
>          kswapd1-86    [001] dN.. 118024.320968: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239844 nr_taken=0 file=1
>          kswapd1-86    [001] dN.. 118024.654375: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239858 nr_taken=0 file=1
>          kswapd1-86    [001] dN.. 118024.987036: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239872 nr_taken=0 file=1
>          kswapd1-86    [001] dN.. 118025.319651: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239886 nr_taken=0 file=1
>          kswapd1-86    [001] dN.. 118025.652248: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239900 nr_taken=0 file=1
>          kswapd1-86    [001] dN.. 118025.984870: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4239914 nr_taken=0 file=1
> [...]
>          kswapd1-86    [001] dN.. 118084.274403: mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 nr_requested=32 nr_scanned=4241133 nr_taken=0 file=1
>
> Note the Need resched flag. The IRQ off part is expected because we are
> holding the LRU lock which is IRQ safe. That is not a problem because
> the lock is only held for SWAP_CLUSTER_MAX pages at maximum. It is also
> interesing to see that we have scanned only 1303 pages during that 1
> minute. That would be dead slow. None of them were good enough for the
> reclaim but that doesn't sound like a problem. The trace simply suggests
> that the reclaim was preempted by something else. Otherwise I cannot
> imagine such a slow scanning.
>
> Is it possible that something else is hogging the CPU and the RCU just
> happens to blame kswapd which is running in the standard user process
> context?

 From looking at the monitoring graphs, there was always enough CPU 
resources available. The machine has 12x E5-2630 @ 2.30GHz. So that 
shouldn’t have been a problem.


Kind regards,

Paul Menzel

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

#1533196

FromDonald Buczek <buczek@molgen.mpg.de>
Date2016-11-30 11:30 +0100
Message-ID<sJajf-4SL-21@gated-at.bofh.it>
In reply to#1531266
On 11/28/16 13:26, Paul Menzel wrote:
> [...]
>
> On 11/28/16 12:04, Michal Hocko wrote:
>> [...]
>>
>> OK, so one of the stall is reported at
>> [118077.988410] INFO: rcu_sched detected stalls on CPUs/tasks:
>> [118077.988416]     1-...: (181 ticks this GP) 
>> idle=6d5/140000000000000/0 softirq=46417663/46417663 fqs=10691
>> [118077.988417]     (detected by 4, t=60002 jiffies, g=11845915, 
>> c=11845914, q=46475)
>> [118077.988421] Task dump for CPU 1:
>> [118077.988421] kswapd1         R  running task        0 86      2 
>> 0x00000008
>> [118077.988424]  ffff88080ad87c58 ffff88080ad87c58 ffff88080ad87cf8 
>> ffff88100c1e5200
>> [118077.988426]  0000000000000003 0000000000000000 ffff88080ad87e60 
>> ffff88080ad87d90
>> [118077.988428]  ffffffff811345f5 ffff88080ad87da0 ffff88100c1e5200 
>> ffff88080ad87dd0
>> [118077.988430] Call Trace:
>> [118077.988436]  [<ffffffff811345f5>] ? shrink_node_memcg+0x605/0x870
>> [118077.988438]  [<ffffffff8113491f>] ? shrink_node+0xbf/0x1c0
>> [118077.988440]  [<ffffffff81135642>] ? kswapd+0x342/0x6b0
>>
>> the interesting part of the traces would be around the same time:
>>         clusterd-989   [009] .... 118023.654491: 
>> mm_vmscan_direct_reclaim_end: nr_reclaimed=193
>>          kswapd1-86    [001] dN.. 118023.987475: 
>> mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 
>> nr_requested=32 nr_scanned=4239830 nr_taken=0 file=1
>>          kswapd1-86    [001] dN.. 118024.320968: 
>> mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 
>> nr_requested=32 nr_scanned=4239844 nr_taken=0 file=1
>>          kswapd1-86    [001] dN.. 118024.654375: 
>> mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 
>> nr_requested=32 nr_scanned=4239858 nr_taken=0 file=1
>>          kswapd1-86    [001] dN.. 118024.987036: 
>> mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 
>> nr_requested=32 nr_scanned=4239872 nr_taken=0 file=1
>>          kswapd1-86    [001] dN.. 118025.319651: 
>> mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 
>> nr_requested=32 nr_scanned=4239886 nr_taken=0 file=1
>>          kswapd1-86    [001] dN.. 118025.652248: 
>> mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 
>> nr_requested=32 nr_scanned=4239900 nr_taken=0 file=1
>>          kswapd1-86    [001] dN.. 118025.984870: 
>> mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 
>> nr_requested=32 nr_scanned=4239914 nr_taken=0 file=1
>> [...]
>>          kswapd1-86    [001] dN.. 118084.274403: 
>> mm_vmscan_lru_isolate: isolate_mode=0 classzone=0 order=0 
>> nr_requested=32 nr_scanned=4241133 nr_taken=0 file=1
>>
>> Note the Need resched flag. The IRQ off part is expected because we are
>> holding the LRU lock which is IRQ safe.

Hmmm. With the lock held, preemption is disabled. If we are in that 
state for some time, I'd expect need_resched just because of time 
quantum. But... :

The call stack always has

 > [<ffffffff811345f5>] ? shrink_node_memcg+0x605/0x870

which translates to

 > (gdb) list *0xffffffff811345f5
 > 0xffffffff811345f5 is in shrink_node_memcg (mm/vmscan.c:2065).
 > 2060    static unsigned long shrink_list(enum lru_list lru, unsigned 
long nr_to_scan,
 > 2061                     struct lruvec *lruvec, struct scan_control *sc)
 > 2062    {
 > 2063        if (is_active_lru(lru)) {
 > 2064            if (inactive_list_is_low(lruvec, is_file_lru(lru), sc))
 > 2065                shrink_active_list(nr_to_scan, lruvec, sc, lru);
 > 2066            return 0;
 > 2067        }
 > 2068
 > 2069        return shrink_inactive_list(nr_to_scan, lruvec, sc, lru);

So we are in shrink_active_list. I made a small change without keeping 
the old vmlinux and the addresses are off by 16 bytes, but it can be 
verified exactly on another machine:

 > buczek@void:/scratch/local/linux-4.8.10-121.x86_64/source$ grep 
shrink_node_memcg /var/log/messages
 > [...]
 > void kernel: [508779.136016]  [<ffffffff8114833a>] ? 
shrink_node_memcg+0x60a/0x870
 > (gdb) disas 0xffffffff8114833a
 > [...]
 >   0xffffffff81148330 <+1536>:    mov    %r10,0x38(%rsp)
 >   0xffffffff81148335 <+1541>:    callq 0xffffffff81147a00 
<shrink_active_list>
 >   0xffffffff8114833a <+1546>:    mov    0x38(%rsp),%r10
 >   0xffffffff8114833f <+1551>:    jmpq 0xffffffff81147f80 
<shrink_node_memcg+592>
 >   0xffffffff81148344 <+1556>:    mov    %r13,0x78(%r12)


shrink_active_list gets and releases the spinlock and calls 
cond_resched(). This should give other tasks a chance to run. Just as an 
experiment, I'm trying

--- a/mm/vmscan.c
+++ b/mm/vmscan.c
@@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long 
nr_to_scan,
         spin_unlock_irq(&pgdat->lru_lock);

         while (!list_empty(&l_hold)) {
-               cond_resched();
+               cond_resched_rcu_qs();
                 page = lru_to_page(&l_hold);
                 list_del(&page->lru);

and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see. 
Is preemption disabled for another reason?

Regards
   Donald

>> That is not a problem because
>> the lock is only held for SWAP_CLUSTER_MAX pages at maximum. It is also
>> interesing to see that we have scanned only 1303 pages during that 1
>> minute. That would be dead slow. None of them were good enough for the
>> reclaim but that doesn't sound like a problem. The trace simply suggests
>> that the reclaim was preempted by something else. Otherwise I cannot
>> imagine such a slow scanning.
>>
>> Is it possible that something else is hogging the CPU and the RCU just
>> happens to blame kswapd which is running in the standard user process
>> context?
>
> From looking at the monitoring graphs, there was always enough CPU 
> resources available. The machine has 12x E5-2630 @ 2.30GHz. So that 
> shouldn’t have been a problem.
>
>
> Kind regards,
>
> Paul Menzel


-- 
Donald Buczek
buczek@molgen.mpg.de
Tel: +49 30 8413 1433

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

#1533230

FromMichal Hocko <mhocko@kernel.org>
Date2016-11-30 12:20 +0100
Message-ID<sJb5D-5oB-7@gated-at.bofh.it>
In reply to#1533196
[CCing Paul]

On Wed 30-11-16 11:28:34, Donald Buczek wrote:
[...]
> shrink_active_list gets and releases the spinlock and calls cond_resched().
> This should give other tasks a chance to run. Just as an experiment, I'm
> trying
> 
> --- a/mm/vmscan.c
> +++ b/mm/vmscan.c
> @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
> nr_to_scan,
>         spin_unlock_irq(&pgdat->lru_lock);
> 
>         while (!list_empty(&l_hold)) {
> -               cond_resched();
> +               cond_resched_rcu_qs();
>                 page = lru_to_page(&l_hold);
>                 list_del(&page->lru);
> 
> and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.

This is really interesting! Is it possible that the RCU stall detector
is somehow confused?

> Is preemption disabled for another reason?

I do not think so. I will have to double check the code but this is a
standard sleepable context. Just wondering what is the PREEMPT
configuration here?
-- 
Michal Hocko
SUSE Labs

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

#1533242

FromDonald Buczek <buczek@molgen.mpg.de>
Date2016-11-30 12:50 +0100
Message-ID<sJbyF-5yf-9@gated-at.bofh.it>
In reply to#1533230
On 11/30/16 12:09, Michal Hocko wrote:
> [CCing Paul]
>
> On Wed 30-11-16 11:28:34, Donald Buczek wrote:
> [...]
>> shrink_active_list gets and releases the spinlock and calls cond_resched().
>> This should give other tasks a chance to run. Just as an experiment, I'm
>> trying
>>
>> --- a/mm/vmscan.c
>> +++ b/mm/vmscan.c
>> @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
>> nr_to_scan,
>>          spin_unlock_irq(&pgdat->lru_lock);
>>
>>          while (!list_empty(&l_hold)) {
>> -               cond_resched();
>> +               cond_resched_rcu_qs();
>>                  page = lru_to_page(&l_hold);
>>                  list_del(&page->lru);
>>
>> and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.
> This is really interesting! Is it possible that the RCU stall detector
> is somehow confused?

Wait... 21 hours is not yet a test result.

>> Is preemption disabled for another reason?
> I do not think so. I will have to double check the code but this is a
> standard sleepable context. Just wondering what is the PREEMPT
> configuration here?

buczek@null:~$ zcat /proc/config.gz |grep PREE
CONFIG_PREEMPT_NOTIFIERS=y
# CONFIG_PREEMPT_NONE is not set
CONFIG_PREEMPT_VOLUNTARY=y
# CONFIG_PREEMPT is not set

Thanks
   Donald

-- 
Donald Buczek
buczek@molgen.mpg.de
Tel: +49 30 8413 1433

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

#1534760

FromDonald Buczek <buczek@molgen.mpg.de>
Date2016-12-02 10:20 +0100
Message-ID<sJSaB-1Wx-19@gated-at.bofh.it>
In reply to#1533242
On 11/30/16 12:43, Donald Buczek wrote:
> On 11/30/16 12:09, Michal Hocko wrote:
>> [CCing Paul]
>>
>> On Wed 30-11-16 11:28:34, Donald Buczek wrote:
>> [...]
>>> shrink_active_list gets and releases the spinlock and calls 
>>> cond_resched().
>>> This should give other tasks a chance to run. Just as an experiment, 
>>> I'm
>>> trying
>>>
>>> --- a/mm/vmscan.c
>>> +++ b/mm/vmscan.c
>>> @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
>>> nr_to_scan,
>>>          spin_unlock_irq(&pgdat->lru_lock);
>>>
>>>          while (!list_empty(&l_hold)) {
>>> -               cond_resched();
>>> +               cond_resched_rcu_qs();
>>>                  page = lru_to_page(&l_hold);
>>>                  list_del(&page->lru);
>>>
>>> and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.
>> This is really interesting! Is it possible that the RCU stall detector
>> is somehow confused?
>
> Wait... 21 hours is not yet a test result.

For the records: We didn't have any stall warnings after 2 days and 20 
hours now and so I'm quite confident, that my above patch fixed the 
problem for v4.8.0. On previous boots the rcu warnings started after 
37,0.2,1,2,0.8 hours uptime.

Now I've applied this patch to stable latest (v4.8.11) on another backup 
machine which suffered even more rcu stalls.

Donald

> [...]

-- 
Donald Buczek
buczek@molgen.mpg.de
Tel: +49 30 8413 1433

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

#1536764

FromDonald Buczek <buczek@molgen.mpg.de>
Date2016-12-06 09:40 +0100
Message-ID<sLjs5-87p-1@gated-at.bofh.it>
In reply to#1534760
On 12/02/16 10:14, Donald Buczek wrote:
> On 11/30/16 12:43, Donald Buczek wrote:
>> On 11/30/16 12:09, Michal Hocko wrote:
>>> [CCing Paul]
>>>
>>> On Wed 30-11-16 11:28:34, Donald Buczek wrote:
>>> [...]
>>>> shrink_active_list gets and releases the spinlock and calls 
>>>> cond_resched().
>>>> This should give other tasks a chance to run. Just as an 
>>>> experiment, I'm
>>>> trying
>>>>
>>>> --- a/mm/vmscan.c
>>>> +++ b/mm/vmscan.c
>>>> @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
>>>> nr_to_scan,
>>>>          spin_unlock_irq(&pgdat->lru_lock);
>>>>
>>>>          while (!list_empty(&l_hold)) {
>>>> -               cond_resched();
>>>> +               cond_resched_rcu_qs();
>>>>                  page = lru_to_page(&l_hold);
>>>>                  list_del(&page->lru);
>>>>
>>>> and didn't hit a rcu_sched warning for >21 hours uptime now. We'll 
>>>> see.
>>> This is really interesting! Is it possible that the RCU stall detector
>>> is somehow confused?
>>
>> Wait... 21 hours is not yet a test result.
>
> For the records: We didn't have any stall warnings after 2 days and 20 
> hours now and so I'm quite confident, that my above patch fixed the 
> problem for v4.8.0. On previous boots the rcu warnings started after 
> 37,0.2,1,2,0.8 hours uptime.
>
> Now I've applied this patch to stable latest (v4.8.11) on another 
> backup machine which suffered even more rcu stalls.
>
> Donald
>
>> [...]

For the records: After 3 days and 21 hours we've got a rcu stall warning 
again [1]. So my patch didn't fix it.

Trying "[PATCH] mm, vmscan: add cond_resched into shrink_node_memcg" 
from Michal Hocko [2] on top of v4.8.12 on both servers now.

[1] https://owww.molgen.mpg.de/~buczek/321322/2016-12-06.dmesg.txt
[2] https://marc.info/?i=20161202095841.16648-1-mhocko%40kernel.org

-- 
Donald Buczek
buczek@molgen.mpg.de
Tel: +49 30 8413 1433

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

#1533250

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-11-30 13:00 +0100
Message-ID<sJbIl-5Bx-13@gated-at.bofh.it>
In reply to#1533230
On Wed, Nov 30, 2016 at 03:53:20AM -0800, Paul E. McKenney wrote:
> On Wed, Nov 30, 2016 at 12:09:44PM +0100, Michal Hocko wrote:
> > [CCing Paul]
> > 
> > On Wed 30-11-16 11:28:34, Donald Buczek wrote:
> > [...]
> > > shrink_active_list gets and releases the spinlock and calls cond_resched().
> > > This should give other tasks a chance to run. Just as an experiment, I'm
> > > trying
> > > 
> > > --- a/mm/vmscan.c
> > > +++ b/mm/vmscan.c
> > > @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
> > > nr_to_scan,
> > >         spin_unlock_irq(&pgdat->lru_lock);
> > > 
> > >         while (!list_empty(&l_hold)) {
> > > -               cond_resched();
> > > +               cond_resched_rcu_qs();
> > >                 page = lru_to_page(&l_hold);
> > >                 list_del(&page->lru);
> > > 
> > > and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.
> > 
> > This is really interesting! Is it possible that the RCU stall detector
> > is somehow confused?
> 
> No, it is not confused.  Again, cond_resched() is not a quiescent
> state unless it does a context switch.  Therefore, if the task running
> in that loop was the only runnable task on its CPU, cond_resched()
> would -never- provide RCU with a quiescent state.
> 
> In contrast, cond_resched_rcu_qs() unconditionally provides RCU
> with a quiescent state (hence the _rcu_qs in its name), regardless
> of whether or not a context switch happens.
> 
> It is therefore expected behavior that this change might prevent
> RCU CPU stall warnings.

I should add...  This assumes that CONFIG_PREEMPT=n.  So what is
CONFIG_PREEMPT?

							Thanx, Paul

> > > Is preemption disabled for another reason?
> > 
> > I do not think so. I will have to double check the code but this is a
> > standard sleepable context. Just wondering what is the PREEMPT
> > configuration here?
> > -- 
> > Michal Hocko
> > SUSE Labs
> >

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

#1533268

FromPaul Menzel <pmenzel@molgen.mpg.de>
Date2016-11-30 13:40 +0100
Message-ID<sJcl3-67K-13@gated-at.bofh.it>
In reply to#1533250
On 11/30/16 12:54, Paul E. McKenney wrote:
> On Wed, Nov 30, 2016 at 03:53:20AM -0800, Paul E. McKenney wrote:
>> On Wed, Nov 30, 2016 at 12:09:44PM +0100, Michal Hocko wrote:
>>> [CCing Paul]
>>>
>>> On Wed 30-11-16 11:28:34, Donald Buczek wrote:
>>> [...]
>>>> shrink_active_list gets and releases the spinlock and calls cond_resched().
>>>> This should give other tasks a chance to run. Just as an experiment, I'm
>>>> trying
>>>>
>>>> --- a/mm/vmscan.c
>>>> +++ b/mm/vmscan.c
>>>> @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
>>>> nr_to_scan,
>>>>         spin_unlock_irq(&pgdat->lru_lock);
>>>>
>>>>         while (!list_empty(&l_hold)) {
>>>> -               cond_resched();
>>>> +               cond_resched_rcu_qs();
>>>>                 page = lru_to_page(&l_hold);
>>>>                 list_del(&page->lru);
>>>>
>>>> and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.
>>>
>>> This is really interesting! Is it possible that the RCU stall detector
>>> is somehow confused?
>>
>> No, it is not confused.  Again, cond_resched() is not a quiescent
>> state unless it does a context switch.  Therefore, if the task running
>> in that loop was the only runnable task on its CPU, cond_resched()
>> would -never- provide RCU with a quiescent state.
>>
>> In contrast, cond_resched_rcu_qs() unconditionally provides RCU
>> with a quiescent state (hence the _rcu_qs in its name), regardless
>> of whether or not a context switch happens.
>>
>> It is therefore expected behavior that this change might prevent
>> RCU CPU stall warnings.
> 
> I should add...  This assumes that CONFIG_PREEMPT=n.  So what is
> CONFIG_PREEMPT?

It’s not selected.

```
# CONFIG_PREEMPT is not set
```

>>>> Is preemption disabled for another reason?
>>>
>>> I do not think so. I will have to double check the code but this is a
>>> standard sleepable context. Just wondering what is the PREEMPT
>>> configuration here?


Kind regards,

Paul

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

#1533351

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-11-30 15:40 +0100
Message-ID<sJedc-7iT-19@gated-at.bofh.it>
In reply to#1533268
On Wed, Nov 30, 2016 at 01:31:37PM +0100, Paul Menzel wrote:
> On 11/30/16 12:54, Paul E. McKenney wrote:
> > On Wed, Nov 30, 2016 at 03:53:20AM -0800, Paul E. McKenney wrote:
> >> On Wed, Nov 30, 2016 at 12:09:44PM +0100, Michal Hocko wrote:
> >>> [CCing Paul]
> >>>
> >>> On Wed 30-11-16 11:28:34, Donald Buczek wrote:
> >>> [...]
> >>>> shrink_active_list gets and releases the spinlock and calls cond_resched().
> >>>> This should give other tasks a chance to run. Just as an experiment, I'm
> >>>> trying
> >>>>
> >>>> --- a/mm/vmscan.c
> >>>> +++ b/mm/vmscan.c
> >>>> @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
> >>>> nr_to_scan,
> >>>>         spin_unlock_irq(&pgdat->lru_lock);
> >>>>
> >>>>         while (!list_empty(&l_hold)) {
> >>>> -               cond_resched();
> >>>> +               cond_resched_rcu_qs();
> >>>>                 page = lru_to_page(&l_hold);
> >>>>                 list_del(&page->lru);
> >>>>
> >>>> and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.
> >>>
> >>> This is really interesting! Is it possible that the RCU stall detector
> >>> is somehow confused?
> >>
> >> No, it is not confused.  Again, cond_resched() is not a quiescent
> >> state unless it does a context switch.  Therefore, if the task running
> >> in that loop was the only runnable task on its CPU, cond_resched()
> >> would -never- provide RCU with a quiescent state.
> >>
> >> In contrast, cond_resched_rcu_qs() unconditionally provides RCU
> >> with a quiescent state (hence the _rcu_qs in its name), regardless
> >> of whether or not a context switch happens.
> >>
> >> It is therefore expected behavior that this change might prevent
> >> RCU CPU stall warnings.
> > 
> > I should add...  This assumes that CONFIG_PREEMPT=n.  So what is
> > CONFIG_PREEMPT?
> 
> It’s not selected.
> 
> ```
> # CONFIG_PREEMPT is not set
> ```

Thank you for the info!

As noted elsewhere in this thread, there are other ways to get stalls,
including the long irq-disabled execution that Michal suspects.

							Thanx, Paul

> >>>> Is preemption disabled for another reason?
> >>>
> >>> I do not think so. I will have to double check the code but this is a
> >>> standard sleepable context. Just wondering what is the PREEMPT
> >>> configuration here?
> 
> 
> Kind regards,
> 
> Paul
>

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

#1533251

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-11-30 13:00 +0100
Message-ID<sJbIl-5Bx-15@gated-at.bofh.it>
In reply to#1533230
On Wed, Nov 30, 2016 at 12:09:44PM +0100, Michal Hocko wrote:
> [CCing Paul]
> 
> On Wed 30-11-16 11:28:34, Donald Buczek wrote:
> [...]
> > shrink_active_list gets and releases the spinlock and calls cond_resched().
> > This should give other tasks a chance to run. Just as an experiment, I'm
> > trying
> > 
> > --- a/mm/vmscan.c
> > +++ b/mm/vmscan.c
> > @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
> > nr_to_scan,
> >         spin_unlock_irq(&pgdat->lru_lock);
> > 
> >         while (!list_empty(&l_hold)) {
> > -               cond_resched();
> > +               cond_resched_rcu_qs();
> >                 page = lru_to_page(&l_hold);
> >                 list_del(&page->lru);
> > 
> > and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.
> 
> This is really interesting! Is it possible that the RCU stall detector
> is somehow confused?

No, it is not confused.  Again, cond_resched() is not a quiescent
state unless it does a context switch.  Therefore, if the task running
in that loop was the only runnable task on its CPU, cond_resched()
would -never- provide RCU with a quiescent state.

In contrast, cond_resched_rcu_qs() unconditionally provides RCU
with a quiescent state (hence the _rcu_qs in its name), regardless
of whether or not a context switch happens.

It is therefore expected behavior that this change might prevent
RCU CPU stall warnings.

							Thanx, Paul

> > Is preemption disabled for another reason?
> 
> I do not think so. I will have to double check the code but this is a
> standard sleepable context. Just wondering what is the PREEMPT
> configuration here?
> -- 
> Michal Hocko
> SUSE Labs
>

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

#1533287

FromMichal Hocko <mhocko@kernel.org>
Date2016-11-30 14:20 +0100
Message-ID<sJcXL-6zu-1@gated-at.bofh.it>
In reply to#1533251
On Wed 30-11-16 03:53:20, Paul E. McKenney wrote:
> On Wed, Nov 30, 2016 at 12:09:44PM +0100, Michal Hocko wrote:
> > [CCing Paul]
> > 
> > On Wed 30-11-16 11:28:34, Donald Buczek wrote:
> > [...]
> > > shrink_active_list gets and releases the spinlock and calls cond_resched().
> > > This should give other tasks a chance to run. Just as an experiment, I'm
> > > trying
> > > 
> > > --- a/mm/vmscan.c
> > > +++ b/mm/vmscan.c
> > > @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
> > > nr_to_scan,
> > >         spin_unlock_irq(&pgdat->lru_lock);
> > > 
> > >         while (!list_empty(&l_hold)) {
> > > -               cond_resched();
> > > +               cond_resched_rcu_qs();
> > >                 page = lru_to_page(&l_hold);
> > >                 list_del(&page->lru);
> > > 
> > > and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.
> > 
> > This is really interesting! Is it possible that the RCU stall detector
> > is somehow confused?
> 
> No, it is not confused.  Again, cond_resched() is not a quiescent
> state unless it does a context switch.  Therefore, if the task running
> in that loop was the only runnable task on its CPU, cond_resched()
> would -never- provide RCU with a quiescent state.

Sorry for being dense here. But why cannot we hide the QS handling into
cond_resched()? I mean doesn't every current usage of cond_resched
suffer from the same problem wrt RCU stalls?

> In contrast, cond_resched_rcu_qs() unconditionally provides RCU
> with a quiescent state (hence the _rcu_qs in its name), regardless
> of whether or not a context switch happens.
> 
> It is therefore expected behavior that this change might prevent
> RCU CPU stall warnings.
> 
> 							Thanx, Paul

-- 
Michal Hocko
SUSE Labs

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

#1533353

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-11-30 15:40 +0100
Message-ID<sJedc-7iT-25@gated-at.bofh.it>
In reply to#1533287
On Wed, Nov 30, 2016 at 02:19:10PM +0100, Michal Hocko wrote:
> On Wed 30-11-16 03:53:20, Paul E. McKenney wrote:
> > On Wed, Nov 30, 2016 at 12:09:44PM +0100, Michal Hocko wrote:
> > > [CCing Paul]
> > > 
> > > On Wed 30-11-16 11:28:34, Donald Buczek wrote:
> > > [...]
> > > > shrink_active_list gets and releases the spinlock and calls cond_resched().
> > > > This should give other tasks a chance to run. Just as an experiment, I'm
> > > > trying
> > > > 
> > > > --- a/mm/vmscan.c
> > > > +++ b/mm/vmscan.c
> > > > @@ -1921,7 +1921,7 @@ static void shrink_active_list(unsigned long
> > > > nr_to_scan,
> > > >         spin_unlock_irq(&pgdat->lru_lock);
> > > > 
> > > >         while (!list_empty(&l_hold)) {
> > > > -               cond_resched();
> > > > +               cond_resched_rcu_qs();
> > > >                 page = lru_to_page(&l_hold);
> > > >                 list_del(&page->lru);
> > > > 
> > > > and didn't hit a rcu_sched warning for >21 hours uptime now. We'll see.
> > > 
> > > This is really interesting! Is it possible that the RCU stall detector
> > > is somehow confused?
> > 
> > No, it is not confused.  Again, cond_resched() is not a quiescent
> > state unless it does a context switch.  Therefore, if the task running
> > in that loop was the only runnable task on its CPU, cond_resched()
> > would -never- provide RCU with a quiescent state.
> 
> Sorry for being dense here. But why cannot we hide the QS handling into
> cond_resched()? I mean doesn't every current usage of cond_resched
> suffer from the same problem wrt RCU stalls?

We can, and you are correct that cond_resched() does not unconditionally
supply RCU quiescent states, and never has.  Last time I tried to add
cond_resched_rcu_qs() semantics to cond_resched(), I got told "no",
but perhaps it is time to try again.

One of the challenges is that there are two different timeframes.
If we want CONFIG_PREEMPT=n kernels to have millisecond-level scheduling
latencies, we need a cond_resched() more than once per millisecond, and
the usual uncertainties will mean more like once per hundred microseconds
or so.  In contrast, the occasional 100-millisecond RCU grace period when
under heavy load is normally not considered to be a problem, which means
that a cond_resched_rcu_qs() every 10 milliseconds or so is just fine.

Which means that cond_resched() is much more sensitive to overhead
than is cond_resched_rcu_qs().

No reason not to give it another try, though!  (Adding Peter Zijlstra
to CC for his reactions.)

Right now, the added overhead is a function call, two tests of per-CPU
variables, one increment of a per-CPU variable, and a barrier() before
and after.  I could probably combine the tests, but I do need at least
one test.  I cannot see how I can eliminate either barrier().  I might
be able to pull the increment under the test.

The patch below is instead very straightforward, avoiding any
optimizations.  Untested, probably does not even build.

Failing this approach, the rule is as follows:

1.	Add cond_resched() to in-kernel loops that cause excessive
	scheduling latencies.

2.	Add cond_resched_rcu_qs() to in-kernel loops that cause
	RCU CPU stall warnings.

							Thanx, Paul

> > In contrast, cond_resched_rcu_qs() unconditionally provides RCU
> > with a quiescent state (hence the _rcu_qs in its name), regardless
> > of whether or not a context switch happens.
> > 
> > It is therefore expected behavior that this change might prevent
> > RCU CPU stall warnings.

------------------------------------------------------------------------

commit d7100358d066cd7d64301a2da161390e9f4aa63f
Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Date:   Wed Nov 30 06:24:30 2016 -0800

    sched,rcu: Make cond_resched() provide RCU quiescent state
    
    There is some confusion as to which of cond_resched() or
    cond_resched_rcu_qs() should be added to long in-kernel loops.
    This commit therefore eliminates the decision by adding RCU
    quiescent states to cond_resched().
    
    Warning: This is a prototype.  For example, it does not correctly
    handle Tasks RCU.  Which is OK for the moment, given that no one
    actually uses Tasks RCU yet.
    
    Reported-by: Michal Hocko <mhocko@kernel.org>
    Not-yet-signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
    Cc: Peter Zijlstra <peterz@infradead.org>

diff --git a/include/linux/sched.h b/include/linux/sched.h
index 348f51b0ec92..ccdb6064884e 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -3308,10 +3308,11 @@ static inline int signal_pending_state(long state, struct task_struct *p)
  * cond_resched_lock() will drop the spinlock before scheduling,
  * cond_resched_softirq() will enable bhs before scheduling.
  */
+void rcu_all_qs(void);
 #ifndef CONFIG_PREEMPT
 extern int _cond_resched(void);
 #else
-static inline int _cond_resched(void) { return 0; }
+static inline int _cond_resched(void) { rcu_all_qs(); return 0; }
 #endif
 
 #define cond_resched() ({			\
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 94732d1ab00a..40b690813b80 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -4906,6 +4906,7 @@ int __sched _cond_resched(void)
 		preempt_schedule_common();
 		return 1;
 	}
+	rcu_all_qs();
 	return 0;
 }
 EXPORT_SYMBOL(_cond_resched);

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

#1533426

FromPeter Zijlstra <peterz@infradead.org>
Date2016-11-30 17:40 +0100
Message-ID<sJg5j-8ux-9@gated-at.bofh.it>
In reply to#1533353
On Wed, Nov 30, 2016 at 06:29:55AM -0800, Paul E. McKenney wrote:
> We can, and you are correct that cond_resched() does not unconditionally
> supply RCU quiescent states, and never has.  Last time I tried to add
> cond_resched_rcu_qs() semantics to cond_resched(), I got told "no",
> but perhaps it is time to try again.

Well, you got told: "ARRGH my benchmark goes all regress", or something
along those lines. Didn't we recently dig out those commits for some
reason or other?

Finding out what benchmark that was and running it against this patch
would make sense.

Also, I seem to have missed, why are we going through this again?

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

#1533446

FromMichal Hocko <mhocko@kernel.org>
Date2016-11-30 18:10 +0100
Message-ID<sJgyl-s0-13@gated-at.bofh.it>
In reply to#1533426
On Wed 30-11-16 17:38:20, Peter Zijlstra wrote:
> On Wed, Nov 30, 2016 at 06:29:55AM -0800, Paul E. McKenney wrote:
> > We can, and you are correct that cond_resched() does not unconditionally
> > supply RCU quiescent states, and never has.  Last time I tried to add
> > cond_resched_rcu_qs() semantics to cond_resched(), I got told "no",
> > but perhaps it is time to try again.
> 
> Well, you got told: "ARRGH my benchmark goes all regress", or something
> along those lines. Didn't we recently dig out those commits for some
> reason or other?
> 
> Finding out what benchmark that was and running it against this patch
> would make sense.
> 
> Also, I seem to have missed, why are we going through this again?

Well, the point I've brought that up is because having basically two
APIs for cond_resched is more than confusing. Basically all longer in
kernel loops do cond_resched() but it seems that this will not help the
silence RCU lockup detector in rare cases where nothing really wants to
schedule. I am really not sure whether we want to sprinkle
cond_resched_rcu_qs at random places just to silence RCU detector...

-- 
Michal Hocko
SUSE Labs

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

#1533462

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-11-30 18:30 +0100
Message-ID<sJgRI-yy-13@gated-at.bofh.it>
In reply to#1533446
On Wed, Nov 30, 2016 at 06:05:57PM +0100, Michal Hocko wrote:
> On Wed 30-11-16 17:38:20, Peter Zijlstra wrote:
> > On Wed, Nov 30, 2016 at 06:29:55AM -0800, Paul E. McKenney wrote:
> > > We can, and you are correct that cond_resched() does not unconditionally
> > > supply RCU quiescent states, and never has.  Last time I tried to add
> > > cond_resched_rcu_qs() semantics to cond_resched(), I got told "no",
> > > but perhaps it is time to try again.
> > 
> > Well, you got told: "ARRGH my benchmark goes all regress", or something
> > along those lines. Didn't we recently dig out those commits for some
> > reason or other?
> > 
> > Finding out what benchmark that was and running it against this patch
> > would make sense.
> > 
> > Also, I seem to have missed, why are we going through this again?
> 
> Well, the point I've brought that up is because having basically two
> APIs for cond_resched is more than confusing. Basically all longer in
> kernel loops do cond_resched() but it seems that this will not help the
> silence RCU lockup detector in rare cases where nothing really wants to
> schedule. I am really not sure whether we want to sprinkle
> cond_resched_rcu_qs at random places just to silence RCU detector...

Just in case there is any doubt on this point, any patch of mine adding
cond_resched_rcu_qs() functionality to cond_resched() cannot go upstream
without Peter's Acked-by.

Or did you have some other solution in mind?

							Thanx, Paul

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

#1533466

FromMichal Hocko <mhocko@kernel.org>
Date2016-11-30 18:40 +0100
Message-ID<sJh1n-BB-5@gated-at.bofh.it>
In reply to#1533462
On Wed 30-11-16 09:23:55, Paul E. McKenney wrote:
> On Wed, Nov 30, 2016 at 06:05:57PM +0100, Michal Hocko wrote:
> > On Wed 30-11-16 17:38:20, Peter Zijlstra wrote:
> > > On Wed, Nov 30, 2016 at 06:29:55AM -0800, Paul E. McKenney wrote:
> > > > We can, and you are correct that cond_resched() does not unconditionally
> > > > supply RCU quiescent states, and never has.  Last time I tried to add
> > > > cond_resched_rcu_qs() semantics to cond_resched(), I got told "no",
> > > > but perhaps it is time to try again.
> > > 
> > > Well, you got told: "ARRGH my benchmark goes all regress", or something
> > > along those lines. Didn't we recently dig out those commits for some
> > > reason or other?
> > > 
> > > Finding out what benchmark that was and running it against this patch
> > > would make sense.
> > > 
> > > Also, I seem to have missed, why are we going through this again?
> > 
> > Well, the point I've brought that up is because having basically two
> > APIs for cond_resched is more than confusing. Basically all longer in
> > kernel loops do cond_resched() but it seems that this will not help the
> > silence RCU lockup detector in rare cases where nothing really wants to
> > schedule. I am really not sure whether we want to sprinkle
> > cond_resched_rcu_qs at random places just to silence RCU detector...
> 
> Just in case there is any doubt on this point, any patch of mine adding
> cond_resched_rcu_qs() functionality to cond_resched() cannot go upstream
> without Peter's Acked-by.

Yeah, that is clear to me. I just wanted to clarify the "why are we
going through this again" part ;)
 
> Or did you have some other solution in mind?

Not really. The fact that cond_resched() cannot silence RCU stall
detector under some circumstances is sad. I believe we shouldn't
have two different APIs to control scheduling and RCU latencies because
that just asks for whack a mole games and some level of confusion...
-- 
Michal Hocko
SUSE Labs

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

#1533475

FromPeter Zijlstra <peterz@infradead.org>
Date2016-11-30 19:00 +0100
Message-ID<sJhkJ-Ij-3@gated-at.bofh.it>
In reply to#1533446
On Wed, Nov 30, 2016 at 06:05:57PM +0100, Michal Hocko wrote:
> On Wed 30-11-16 17:38:20, Peter Zijlstra wrote:
> > On Wed, Nov 30, 2016 at 06:29:55AM -0800, Paul E. McKenney wrote:
> > > We can, and you are correct that cond_resched() does not unconditionally
> > > supply RCU quiescent states, and never has.  Last time I tried to add
> > > cond_resched_rcu_qs() semantics to cond_resched(), I got told "no",
> > > but perhaps it is time to try again.
> > 
> > Well, you got told: "ARRGH my benchmark goes all regress", or something
> > along those lines. Didn't we recently dig out those commits for some
> > reason or other?
> > 
> > Finding out what benchmark that was and running it against this patch
> > would make sense.

See commit:

  4a81e8328d37 ("rcu: Reduce overhead of cond_resched() checks for RCU")

Someone actually wrote down what the problem was.

> > Also, I seem to have missed, why are we going through this again?
> 
> Well, the point I've brought that up is because having basically two
> APIs for cond_resched is more than confusing. Basically all longer in
> kernel loops do cond_resched() but it seems that this will not help the
> silence RCU lockup detector in rare cases where nothing really wants to
> schedule. I am really not sure whether we want to sprinkle
> cond_resched_rcu_qs at random places just to silence RCU detector...

Right.. now, this is obviously all PREEMPT=n code, which therefore also
implies this is rcu-sched.

Paul, now doesn't rcu-sched, when the grace-period has been long in
coming, try and force it? And doesn't that forcing include prodding CPUs
with resched_cpu() ?

I'm thinking not, because if it did, that would make cond_resched()
actually schedule, which would then call into rcu_note_context_switch()
which would then make RCU progress, no?

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

#1533592

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-11-30 22:40 +0100
Message-ID<sJkLD-2XW-11@gated-at.bofh.it>
In reply to#1533475
On Wed, Nov 30, 2016 at 06:50:16PM +0100, Peter Zijlstra wrote:
> On Wed, Nov 30, 2016 at 06:05:57PM +0100, Michal Hocko wrote:
> > On Wed 30-11-16 17:38:20, Peter Zijlstra wrote:
> > > On Wed, Nov 30, 2016 at 06:29:55AM -0800, Paul E. McKenney wrote:
> > > > We can, and you are correct that cond_resched() does not unconditionally
> > > > supply RCU quiescent states, and never has.  Last time I tried to add
> > > > cond_resched_rcu_qs() semantics to cond_resched(), I got told "no",
> > > > but perhaps it is time to try again.
> > > 
> > > Well, you got told: "ARRGH my benchmark goes all regress", or something
> > > along those lines. Didn't we recently dig out those commits for some
> > > reason or other?
> > > 
> > > Finding out what benchmark that was and running it against this patch
> > > would make sense.
> 
> See commit:
> 
>   4a81e8328d37 ("rcu: Reduce overhead of cond_resched() checks for RCU")
> 
> Someone actually wrote down what the problem was.

Don't worry, it won't happen again.  ;-)

OK, so the regressions were in the "open1" test of Anton Blanchard's
"will it scale" suite, and were due to faster (and thus more) grace
periods rather than path length.

I could likely counter the grace-period speedup by regulating the rate
at which the grace-period machinery pays attention to the rcu_qs_ctr
per-CPU variable.  Actually, this looks pretty straightforward (famous
last words).  But see patch below, which is untested and probably
completely bogus.

> > > Also, I seem to have missed, why are we going through this again?
> > 
> > Well, the point I've brought that up is because having basically two
> > APIs for cond_resched is more than confusing. Basically all longer in
> > kernel loops do cond_resched() but it seems that this will not help the
> > silence RCU lockup detector in rare cases where nothing really wants to
> > schedule. I am really not sure whether we want to sprinkle
> > cond_resched_rcu_qs at random places just to silence RCU detector...
> 
> Right.. now, this is obviously all PREEMPT=n code, which therefore also
> implies this is rcu-sched.
> 
> Paul, now doesn't rcu-sched, when the grace-period has been long in
> coming, try and force it? And doesn't that forcing include prodding CPUs
> with resched_cpu() ?

It does in the v4.8.4 kernel that Boris is running.  It still does in my
-rcu tree, but only after an RCU CPU stall (something about people not
liking IPIs).  I may need to do a resched_cpu() halfway to stall-warning
time or some such.

> I'm thinking not, because if it did, that would make cond_resched()
> actually schedule, which would then call into rcu_note_context_switch()
> which would then make RCU progress, no?

Sounds plausible, but from what I can see some of the loops pointed
out by Boris's stall-warning messages don't have cond_resched().
There was another workload that apparently worked better when moved from
cond_resched() to cond_resched_rcu_qs(), but I don't know what kernel
version was running.

							Thanx, Paul

------------------------------------------------------------------------

commit 42b4ae9cb79479d2f922620fd696a0532019799c
Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Date:   Wed Nov 30 11:21:21 2016 -0800

    rcu: Check cond_resched_rcu_qs() state less often to reduce GP overhead
    
    Commit 4a81e8328d37 ("rcu: Reduce overhead of cond_resched() checks
    for RCU") moved quiescent-state generation out of cond_resched()
    and commit bde6c3aa9930 ("rcu: Provide cond_resched_rcu_qs() to force
    quiescent states in long loops") introduced cond_resched_rcu_qs(), and
    commit 5cd37193ce85 ("rcu: Make cond_resched_rcu_qs() apply to normal RCU
    flavors") introduced the per-CPU rcu_qs_ctr variable, which is frequently
    polled by the RCU core state machine.
    
    This frequent polling can increase grace-period rate, which in turn
    increases grace-period overhead, which is visible in some benchmarks
    (for example, the "open1" benchmark in Anton Blanchard's "will it scale"
    suite).  This commit therefore reduces the rate at which rcu_qs_ctr
    is polled by moving that polling into the force-quiescent-state (FQS)
    machinery, and by further polling it only on the second and subsequent
    FQS passes of a given grace period.
    
    Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
index 9d4f9b3a2b7b..e3facb356838 100644
--- a/include/trace/events/rcu.h
+++ b/include/trace/events/rcu.h
@@ -385,11 +385,11 @@ TRACE_EVENT(rcu_quiescent_state_report,
 
 /*
  * Tracepoint for quiescent states detected by force_quiescent_state().
- * These trace events include the type of RCU, the grace-period number
- * that was blocked by the CPU, the CPU itself, and the type of quiescent
- * state, which can be "dti" for dyntick-idle mode, "ofl" for CPU offline,
- * or "kick" when kicking a CPU that has been in dyntick-idle mode for
- * too long.
+ * These trace events include the type of RCU, the grace-period number that
+ * was blocked by the CPU, the CPU itself, and the type of quiescent state,
+ * which can be "dti" for dyntick-idle mode, "ofl" for CPU offline, "kick"
+ * when kicking a CPU that has been in dyntick-idle mode for too long, or
+ * "rqc" if the CPU got a quiescent state via its rcu_qs_ctr.
  */
 TRACE_EVENT(rcu_fqs,
 
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index b546c959c854..6745f1899ad9 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -1275,6 +1275,7 @@ static int rcu_implicit_dynticks_qs(struct rcu_data *rdp,
 				    bool *isidle, unsigned long *maxj)
 {
 	int *rcrmp;
+	struct rcu_node *rnp;
 
 	/*
 	 * If the CPU passed through or entered a dynticks idle phase with
@@ -1291,6 +1292,19 @@ static int rcu_implicit_dynticks_qs(struct rcu_data *rdp,
 	}
 
 	/*
+	 * Has this CPU encountered a cond_resched_rcu_qs() since the
+	 * beginning of the grace period?  For this to be the case,
+	 * the CPU has to have noticed the current grace period.  This
+	 * might not be the case for nohz_full CPUs looping in the kernel.
+	 */
+	rnp = rdp->mynode;
+	if (READ_ONCE(rdp->rcu_qs_ctr_snap) != __this_cpu_read(rcu_qs_ctr) &&
+	    READ_ONCE(rdp->gpnum) == rnp->gpnum && !rdp->gpwrap) {
+		trace_rcu_fqs(rdp->rsp->name, rdp->gpnum, rdp->cpu, TPS("rqc"));
+		return 1;
+	}
+
+	/*
 	 * Check for the CPU being offline, but only if the grace period
 	 * is old enough.  We don't need to worry about the CPU changing
 	 * state: If we see it offline even once, it has been through a
@@ -2588,10 +2602,8 @@ rcu_report_qs_rdp(int cpu, struct rcu_state *rsp, struct rcu_data *rdp)
 
 	rnp = rdp->mynode;
 	raw_spin_lock_irqsave_rcu_node(rnp, flags);
-	if ((rdp->cpu_no_qs.b.norm &&
-	     rdp->rcu_qs_ctr_snap == __this_cpu_read(rcu_qs_ctr)) ||
-	    rdp->gpnum != rnp->gpnum || rnp->completed == rnp->gpnum ||
-	    rdp->gpwrap) {
+	if (rdp->cpu_no_qs.b.norm || rdp->gpnum != rnp->gpnum ||
+	    rnp->completed == rnp->gpnum || rdp->gpwrap) {
 
 		/*
 		 * The grace period in which this quiescent state was
@@ -2646,8 +2658,7 @@ rcu_check_quiescent_state(struct rcu_state *rsp, struct rcu_data *rdp)
 	 * Was there a quiescent state since the beginning of the grace
 	 * period? If no, then exit and wait for the next call.
 	 */
-	if (rdp->cpu_no_qs.b.norm &&
-	    rdp->rcu_qs_ctr_snap == __this_cpu_read(rcu_qs_ctr))
+	if (rdp->cpu_no_qs.b.norm)
 		return;
 
 	/*
@@ -3625,9 +3636,7 @@ static int __rcu_pending(struct rcu_state *rsp, struct rcu_data *rdp)
 	    rdp->core_needs_qs && rdp->cpu_no_qs.b.norm &&
 	    rdp->rcu_qs_ctr_snap == __this_cpu_read(rcu_qs_ctr)) {
 		rdp->n_rp_core_needs_qs++;
-	} else if (rdp->core_needs_qs &&
-		   (!rdp->cpu_no_qs.b.norm ||
-		    rdp->rcu_qs_ctr_snap != __this_cpu_read(rcu_qs_ctr))) {
+	} else if (rdp->core_needs_qs && !rdp->cpu_no_qs.b.norm) {
 		rdp->n_rp_report_qs++;
 		return 1;
 	}

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

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | linux.kernel

csiph-web