Linux内存Cache问题定位

引子

最近在做服务器压力测试,经常关注的就是服务器的负载情况。我们目前服务器的逻辑进程主要使用 lua 编写,开启定期 GC 后单个用户占用内存大概在1M 左右,开多逻辑进程后,单个进程占用内存都不大。

这次的小范围内部测试,只申请了一台 4 核 8 G的机器,测试开始后,cpu 和其他负载都不大。但是跑了大概1个小时左右,查看内存发现 free 的很少,只有几百兆了。其实实际占用的也并不多,但是很大一部分内存被 cache 住了,大概有 4 个多 G。

1
2
3
4
5
$ free -m
total used free shared buffers cached
Mem: 7870 7698 172 0 153 4852
-/+ buffers/cache: 2691 5179
Swap: 0 0 0

以前只知道 cached 的内存一般是缓存的磁盘文件,如果后续需要内存,内核会采取策略释放这些 cached 的内存,不会出什么问题。但是这次很想知道是什么文件被 cache 住了,有没有优化措施。于是决定查下资料定位一下是哪些文件导致内存被大量 cache 的。

内存使用

首先通过 proc 文件系统的 meminfo 看下当前内存的使用情况。由于 top、vmstat、free 命令都是采样的 proc 文件系统的数据,所以直接看 meminfo 会更全面准确。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
$ cat /proc/meminfo 
MemTotal: 8059260 kB
MemFree: 176040 kB
Buffers: 157708 kB
Cached: 4969824 kB
SwapCached: 0 kB
Active: 6487916 kB
Inactive: 1093960 kB
Active(anon): 2454360 kB
Inactive(anon): 536 kB
Active(file): 4033556 kB
Inactive(file): 1093424 kB
Unevictable: 0 kB
Mlocked: 0 kB
SwapTotal: 0 kB
SwapFree: 0 kB
Dirty: 24 kB
Writeback: 0 kB
AnonPages: 2454348 kB
Mapped: 66424 kB
Shmem: 552 kB
Slab: 214400 kB
SReclaimable: 188528 kB
SUnreclaim: 25872 kB
KernelStack: 4176 kB
PageTables: 10540 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
WritebackTmp: 0 kB
CommitLimit: 4029628 kB
Committed_AS: 10610552 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 30988 kB
VmallocChunk: 34359664624 kB
HardwareCorrupted: 0 kB
AnonHugePages: 2281472 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
Hugepagesize: 2048 kB
DirectMap4k: 8180 kB
DirectMap2M: 8380416 kB

其中anno 匿名内存应该就是我们程序分配的堆栈内存,而 file 应该就是和文件关联的内存,比如我们的程序代码,打开的文件等。可以看到 Active(file)项已经很大了。

那怎么知道是哪个进程占用的比较多呢?这时候就要借助 top 命令的输出了。

image-20180901122607751

shift + M 按内存占用排序后可以看到,果然是我们的游戏进程占用最多。

RES 列的实际占用内存并不高,但是虚拟内存 VIRT 就将近3倍于实际使用内存,多出来的内存基本就是 cache 住的文件缓存了。

为了查看进程打开了哪些文件,我们 lsof 看下

1
lsof -p PID

具体结果由于涉及业务这里就不贴了, 打开的文件主要是程序可执行文件、连接的 so、网络连接、日志文件等。从 size 大小看除日志文件外,其他都很小。我们的日志轮转大小是100M,打开的日志文件大概有 200M 左右,总的加起来也不会有4G 大小。

于是猜想,是不是可能缓存了其他日志文件。由于我们测试为了方便查找问题,是开启 DEBUG 级别日志的,因此日志量比较大,一个小时单个进程轮转了9个日志文件,如果缓存了部分,那就很可观了。为了证实这个猜想,我查找了一些工具来统计 cache 内存的大小。

统计大小

网上推荐了 linux-ftools 这个工具来进行统计,fincore 是其中的一个。fincore 的工作原理是将指定的文件的相应 inode data 与 kernel 的 page cache table 做对比,如果 page cache table 有这个 inode 信息,就找该inode 对应的 data block 的大小。因为 kernel 的 page cache table 只存储 data block 的引用而不是文件名,即文件的 inode 信息。所以并没有任何一个工具运行一次就可以找出所有的文件使用缓存的情况。

不过遗憾的是,linux-ftools 不再维护了,编译这个程序会出问题。所幸的是,还有个 Go 实现的类似功能的工具,叫 pcstat,下载方式是

1
2
3
curl -L -o pcstat https://github.com/tobert/pcstat/raw/2014-05-02-01/pcstat.x86_64
或者
curl -L -o pcstat https://github.com/tobert/pcstat/raw/2014-05-02-01/pcstat.x86_32

这里感谢下作者的付出。

我们列出 log 目录下的所有目录文件,然后运行 pcstat 命令得到统计结果如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
$ ~/pcstat `ls *.0831*.log`
|------------------------------+----------------+------------+-----------+---------|
| Name | Size | Pages | Cached | Percent |
|------------------------------+----------------+------------+-----------+---------|
| dbsvr.0831.00.log | 91415 | 23 | 6 | 026.087 |
| dbsvr.error.0831.00.log | 2 | 1 | 1 | 100.000 |
| gamesvr1.0831.00.log | 104861059 | 25601 | 8040 | 031.405 |
| gamesvr1.0831.01.log | 104940405 | 25621 | 20750 | 080.988 |
| gamesvr1.0831.02.log | 105522786 | 25763 | 23659 | 091.833 |
| gamesvr1.0831.03.log | 105247528 | 25696 | 25693 | 099.988 |
| gamesvr1.0831.04.log | 105221709 | 25689 | 25689 | 100.000 |
| gamesvr1.0831.05.log | 105098602 | 25659 | 25659 | 100.000 |
| gamesvr1.0831.06.log | 105151912 | 25672 | 22430 | 087.371 |
| gamesvr1.0831.07.log | 104904682 | 25612 | 3266 | 012.752 |
| gamesvr1.0831.08.log | 78897232 | 19263 | 4666 | 024.223 |
| gamesvr1.error.0831.00.log | 600715 | 147 | 10 | 006.803 |
| gamesvr2.0831.00.log | 104963951 | 25626 | 9292 | 036.260 |
| gamesvr2.0831.01.log | 104965184 | 25627 | 19936 | 077.793 |
| gamesvr2.0831.02.log | 105106982 | 25661 | 14924 | 058.158 |
| gamesvr2.0831.03.log | 105292165 | 25707 | 24521 | 095.386 |
| gamesvr2.0831.04.log | 104927914 | 25618 | 23745 | 092.689 |
| gamesvr2.0831.05.log | 105090378 | 25657 | 13332 | 051.962 |
| gamesvr2.0831.06.log | 105175478 | 25678 | 10070 | 039.216 |
| gamesvr2.0831.07.log | 104893356 | 25609 | 21299 | 083.170 |
| gamesvr2.0831.08.log | 73241449 | 17882 | 10886 | 060.877 |
| gamesvr2.error.0831.00.log | 618867 | 152 | 9 | 005.921 |
| gamesvr3.0831.00.log | 105143734 | 25670 | 10861 | 042.310 |
| gamesvr3.0831.01.log | 104923026 | 25616 | 19485 | 076.066 |
| gamesvr3.0831.02.log | 104971350 | 25628 | 21631 | 084.404 |
| gamesvr3.0831.03.log | 104984690 | 25632 | 23985 | 093.574 |
| gamesvr3.0831.04.log | 105210760 | 25687 | 23336 | 090.848 |
| gamesvr3.0831.05.log | 104935556 | 25620 | 12325 | 048.107 |
| gamesvr3.0831.06.log | 105270020 | 25701 | 17420 | 067.779 |
| gamesvr3.0831.07.log | 105085266 | 25656 | 23922 | 093.241 |
| gamesvr3.0831.08.log | 50092509 | 12230 | 11285 | 092.273 |
| gamesvr3.error.0831.00.log | 563414 | 138 | 6 | 004.348 |
| gamesvr4.0831.00.log | 104876090 | 25605 | 23576 | 092.076 |
| gamesvr4.0831.01.log | 105038856 | 25645 | 22705 | 088.536 |
| gamesvr4.0831.02.log | 105311253 | 25711 | 23118 | 089.915 |
| gamesvr4.0831.03.log | 105305787 | 25710 | 24598 | 095.675 |
| gamesvr4.0831.04.log | 104948309 | 25623 | 24237 | 094.591 |
| gamesvr4.0831.05.log | 104858573 | 25601 | 24100 | 094.137 |
| gamesvr4.0831.06.log | 105359076 | 25723 | 24075 | 093.593 |
| gamesvr4.0831.07.log | 105010884 | 25638 | 23978 | 093.525 |
| gamesvr4.0831.08.log | 58704318 | 14333 | 13332 | 093.016 |
| gamesvr4.error.0831.00.log | 605733 | 148 | 11 | 007.432 |
| gatesvr.0831.00.log | 104982018 | 25631 | 802 | 003.129 |
| gatesvr.0831.01.log | 30392638 | 7421 | 395 | 005.323 |
| gatesvr.error.0831.00.log | 364959 | 90 | 4 | 004.444 |
| gmtool.0831.00.log | 1818 | 1 | 0 | 000.000 |
| gmtool.error.0831.00.log | 2 | 1 | 1 | 100.000 |
| sessionsvr.0831.00.log | 104899344 | 25611 | 3047 | 011.897 |
| sessionsvr.0831.01.log | 21431262 | 5233 | 1166 | 022.282 |
| sessionsvr.error.0831.00.log | 25675 | 7 | 1 | 014.286 |
|------------------------------+----------------+------------+-----------+---------|

可以看到大量的轮转过的日志文件,虽然没有再被打开使用,仍然被操作系统缓存了起来,百分比不等。

我们可以使用 linux 的清除 cache 命令来手动释放一下试试,使用 root 执行

1
2
3
$ sync
$ echo 3 > /proc/sys/vm/drop_caches
$ echo 0 > /proc/sys/vm/drop_caches # 恢复0

再查看内存使用情况

1
2
3
4
5
$ free -m
total used free shared buffers cached
Mem: 7870 2587 5282 0 2 62
-/+ buffers/cache: 2521 5348
Swap: 0 0 0

cache 的大量内存被释放了,再查看 pcstat 的统计结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
$ ~/pcstat `ls *.0831*.log`
|------------------------------+----------------+------------+-----------+---------|
| Name | Size | Pages | Cached | Percent |
|------------------------------+----------------+------------+-----------+---------|
| dbsvr.0831.00.log | 91415 | 23 | 0 | 000.000 |
| dbsvr.error.0831.00.log | 2 | 1 | 0 | 000.000 |
| gamesvr1.0831.00.log | 104861059 | 25601 | 0 | 000.000 |
| gamesvr1.0831.01.log | 104940405 | 25621 | 0 | 000.000 |
| gamesvr1.0831.02.log | 105522786 | 25763 | 0 | 000.000 |
| gamesvr1.0831.03.log | 105247528 | 25696 | 0 | 000.000 |
| gamesvr1.0831.04.log | 105221709 | 25689 | 0 | 000.000 |
| gamesvr1.0831.05.log | 105098602 | 25659 | 0 | 000.000 |
| gamesvr1.0831.06.log | 105151912 | 25672 | 0 | 000.000 |
| gamesvr1.0831.07.log | 104904682 | 25612 | 0 | 000.000 |
| gamesvr1.0831.08.log | 78897232 | 19263 | 0 | 000.000 |
| gamesvr1.error.0831.00.log | 600715 | 147 | 0 | 000.000 |
| gamesvr2.0831.00.log | 104963951 | 25626 | 0 | 000.000 |
| gamesvr2.0831.01.log | 104965184 | 25627 | 0 | 000.000 |
| gamesvr2.0831.02.log | 105106982 | 25661 | 0 | 000.000 |
| gamesvr2.0831.03.log | 105292165 | 25707 | 0 | 000.000 |
| gamesvr2.0831.04.log | 104927914 | 25618 | 0 | 000.000 |
| gamesvr2.0831.05.log | 105090378 | 25657 | 0 | 000.000 |
| gamesvr2.0831.06.log | 105175478 | 25678 | 0 | 000.000 |
| gamesvr2.0831.07.log | 104893356 | 25609 | 0 | 000.000 |
| gamesvr2.0831.08.log | 73241449 | 17882 | 0 | 000.000 |
| gamesvr2.error.0831.00.log | 618867 | 152 | 0 | 000.000 |
| gamesvr3.0831.00.log | 105143734 | 25670 | 0 | 000.000 |
| gamesvr3.0831.01.log | 104923026 | 25616 | 0 | 000.000 |
| gamesvr3.0831.02.log | 104971350 | 25628 | 0 | 000.000 |
| gamesvr3.0831.03.log | 104984690 | 25632 | 0 | 000.000 |
| gamesvr3.0831.04.log | 105210760 | 25687 | 0 | 000.000 |
| gamesvr3.0831.05.log | 104935556 | 25620 | 0 | 000.000 |
| gamesvr3.0831.06.log | 105270020 | 25701 | 0 | 000.000 |
| gamesvr3.0831.07.log | 105085266 | 25656 | 0 | 000.000 |
| gamesvr3.0831.08.log | 50092509 | 12230 | 0 | 000.000 |
| gamesvr3.error.0831.00.log | 563414 | 138 | 0 | 000.000 |
| gamesvr4.0831.00.log | 104876090 | 25605 | 0 | 000.000 |
| gamesvr4.0831.01.log | 105038856 | 25645 | 0 | 000.000 |
| gamesvr4.0831.02.log | 105311253 | 25711 | 0 | 000.000 |
| gamesvr4.0831.03.log | 105305787 | 25710 | 0 | 000.000 |
| gamesvr4.0831.04.log | 104948309 | 25623 | 0 | 000.000 |
| gamesvr4.0831.05.log | 104858573 | 25601 | 0 | 000.000 |
| gamesvr4.0831.06.log | 105359076 | 25723 | 0 | 000.000 |
| gamesvr4.0831.07.log | 105010884 | 25638 | 0 | 000.000 |
| gamesvr4.0831.08.log | 58704318 | 14333 | 0 | 000.000 |
| gamesvr4.error.0831.00.log | 605733 | 148 | 0 | 000.000 |
| gatesvr.0831.00.log | 104982018 | 25631 | 0 | 000.000 |
| gatesvr.0831.01.log | 30392638 | 7421 | 0 | 000.000 |
| gatesvr.error.0831.00.log | 364959 | 90 | 0 | 000.000 |
| gmtool.0831.00.log | 1818 | 1 | 0 | 000.000 |
| gmtool.error.0831.00.log | 2 | 1 | 0 | 000.000 |
| sessionsvr.0831.00.log | 104899344 | 25611 | 0 | 000.000 |
| sessionsvr.0831.01.log | 21431262 | 5233 | 0 | 000.000 |
| sessionsvr.error.0831.00.log | 25675 | 7 | 0 | 000.000 |
|------------------------------+----------------+------------+-----------+---------|

注意,这里只是通过清除命令展示一下 cache 前后的统计结果,生产环境在运行时,不要手动释放这些缓存,否则可能带来性能方面的问题,应该放心的由操作系统去实时他的策略。

参考资料

/proc/meminfo官方文档

谁吃了我的Linux内存?