linux-kernel - Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and `mem_cgroup_shrink

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Wed, 16 Nov 2016 09:30:36 -0800
From:   "Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>
To:     Paul Menzel <pmenzel@...gen.mpg.de>
Cc:     linux-xfs@...r.kernel.org, linux-kernel@...r.kernel.org,
        Josh Triplett <josh@...htriplett.org>, dvteam@...gen.mpg.de
Subject: Re: INFO: rcu_sched detected stalls on CPUs/tasks with `kswapd` and
 `mem_cgroup_shrink_node`

On Wed, Nov 16, 2016 at 06:01:19PM +0100, Paul Menzel wrote:
> Dear Linux folks,
> 
> 
> On 11/08/16 19:39, Paul E. McKenney wrote:
> >On Tue, Nov 08, 2016 at 06:38:18PM +0100, Paul Menzel wrote:
> >>On 11/08/16 18:03, Paul E. McKenney wrote:
> >>>On Tue, Nov 08, 2016 at 01:22:28PM +0100, Paul Menzel wrote:
> >>
> >>>>Could you please help me shedding some light into the messages below?
> >>>>
> >>>>With Linux 4.4.X, these messages were not seen. When updating to
> >>>>Linux 4.8.4, and Linux 4.8.6 they started to appear. In that
> >>>>version, we enabled several CGROUP options.
> >>>>
> >>>>>$ dmesg -T
> >>>>>[…]
> >>>>>[Mon Nov  7 15:09:45 2016] INFO: rcu_sched detected stalls on CPUs/tasks:
> >>>>>[Mon Nov  7 15:09:45 2016]     3-...: (493 ticks this GP) idle=515/140000000000000/0 softirq=5504423/5504423 fqs=13876
> >>>>>[Mon Nov  7 15:09:45 2016]     (detected by 5, t=60002 jiffies, g=1363193, c=1363192, q=268508)
> >>>>>[Mon Nov  7 15:09:45 2016] Task dump for CPU 3:
> >>>>>[Mon Nov  7 15:09:45 2016] kswapd1         R  running task        0    87      2 0x00000008
> >>>>>[Mon Nov  7 15:09:45 2016]  ffffffff81aabdfd ffff8810042a5cb8 ffff88080ad34000 ffff88080ad33dc8
> >>>>>[Mon Nov  7 15:09:45 2016]  ffff88080ad33d00 0000000000003501 0000000000000000 0000000000000000
> >>>>>[Mon Nov  7 15:09:45 2016]  0000000000000000 0000000000000000 0000000000022316 000000000002bc9f
> >>>>>[Mon Nov  7 15:09:45 2016] Call Trace:
> >>>>>[Mon Nov  7 15:09:45 2016]  [<ffffffff81aabdfd>] ? __schedule+0x21d/0x5b0
> >>>>>[Mon Nov  7 15:09:45 2016]  [<ffffffff81106dcf>] ? shrink_node+0xbf/0x1c0
> >>>>>[Mon Nov  7 15:09:45 2016]  [<ffffffff81107865>] ? kswapd+0x315/0x5f0
> >>>>>[Mon Nov  7 15:09:45 2016]  [<ffffffff81107550>] ? mem_cgroup_shrink_node+0x90/0x90
> >>>>>[Mon Nov  7 15:09:45 2016]  [<ffffffff8106c614>] ? kthread+0xc4/0xe0
> >>>>>[Mon Nov  7 15:09:45 2016]  [<ffffffff81aaf64f>] ? ret_from_fork+0x1f/0x40
> >>>>>[Mon Nov  7 15:09:45 2016]  [<ffffffff8106c550>] ? kthread_worker_fn+0x160/0x160
> >>>>
> >>>>Even after reading `stallwarn.txt` [1], I don’t know what could
> >>>>cause this. All items in the backtrace seem to belong to the Linux
> >>>>kernel.
> >>>>
> >>>>There is also nothing suspicious in the monitoring graphs during that time.
> >>>
> >>>If you let it be, do you get a later stall warning a few minutes later?
> >>>If so, how does the stack trace compare?
> >>
> >>With Linux 4.8.6 this is the only occurrence since yesterday.
> >>
> >>With Linux 4.8.3, and 4.8.4 the following stack traces were seen.
> >
> >Looks to me like one or both of the loops in shrink_node() need
> >an cond_resched_rcu_qs().
> 
> Thank you for the pointer. I haven’t had time yet to look into it.

In theory, it is quite straightforward, as shown by the patch below.
In practice, the MM guys might wish to call cond_resched_rcu_qs() less
frequently, but I will leave that to their judgment.  My guess is that
the overhead of the cond_resched_rcu_qs() is way down in the noise,
but I have been surprised in the past.

Anyway, please give this patch a try and let me know how it goes.

							Thanx, Paul

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

commit 1a5595eec6c034c27e1c826a93292240bfea934e
Author: Paul E. McKenney <paulmck@...ux.vnet.ibm.com>
Date:   Wed Nov 16 09:26:28 2016 -0800

    mm: Prevent shrink_node() RCU CPU stall warnings
    
    This commit adds a couple cond_resched_rcu_qs() calls in the inner
    loop in shrink_node() in order to prevent RCU CPU stall warnings.
    
    Reported-by: Paul Menzel <pmenzel@...gen.mpg.de>
    Signed-off-by: Paul E. McKenney <paulmck@...ux.vnet.ibm.com>

diff --git a/mm/vmscan.c b/mm/vmscan.c
index 744f926af442..0d3b5f5a04ef 100644
--- a/mm/vmscan.c
+++ b/mm/vmscan.c
@@ -2529,8 +2529,11 @@ static bool shrink_node(pg_data_t *pgdat, struct scan_control *sc)
 			unsigned long scanned;
 
 			if (mem_cgroup_low(root, memcg)) {
-				if (!sc->may_thrash)
+				if (!sc->may_thrash) {
+					/* Prevent CPU CPU stalls. */
+					cond_resched_rcu_qs();
 					continue;
+				}
 				mem_cgroup_events(memcg, MEMCG_LOW, 1);
 			}
 
@@ -2565,6 +2568,7 @@ static bool shrink_node(pg_data_t *pgdat, struct scan_control *sc)
 				mem_cgroup_iter_break(root, memcg);
 				break;
 			}
+			cond_resched_rcu_qs(); /* Prevent CPU CPU stalls. */
 		} while ((memcg = mem_cgroup_iter(root, memcg, &reclaim)));
 
 		/*