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]
Message-ID: <20160804231110.GU12670@dastard>
Date:	Fri, 5 Aug 2016 09:11:10 +1000
From:	Dave Chinner <david@...morbit.com>
To:	Mel Gorman <mgorman@...hsingularity.net>
Cc:	linux-kernel@...r.kernel.org
Subject: Re: [bug, 4.8] /proc/meminfo: counter values are very wrong

On Thu, Aug 04, 2016 at 01:34:58PM +0100, Mel Gorman wrote:
> On Thu, Aug 04, 2016 at 01:24:09PM +0100, Mel Gorman wrote:
> > On Thu, Aug 04, 2016 at 03:10:51PM +1000, Dave Chinner wrote:
> > > Hi folks,
> > > 
> > > I just noticed a whacky memory usage profile when running some basic
> > > IO tests on a current 4.8 tree. It looked like there was a massive
> > > memory leak from my monitoring graphs - doing buffered IO was
> > > causing huge amounts of memory to be considered used, but the cache
> > > size was not increasing.
> > > 
> > > Looking at /proc/meminfo:
> > > 
> > > $ cat /proc/meminfo
> > > MemTotal:       16395408 kB
> > > MemFree:           79424 kB
> > > MemAvailable:    2497240 kB
> > > Buffers:            4372 kB
> > > Cached:           558744 kB
> > > SwapCached:           48 kB
> > > Active:          2127212 kB
> > > Inactive:         100400 kB
> > > Active(anon):      25348 kB
> > > Inactive(anon):    79424 kB
> > > Active(file):    2101864 kB
> > > Inactive(file):    20976 kB
> > > Unevictable:    13612980 kB	<<<<<<<<<
> > 
> > This? Very quickly done, no boot testing
> > 
> 
> Or better yet, this. This is aimed at the proc reporting only.
> 
> diff --git a/fs/proc/meminfo.c b/fs/proc/meminfo.c
> index 09e18fdf61e5..b9a8c813e5e6 100644
> --- a/fs/proc/meminfo.c
> +++ b/fs/proc/meminfo.c
> @@ -46,7 +46,7 @@ static int meminfo_proc_show(struct seq_file *m, void *v)
>  		cached = 0;
>  
>  	for (lru = LRU_BASE; lru < NR_LRU_LISTS; lru++)
> -		pages[lru] = global_page_state(NR_LRU_BASE + lru);
> +		pages[lru] = global_node_page_state(NR_LRU_BASE + lru);
>  
>  	available = si_mem_available();
>  
> diff --git a/mm/page_alloc.c b/mm/page_alloc.c
> index fb975cec3518..baa97da3687d 100644
> --- a/mm/page_alloc.c
> +++ b/mm/page_alloc.c
> @@ -4064,7 +4064,7 @@ long si_mem_available(void)
>  	int lru;
>  
>  	for (lru = LRU_BASE; lru < NR_LRU_LISTS; lru++)
> -		pages[lru] = global_page_state(NR_LRU_BASE + lru);
> +		pages[lru] = global_node_page_state(NR_LRU_BASE + lru);
>  
>  	for_each_zone(zone)
>  		wmark_low += zone->watermark[WMARK_LOW];

OK, that makes the /proc accounting match the /sys per-node
accounting, but the output still looks wrong. I remove files with
cached pages from the filesystem (i.e. invalidate and free them),
yet they are apparrently still accounted as being on the
active/inactive LRU.

Reboot, then run dbench for a minute:

$ sudo mkfs.xfs -f /dev/pmem1
meta-data=/dev/pmem1             isize=512    agcount=4, agsize=524288 blks
         =                       sectsz=4096  attr=2, projid32bit=1
         =                       crc=1        finobt=1, sparse=0
data     =                       bsize=4096   blocks=2097152, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0 ftype=1
log      =internal log           bsize=4096   blocks=2560, version=2
         =                       sectsz=4096  sunit=1 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0
$ sudo mount /dev/pmem1 /mnt/scratch
$ sudo dbench -t 60 -D /mnt/scratch/ 16
dbench version 4.00 - Copyright Andrew Tridgell 1999-2004

Running for 60 seconds with load '/usr/share/dbench/client.txt' and minimum warmup 12 secs
13 of 16 processes prepared for launch   0 sec
16 of 16 processes prepared for launch   0 sec
releasing clients
  16     21754  2147.77 MB/sec  warmup   1 sec  latency 17.381 ms
  16     53021  2426.23 MB/sec  warmup   2 sec  latency 7.557 ms
  16     79871  2389.22 MB/sec  warmup   3 sec  latency 13.746 ms
  16    110047  2441.00 MB/sec  warmup   4 sec  latency 7.685 ms
  16    141388  2495.74 MB/sec  warmup   5 sec  latency 10.877 ms
  16    172085  2519.72 MB/sec  warmup   6 sec  latency 14.059 ms
  16    205794  2574.78 MB/sec  warmup   7 sec  latency 8.034 ms
  16    245632  2682.26 MB/sec  warmup   8 sec  latency 6.851 ms
  16    286074  2771.92 MB/sec  warmup   9 sec  latency 6.495 ms
  16    317664  2767.22 MB/sec  warmup  10 sec  latency 10.318 ms
  16    345883  2736.86 MB/sec  warmup  11 sec  latency 14.107 ms
  16    407209  2491.90 MB/sec  execute   1 sec  latency 14.000 ms
  16    434075  2416.98 MB/sec  execute   2 sec  latency 14.067 ms
  16    460773  2405.59 MB/sec  execute   3 sec  latency 10.984 ms
  16    489597  2438.34 MB/sec  execute   4 sec  latency 12.759 ms
  16    516526  2432.47 MB/sec  execute   5 sec  latency 11.068 ms
  16    550227  2511.25 MB/sec  execute   6 sec  latency 8.156 ms
  16    592814  2677.03 MB/sec  execute   7 sec  latency 5.571 ms
  16    633506  2781.02 MB/sec  execute   8 sec  latency 6.116 ms
  16    668733  2808.95 MB/sec  execute   9 sec  latency 8.357 ms
  16    706375  2853.15 MB/sec  execute  10 sec  latency 14.133 ms
  16    738346  2843.96 MB/sec  execute  11 sec  latency 9.305 ms
  16    766890  2812.90 MB/sec  execute  12 sec  latency 9.677 ms
  16    795720  2788.20 MB/sec  execute  13 sec  latency 11.019 ms
  16    827221  2783.46 MB/sec  execute  14 sec  latency 9.281 ms
  16    857404  2774.13 MB/sec  execute  15 sec  latency 7.055 ms
  16    886224  2756.10 MB/sec  execute  16 sec  latency 9.445 ms
  16    915254  2744.52 MB/sec  execute  17 sec  latency 10.447 ms
  16    949089  2757.18 MB/sec  execute  18 sec  latency 18.721 ms
  16    982041  2763.18 MB/sec  execute  19 sec  latency 12.401 ms
  16   1013375  2762.66 MB/sec  execute  20 sec  latency 10.355 ms
  16   1045294  2763.22 MB/sec  execute  21 sec  latency 11.896 ms
  16   1083431  2786.87 MB/sec  execute  22 sec  latency 8.539 ms
  16   1121150  2807.17 MB/sec  execute  23 sec  latency 11.574 ms
  16   1152589  2803.24 MB/sec  execute  24 sec  latency 9.669 ms
  16   1189106  2816.73 MB/sec  execute  25 sec  latency 10.104 ms
  16   1222171  2819.00 MB/sec  execute  26 sec  latency 15.502 ms
  16   1253029  2813.85 MB/sec  execute  27 sec  latency 10.030 ms
  16   1283695  2808.15 MB/sec  execute  28 sec  latency 14.520 ms
  16   1310353  2791.60 MB/sec  execute  29 sec  latency 10.559 ms
  16   1339147  2781.06 MB/sec  execute  30 sec  latency 10.048 ms
  16   1367932  2772.66 MB/sec  execute  31 sec  latency 8.283 ms
  16   1397614  2766.76 MB/sec  execute  32 sec  latency 18.411 ms
  16   1424115  2753.46 MB/sec  execute  33 sec  latency 10.346 ms
  16   1450474  2739.71 MB/sec  execute  34 sec  latency 14.018 ms
  16   1477712  2729.13 MB/sec  execute  35 sec  latency 13.977 ms
  16   1504889  2719.33 MB/sec  execute  36 sec  latency 12.919 ms
  16   1541168  2731.19 MB/sec  execute  37 sec  latency 7.316 ms
  16   1576119  2738.48 MB/sec  execute  38 sec  latency 7.054 ms
  16   1607758  2738.84 MB/sec  execute  39 sec  latency 8.155 ms
  16   1640821  2742.17 MB/sec  execute  40 sec  latency 6.686 ms
  16   1672161  2741.02 MB/sec  execute  41 sec  latency 10.458 ms
  16   1701658  2736.87 MB/sec  execute  42 sec  latency 13.877 ms
  16   1731166  2732.70 MB/sec  execute  43 sec  latency 12.307 ms
  16   1759926  2726.88 MB/sec  execute  44 sec  latency 9.745 ms
  16   1785855  2716.11 MB/sec  execute  45 sec  latency 12.085 ms
  16   1815083  2712.64 MB/sec  execute  46 sec  latency 8.048 ms
  16   1843967  2708.13 MB/sec  execute  47 sec  latency 13.302 ms
  16   1871199  2701.24 MB/sec  execute  48 sec  latency 10.160 ms
  16   1898231  2694.15 MB/sec  execute  49 sec  latency 16.625 ms
  16   1929620  2694.67 MB/sec  execute  50 sec  latency 10.693 ms
  16   1968670  2708.80 MB/sec  execute  51 sec  latency 20.115 ms
  16   2001738  2711.94 MB/sec  execute  52 sec  latency 7.594 ms
  16   2038135  2720.41 MB/sec  execute  53 sec  latency 12.177 ms
  16   2069687  2721.12 MB/sec  execute  54 sec  latency 8.222 ms
  16   2097545  2715.63 MB/sec  execute  55 sec  latency 14.536 ms
  16   2122502  2705.52 MB/sec  execute  56 sec  latency 14.738 ms
  16   2148142  2697.19 MB/sec  execute  57 sec  latency 14.473 ms
  16   2178085  2695.15 MB/sec  execute  58 sec  latency 8.586 ms
  16   2210608  2697.11 MB/sec  execute  59 sec  latency 10.013 ms
  16  cleanup  60 sec
   0  cleanup  60 sec

 Operation      Count    AvgLat    MaxLat
 ----------------------------------------
 NTCreateX    5153313     0.048    15.558
 Close        3785702     0.003     8.334
 Rename        218238     0.041     9.738
 Unlink       1040545     0.336    18.710
 Deltree          136    11.999    65.636
 Mkdir             68     0.004     0.007
 Qpathinfo    4670973     0.007     8.336
 Qfileinfo     818833     0.001     8.544
 Qfsinfo       856506     0.005     4.494
 Sfileinfo     419850     0.013     8.224
 Find         1806064     0.018    13.301
 WriteX       2570636     0.032    16.620
 ReadX        8078906     0.005    12.453
 LockX          16782     0.004     1.633
 UnlockX        16782     0.002     0.179
 Flush         361228     0.171    20.110

Throughput 2697.11 MB/sec  16 clients  16 procs  max_latency=20.115 ms
$ cat /proc/meminfo 
MemTotal:       16395372 kB
MemFree:           74092 kB
MemAvailable:   16090152 kB
Buffers:           59348 kB
Cached:           142660 kB
SwapCached:            0 kB
Active:          3098852 kB
Inactive:       12669128 kB
Active(anon):      21580 kB
Inactive(anon):    25288 kB
Active(file):    3077272 kB
Inactive(file): 12643840 kB
Unevictable:        3516 kB
Mlocked:            3516 kB
SwapTotal:        497976 kB
SwapFree:         497976 kB
Dirty:                 0 kB
Writeback:             0 kB
AnonPages:         39248 kB
Mapped:            36596 kB
Shmem:              8968 kB
Slab:             462224 kB
SReclaimable:     428468 kB
SUnreclaim:        33756 kB
KernelStack:        6256 kB
PageTables:         6852 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:     8695660 kB
Committed_AS:     187528 kB
VmallocTotal:   34359738367 kB
VmallocUsed:           0 kB
VmallocChunk:          0 kB
HugePages_Total:       0
HugePages_Free:        0
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
DirectMap4k:       14204 kB
DirectMap2M:    16762880 kB
$

dbench completely removes the files it uses during the test.
Aparently I have 15GB of cached file lru pages in the system now,
which should be impossible because the filesystem is only 8GB in
size. It also doesn't match the "cached" accounting, so free
considers all these lru pages as used, not free:

$ free
              total        used        free      shared  buff/cache   available
Mem:       16395372    15652956       78264        8968      664152    16094336
Swap:        497976           0      497976
$

So there's still something screwed up....

Cheers,

Dave.
-- 
Dave Chinner
david@...morbit.com

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ