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@xxxxxxxxxxxxx
Tel: +49 30 8413 1433
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@xxxxxxxxx. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@xxxxxxxxx";> email@xxxxxxxxx </a>