Re: Caching/buffers become useless after some time

[Michal Hocko <mhocko@suse.com>]

On Tue 30-10-18 14:44:27, Vlastimil Babka wrote:
> On 10/22/18 3:19 AM, Marinko Catovic wrote:
> > Am Mi., 29. Aug. 2018 um 18:44 Uhr schrieb Marinko Catovic
[...]
> >> here you go: https://nofile.io/f/VqRg644AT01/vmstat.tar.gz
> >> trace_pipe: https://nofile.io/f/wFShvZScpvn/trace_pipe.gz
> >>
> > 
> > There we go again.
> > 
> > First of all, I have set up this monitoring on 1 host, as a matter of
> > fact it did not occur on that single
> > one for days and weeks now, so I set this up again on all the hosts
> > and it just happened again on another one.
> > 
> > This issue is far from over, even when upgrading to the latest 4.18.12
> > 
> > https://nofile.io/f/z2KeNwJSMDj/vmstat-2.zip
> > https://nofile.io/f/5ezPUkFWtnx/trace_pipe-2.gz
> 
> I have plot the vmstat using the attached script, and got the attached
> plots. X axis are the vmstat snapshots, almost 14k of them, each for 5
> seconds, so almost 19 hours. I can see the following phases:

Thanks a lot. I like the script much!

[...]

> 12000 - end:
> - free pages growing sharply
> - page cache declining sharply
> - slab still slowly declining

$ cat filter 
pgfree
pgsteal_
pgscan_
compact
nr_free_pages

$ grep -f filter -h vmstat.1539866837 vmstat.1539874353 | awk '{if (c[$1]) {printf "%s %d\n", $1, $2-c[$1]}; c[$1]=$2}'
nr_free_pages 4216371
pgfree 267884025
pgsteal_kswapd 0
pgsteal_direct 11890416
pgscan_kswapd 0
pgscan_direct 11937805
compact_migrate_scanned 2197060121
compact_free_scanned 4747491606
compact_isolated 54281848
compact_stall 1797
compact_fail 1721
compact_success 76

So we have ended up with 16G freed pages in that last time period.
Kswapd was sleeping throughout the time but direct reclaim was quite
active. ~46GB pages recycled. Note that much more pages were freed which
suggests there was quite a large memory allocation/free activity.

One notable thing here is that there shouldn't be any reason to do the
direct reclaim when kswapd itself doesn't do anything. It could be
either blocked on something but I find it quite surprising to see it in
that state for the whole 1500s time period or we are simply not low on
free memory at all. That would point towards compaction triggered memory
reclaim which account as the direct reclaim as well. The direct
compaction triggered more than once a second in average. We shouldn't
really reclaim unless we are low on memory but repeatedly failing
compaction could just add up and reclaim a lot in the end. There seem to
be quite a lot of low order request as per your trace buffer

$ grep order trace-last-phase | sed 's@.*\(order=[0-9]*\).*gfp_flags=\(.*\)@\1 \2@' | sort | uniq -c
   1238 order=1 __GFP_HIGH|__GFP_ATOMIC|__GFP_NOWARN|__GFP_COMP|__GFP_THISNODE
   5812 order=1 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_COMP|__GFP_THISNODE
    121 order=1 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_NOMEMALLOC|__GFP_THISNODE
     22 order=1 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_THISNODE
 395910 order=1 GFP_KERNEL_ACCOUNT|__GFP_ZERO
 783055 order=1 GFP_NOWAIT|__GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_COMP|__GFP_ACCOUNT
   1060 order=1 __GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_NOMEMALLOC|__GFP_THISNODE
   3278 order=2 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_COMP|__GFP_THISNODE
 797255 order=2 GFP_NOWAIT|__GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_COMP|__GFP_ACCOUNT
  93524 order=3 GFP_ATOMIC|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_NOMEMALLOC
 498148 order=3 GFP_NOWAIT|__GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_COMP|__GFP_ACCOUNT
 243563 order=3 GFP_NOWAIT|__GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP
     10 order=4 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_THISNODE
    114 order=7 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_THISNODE
  67621 order=9 GFP_TRANSHUGE|__GFP_THISNODE

We can safely rule out NOWAIT and ATOMIC because those do not reclaim.
That leaves us with 
   5812 order=1 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_COMP|__GFP_THISNODE
    121 order=1 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_NOMEMALLOC|__GFP_THISNODE
     22 order=1 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_THISNODE
 395910 order=1 GFP_KERNEL_ACCOUNT|__GFP_ZERO
   1060 order=1 __GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_NOMEMALLOC|__GFP_THISNODE
   3278 order=2 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_COMP|__GFP_THISNODE
     10 order=4 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_THISNODE
    114 order=7 __GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_THISNODE
  67621 order=9 GFP_TRANSHUGE|__GFP_THISNODE

by large the kernel stack allocations are in lead. You can put some
relief by enabling CONFIG_VMAP_STACK. There is alos a notable number of
THP pages allocations. Just curious are you running on a NUMA machine?
If yes [1] might be relevant. Other than that nothing really jumped at
me.

[1] http://lkml.kernel.org/r/20180925120326.24392-2-mhocko@kernel.org
-- 
Michal Hocko
SUSE Labs