性能优化-日志打印导致page-cache飙升问题解决

3,893

1.出现问题

昨天接收到了容器的监控告警,这个服务主要是用来进行接口开发对接使用的。平时流量是比较少的,所以使用的是2G内存限制的容器。

使用jinfo查看了jvm的启动参数为 ault VM flags: -XX:CICompilerCount=3 -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=1073741824 -XX:MaxNewSize=357564416 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=357564416 -XX:OldSize=716177408 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseParallelGC 

        查看了容器24小时的监控信息,容器实际使用内存情况如下可以看到,绿色曲线代表的实例的实际使用内存一直在飙升。

使用top命令查看了java进程的使用情况如下

使用top -H -p 命令查看了java进程下的线程使用情况如下

        一些监控信息查看下来,发现监控信息基本准确,容器内存限制为2G,服务进程使用大概1.3G, 服务实际却使用了2.3G多的内存,page-cache较大。

2.问题分析

2.1 JVM内分析

使用<jmap -histo:live 1 | head -10>命令查看如下,并没有发现大对象的存在

使用<jmap -dump:format=b,file=21_01_21.hprof 1>将堆栈信息dump下来,使用了mat工具来分析的结果如下,堆栈并没有什么大对象。看来问题不是出在jvm堆上。

2.2 Linux系统分析

使用<pmap -x 1 | sort -k 3 -n -r>查看进程的内存情况,看下是不是大神说的malloc函数导致的64M问题,结果显示并没有分配特别大的内存空间。

       使用<strace -f -e "brk,mmap,munmap,fork,clone" -p 1>命令查看下内存的开辟与回收的调用方法情况,依然没找到大内存分配的情况。

        目前来看对堆内外都没有泄漏或者大内存空间分配的情况发生。看来只能求助运维大佬,运维大佬建议使用<cat /proc/meminfo>查看具体内存耗费情况,可以看到用于文件读写的内存占用特别大,看来引起的变化因素主要是服务器的网络或磁盘的I/O吞吐飙高了。 

# cat /proc/meminfoMemTotal:       129778440 kB 内存总量
MemFree:         7533696 kB  空闲内存总量
MemAvailable:   52198264 kB  有效内存量
Buffers:          850716 kB  内存中写完的东西缓存起来,这样快速响应请求,后面数据再定期到硬盘上
Cached:         48735240 kB  内存中读完缓存起来内容占的大小
SwapCached:            0 kB  硬盘上交换分区大小
Active:         88164904 kB  活跃使用中的高速缓冲存储器页面文件大小
Inactive:       23182084 kB  不经常使用中的告诉缓冲存储器文件大小
Active(anon):   26384472 kB  活跃的匿名内存(进程中堆上分配的内存,是用malloc分配的内存)
Inactive(anon):     2672 kB  不活跃的匿名内存
Active(file):   61780432 kB  活跃的file内存
Inactive(file): 23179412 kB  不活跃的file内存  
……
Shmem:             22056 kB 已经被分配的共享内存大小
……
SReclaimable:    8194524 kB 可收回slab的大小

由于这个服务本身流量很小,所以排除了网络I/O带来的问题,基本可以确定是磁盘I/O带来的,那么可以肯定是由日志打印带来的磁盘I/O。使用<vmtouch /root/logs>查看,可以查看到目录下的文件内容有多少在内存中,这里看到日志文件读写占用的内存居然有900M,这里就可以看出来是日志文件的读写会使page cache飙升,不断占用容器的使用内存。

3.问题解决

       使用arthas命令<logger --name root --level error -c xxxxx>动态调整了实例的日志打印级别从info提升到了lerror来降低日志打印量。这样一关,瞬间容器实际使用内存和page_cache一下子就降下来了。

但是经过一个夜晚后,实际内存使用又飙升上去了,查看代码才知道rocketmq-client的日志被单独打印到其他地方了,这里还有另外一个现象就是容器的使用内存到某个时间点上又会往下降,通过查才发现这段时间恰巧就是的rocketmq-client日志文件rolling的时间,我们重新调整了日志文件打印的配置如下,后面使用的容器内存和page_cache都下降到正常水平。

4.问题复盘

4.1 page cache相关知识

        page cache,又称pcache,其中文名称为页高速缓冲存储器,简称页高缓。page cache的大 小为一页,通常为4K。在linux读写文件时,它用于缓存文件的逻辑内容,从而加快对磁盘上映像和数据的访问,所以通过page cache可以有效减少 I/O,提升应用的 I/O 速度,可通过/proc/meminfo、free 、/proc/vmstat等手段来监测。但是page cache占用的内存过高也会带来如服务器的 load 飙高,业务响应时延出现大的毛刺,业务平均访问时延明显增加等问题。

4.2  文件读写性能影响

       这个效果我在开发环境上测试了一番,结果是一样的,读写文件越大,使用内存增长越多。这跟我们日志频繁打印的场景非常类似,因为日志文件是累积的,所以消耗的内存会越来越大。

参考资料

www.jianshu.com/p/933c664c2… /proc/meminfo详解

www.cnblogs.com/coldplayere… vmtouch使用

blog.csdn.net/top\_explor… java测试page cache回写机制

www.freesion.com/article/551… 文件读写_性能测试_

blog.csdn.net/u012501054/… Linux内存详解