性能文章>使用google perf工具来排查堆外内存占用>

使用google perf工具来排查堆外内存占用原创

https://a.perfma.net/img/2959233
9月前
434703

作者:KL
原文链接:https://qsli.github.io/2017/12/02/google-perf-tools/
转载已获授权

现象

线上机器内存不足,经常被系统oom killer干掉。

如果tomcat运行的好好的,突然被干掉了,没有任何线索,那么就可以使用下面的命令看看是不是oom killer搞的鬼。

sudo dmesg | grep -i kill | less

Out of memory: Kill process 23195 (java) score 558 or sacrifice child
Killed process 23195, UID 40001, (java) total-vm:81176732kB, anon-rss:64507900kB, file-rss:2604kB

其中anon-rss是程序占用的物理内存, 64507900kB = 61.519527435302734 GB
系统总的内存也才62GB,linux发现没有可分配的内存,就会启用oom killer的机制,根据oom_score_adj的值去干掉相应的进程了。

系统上oom_score_adj的值

43722 total pagecache pages
4335 pages in swap cache
Swap cache stats: add 1009840, delete 1005505, find 76432470/76485037
Free swap  = 49990420kB
Total swap = 50331644kB
16777215 pages RAM
282254 pages reserved
36481 pages shared
16386140 pages non-shared
[ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
[ 1419]     0  1419     2883       94  18     -17         -1000 udevd
[ 2894]     0  2894     2660      105   6     -17         -1000 udevd
[ 2895]     0  2895     2882       43   2     -17         -1000 udevd
[  388]     0   388    16557       63  12     -17         -1000 sshd
[ 1340]     0  1340   152806     9114   6       0             0 salt-minion
[ 1341]     0  1341   110173     5224  22       0             0 salt-minion
[14168]     0 14168     6899      149   6     -17         -1000 auditd

tomcat的进程占用内存最多,得分也最高 —— 558

tomcat的配置

 -Xms44g -Xmx44g -server \
-XX:+UseG1GC -XX:MaxGCPauseMillis=200 \
-XX:InitiatingHeapOccupancyPercent=65 -XX:SurvivorRatio=8 \
-XX:MaxTenuringThreshold=15 \
-verbosegc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps \
-XX:+PrintTenuringDistribution -XX:+PrintAdaptiveSizePolicy \
-XX:-TraceClassUnloading \
-XX:+DisableExplicitGC

jvm最大的堆只有44GB, 但是从上面的日志中看到实际占用的内存达到了62GB,几乎把整个系统的内存都吃掉了。

既然堆内没有问题,问题自然应该出在堆外内存的占用上。

java 堆外内存

JVM源码分析之堆外内存完全解读-你假笨中说道:

对于System.gc的实现,之前写了一篇文章来重点介绍,JVM源码分析之SystemGC完全解读,它会对新生代的老生代都会进行内存回收,这样会比较彻底地回收DirectByteBuffer对象以及他们关联的堆外内存,我们dump内存发现DirectByteBuffer对象本身其实是很小的,但是它后面可能关联了一个非常大的堆外内存,因此我们通常称之为『冰山对象』,我们做ygc的时候会将新生代里的不可达的DirectByteBuffer对象及其堆外内存回收了,但是无法对old里的DirectByteBuffer对象及其堆外内存进行回收,这也是我们通常碰到的最大的问题,如果有大量的DirectByteBuffer对象移到了old,但是又一直没有做cms gc或者full gc,而只进行ygc,那么我们的物理内存可能被慢慢耗光,但是我们还不知道发生了什么,因为heap明明剩余的内存还很多(前提是我们禁用了System.gc)。

白衣大侠也建议:

这时,就只能靠前面提到的申请额度超限时触发的system.gc()来救场了。但这道最后的保险其实也不很好,首先它会中断整个进程,然后它让当前线程睡了整整一百毫秒,而且如果gc没在一百毫秒内完成,它仍然会无情的抛出OOM异常。还有,万一,万一大家迷信某个调优指南设置了-DisableExplicitGC禁止了system.gc(),那就不好玩了。
所以,堆外内存还是自己主动点回收更好,比如Netty就是这么做的。

限制堆外内存的大小

加上-XX:MaxDirectMemorySize=4g, 去除-XX:+DisableExplicitG观察了几天,发现并不能解决问题,于是继续使用google perf tools去观察下堆外内存的使用

google perf tools

下载地址

原理

该工具主要利用了unix的一个环境变量LD_PRELOAD,它允许你要加载的动态库优先加载起来,相当于一个Hook了,
于是可以针对同一个函数可以选择不同的动态库里的实现了,比如googleperftools就是将malloc方法替换成了tcmalloc的实现,这样就可以跟踪内存分配路径了

使用

tomcat的启动变量中加入下面的配置

export LD_PRELOAD=/usr/local/lib/libtcmalloc.so
export HEAPPROFILE=/home/q/perf-result/
export HEAP_PROFILE_ALLOCATION_INTERVAL=2000000000

HEAPPROFILE是存放结果的地址

HEAP_PROFILE_ALLOCATION_INTERVAL default: 1073741824 (1 Gb) Dump heap profiling information once every specified number of bytes has been allocated by the program.

查看运行中的日志:

Dumping heap profile to /home/q/perf-result/_23207.0927.heap (1755151 MB allocated cumulatively, 1267 MB currently in use)

日志中会显示累计的对外内存的分配和当前使用的堆外内存的大小。

分析结果

文本形式的
命令:

/usr/local/bin/pprof --text /home/q/java/default/bin/java _23207.0035.heap

输出结果如下:

Using local file /home/q/java/default/bin/java.
Using local file _23207.1012.heap.
Total: 1283.1 MB

     0.0   0.0% 100.0%     39.5   3.1% PtrQueue::enqueue_known_active
     0.0   0.0% 100.0%     39.5   3.1% PtrQueueSet::allocate_buffer
     0.0   0.0% 100.0%     42.2   3.3% G1ParTask::work
     0.0   0.0% 100.0%     42.2   3.3% GangWorker::loop
     0.0   0.0% 100.0%     75.6   5.9% ObjArrayKlass::oop_oop_iterate_nv_m@8fbe80
     0.0   0.0% 100.0%    146.2  11.4% 0x00007f63bf0e5825
     0.0   0.0% 100.0%    146.2  11.4% JVM_InternString
     0.0   0.0% 100.0%    146.2  11.4% StringTable::intern@a24ca0
     0.0   0.0% 100.0%    147.2  11.5% StringTable::basic_add
     0.0   0.0% 100.0%    147.3  11.5% StringTable::intern@a24780
     0.0   0.0% 100.0%    152.4  11.9% Hashtable::new_entry
     0.0   0.0% 100.0%    170.5  13.3% AllocateHeap
     0.0   0.0% 100.0%    256.0  20.0% ConcurrentMark::ConcurrentMark
     0.0   0.0% 100.0%    265.5  20.7% InstanceKlass::oop_oop_iterate_nv
     0.0   0.0% 100.0%    287.2  22.4% G1CollectedHeap::initialize
     0.0   0.0% 100.0%    305.4  23.8% Universe::initialize_heap
     0.0   0.0% 100.0%    306.3  23.9% universe_init
     0.0   0.0% 100.0%    307.0  23.9% init_globals
     0.0   0.0% 100.0%    307.1  23.9% JNI_CreateJavaVM
     0.0   0.0% 100.0%    307.1  23.9% Threads::create_vm
     0.0   0.0% 100.0%    307.2  23.9% JavaMain
     0.0   0.0% 100.0%    326.5  25.4% ConcurrentG1RefineThread::run
     0.0   0.0% 100.0%    326.5  25.4% RefineCardTableEntryClosure::do_card_ptr
     0.0   0.0% 100.0%    329.8  25.7% 0x00007f63bfae74a7
     0.0   0.0% 100.0%    348.5  27.2% DirtyCardQueueSet::apply_closure_to_completed_buffer
     0.0   0.0% 100.0%    349.7  27.3% G1RemSet::refine_card
     0.0   0.0% 100.0%    349.7  27.3% HeapRegion::oops_on_card_seq_iterate_careful
     0.0   0.0% 100.0%    349.7  27.3% OtherRegionsTable::add_reference
     0.0   0.0% 100.0%    351.0  27.4% os::malloc@913e80
     0.0   0.0% 100.0%    351.0  27.4% Unsafe_AllocateMemory
     0.0   0.0% 100.0%    408.4  31.8% java_start
     0.0   0.0% 100.0%    562.6  43.8% BitMap::resize
     0.0   0.0% 100.0%    598.5  46.6% ArrayAllocator::allocate
     0.0   0.0% 100.0%    715.5  55.8% __clone
     0.0   0.0% 100.0%    715.5  55.8% start_thread
  1277.3  99.5%  99.5%   1277.3  99.5% os::malloc@9137e0

结果代表的含义:

Analyzing Text Output

Text mode has lines of output that look like this:

       14   2.1%  17.2%       58   8.7% std::_Rb_tree::find
Here is how to interpret the columns:

1. Number of profiling samples in this function
2. Percentage of profiling samples in this function
3. Percentage of profiling samples in the functions printed so far
4. Number of profiling samples in this function and its callees
5. Percentage of profiling samples in this function and its callees
6. Function name

Gperftools CPU Profiler中有更加详细的说明

pdf形式的结果
相比文字的结果,图片形式的调用关系,更加清楚和直观。

命令如下:

sudo yum install ghostscript
sudo yum install dot
sudo yum install graphviz -y
sudo pprof --pdf  /home/q/java/default/bin/java _19877.19793.heap > result.pdf

结果:
result.pdf

可能的原因

从google perf tools的结果来看主要的堆外内存来自

0x00007f52e05126a5
0.0 (0.0%)
of 7089.3 (82.5%)

这个再往上就没有地址了。

heap 占用

查看出问题机器的heap占用情况如下

jmap -histo:live `pgrep -f 'tomcat'`

 num     #instances         #bytes  class name

----------------------------------------------

   1:      15272979      940261992  [C

   2:      19182959      767318360  java.util.ArrayList

   3:      15397474      739078752  qunar.tc.plato.zeno.util.collections.offheap.map.OffHeapHashMap

   4:      13281544      637514112  java.util.concurrent.ConcurrentHashMap$Node

   5:      10136730      612997544  [Ljava.lang.Object;

   6:      15265576      488498432  java.lang.String

   7:       4694324      413100512  _plato.com.qunar.hotel.price.data.center.plato.beans.shotel.IMetaSHotelBizInfo

   8:           854      379525944  [Ljava.util.concurrent.ConcurrentHashMap$Node;

   9:      15397474      369539376  qunar.tc.plato.zeno.util.collections.offheap.set.OffHeapHashSet

  10:       4694324      337991328  _plato.com.qunar.hotel.price.data.center.plato.beans.shotel.IMetaContactConfig

前面的都是去哪儿自己开发的堆外缓存占用的对象,缓存的内容也多是酒店相关的元数据。结合工具的结果,推测问题出在堆外缓存。
堆外缓存采用的是内存映射的方式,大量使用了DirectByteBuffer这种冰山对象。

疑点

这个系统目前处于重构阶段,之前也是使用的堆外缓存,并没有出现问题。不过,目前在逐渐下掉堆外缓存的使用,到时候可以再看看是否出问题。

杂谈

使用pmap查看进程的内存映射

sudo -u tomcat pmap -x  25147 | less

Address           Kbytes     RSS   Dirty Mode   Mapping
0000000000400000       4       0       0 r-x--  java
0000000000600000       4       4       4 rw---  java
0000000001d3f000    1484    1224    1224 rw---    [ anon ]
0000003e0a400000     128     112       0 r-x--  ld-2.12.so
0000003e0a61f000       4       4       4 r----  ld-2.12.so
0000003e0a620000       4       4       4 rw---  ld-2.12.so
0000003e0a621000       4       4       4 rw---    [ anon ]
0000003e0a800000       8       8       0 r-x--  libdl-2.12.so
0000003e0a802000    2048       0       0 -----  libdl-2.12.so
0000003e0aa02000       4       4       4 r----  libdl-2.12.so
0000003e0aa03000       4       4       4 rw---  libdl-2.12.so
0000003e0ac00000    1576     680       0 r-x--  libc-2.12.so
0000003e0ad8a000    2048       0       0 -----  libc-2.12.so
0000003e0af8a000      16      16       8 r----  libc-2.12.so
0000003e0af8e000       4       4       4 rw---  libc-2.12.so
0000003e0af8f000      20      20      20 rw---    [ anon ]
0000003e0b000000      92      72       0 r-x--  libpthread-2.12.so
0000003e0b017000    2048       0       0 -----  libpthread-2.12.so
0000003e0b217000       4       4       4 r----  libpthread-2.12.so
0000003e0b218000       4       4       4 rw---  libpthread-2.12.so
0000003e0b219000      16       4       4 rw---    [ anon ]

将内存块的内容dump成文件(慎重,会影响服务)

sudo  gdb --batch --pid 25147 -ex " dump memory /home/qisheng.li/c.dump 0x00007eefcc000000 0x00007eefcf000000"

查看文件的内容:

[qisheng.li@xxx.h.cn2 ~]$ view c.dump

这个dump是我在2017年 09月 05日 星期二 01:34:24 CST做的,但是内容看起来是tomcat respone的内容,奇怪的是内容的时间是2017 17:38:18 GMT,不知道是什么原因导致的,如果你知道,烦请告知。

直接查看堆外的内存块,无疑是最快排查堆外占用的方法,但是内存块的选择非常依赖经验, 我尝试了下,并没有找到问题。

参考5中的大神,通过dump内存块,发现是netty使用的directBuffer分配的大量64M的内存块。

JDK8中的 Native Memory Tracker

在启动参数中开启:

-XX:NativeMemoryTracking=[off | summary | detail]

也可以在jvm退出的时候,打印相关的统计信息

NMT at VM Exit
Use the following VM diagnostic command line option to obtain last memory usage data at VM exit when Native Memory Tracking is enabled. The level of detail is based on tracking level.

-XX:+UnlockDiagnosticVMOptions -XX:+PrintNMTStatistics

在程序运行时可以使用jcmd查看内存的分配情况

jcmd <pid> VM.native_memory [summary | detail | baseline | summary.diff | detail.diff | shutdown] [scale= KB | MB | GB]

输出的结果:

sudo -u tomcat jcmd `pgrep -f tomcat` VM.native_memory detail
31549:

Native Memory Tracking:

Total: reserved=50215227KB, committed=49947839KB
-                 Java Heap (reserved=46137344KB, committed=46137344KB)
                            (mmap: reserved=46137344KB, committed=46137344KB) 
 
-                     Class (reserved=92639KB, committed=91707KB)
                            (classes #14958)
                            (malloc=2527KB #50184) 
                            (mmap: reserved=90112KB, committed=89180KB) 
 
-                    Thread (reserved=914804KB, committed=914804KB)
                            (thread #883)
                            (stack: reserved=906696KB, committed=906696KB)
                            (malloc=2904KB #4435) 
                            (arena=5203KB #1764)
 
-                      Code (reserved=263567KB, committed=87223KB)
                            (malloc=13967KB #19565) 
                            (mmap: reserved=249600KB, committed=73256KB) 
 
-                        GC (reserved=1849937KB, committed=1849937KB)
                            (malloc=105041KB #121050) 
                            (mmap: reserved=1744896KB, committed=1744896KB) 
 
-                  Compiler (reserved=13354KB, committed=13354KB)
                            (malloc=3061KB #3484) 
                            (arena=10292KB #13)
 
-                  Internal (reserved=813935KB, committed=813935KB)
                            (malloc=813903KB #102254) 
                            (mmap: reserved=32KB, committed=32KB) 
 
-                    Symbol (reserved=18071KB, committed=18071KB)
                            (malloc=14355KB #138545) 
                            (arena=3716KB #1)
 
-    Native Memory Tracking (reserved=7274KB, committed=7274KB)
                            (malloc=298KB #4295) 
                            (tracking overhead=6976KB)
 
-               Arena Chunk (reserved=14191KB, committed=14191KB)
                            (malloc=14191KB) 
 
-                   Unknown (reserved=90112KB, committed=0KB)
                            (mmap: reserved=90112KB, committed=0KB) 
 
Virtual memory map:
 
[0x00007ef481693000 - 0x00007ef481794000] reserved and committed 1028KB for Thread Stack from
    [0x00007f0486546f74] JavaThread::run()+0x24
    [0x00007f04863fab88] java_start(Thread*)+0x108
 
[0x00007ef481794000 - 0x00007ef481895000] reserved and committed 1028KB for Thread Stack from
    [0x00007f0486546f74] JavaThread::run()+0x24
    [0x00007f04863fab88] java_start(Thread*)+0x108
 
[0x00007ef48224d000 - 0x00007ef48244d000] reserved 2048KB for Class from
    [0x00007f0486593c66] ReservedSpace::initialize(unsigned long, unsigned long, bool, char*, unsigned long, bool)+0x256
    [0x00007f0486593d0b] ReservedSpace::ReservedSpace(unsigned long, unsigned long, bool, char*, unsigned long)+0x1b
    [0x00007f0486379cda] VirtualSpaceNode::VirtualSpaceNode(unsigned long)+0x17a
    [0x00007f048637a59a] VirtualSpaceList::create_new_virtual_space(unsigned long)+0x5a

	[0x00007ef48228d000 - 0x00007ef4823cd000] committed 1280KB from
            [0x00007f0486593549] VirtualSpace::expand_by(unsigned long, bool)+0x199
            [0x00007f0486377936] VirtualSpaceList::expand_node_by(VirtualSpaceNode*, unsigned long, unsigned long)+0x76
            [0x00007f048637a750] VirtualSpaceList::expand_by(unsigned long, unsigned long)+0xf0
            [0x00007f048637a8e3] VirtualSpaceList::get_new_chunk(unsigned long, unsigned long, unsigned long)+0xb3

	[0x00007ef48224d000 - 0x00007ef48228d000] committed 256KB from
            [0x00007f0486593549] VirtualSpace::expand_by(unsigned long, bool)+0x199
            [0x00007f0486377936] VirtualSpaceList::expand_node_by(VirtualSpaceNode*, unsigned long, unsigned long)+0x76
            [0x00007f048637a8e3] VirtualSpaceList::get_new_chunk(unsigned long, unsigned long, unsigned long)+0xb3
            [0x00007f048637c432] SpaceManager::grow_and_allocate(unsigned long)+0x2d2

memorymapping.jpeg
如果通过上述的映射关系能直接找到系统的StringTable等对应的分区,dump内存下来应该能很快的发现问题,不知道行不行得通。

请先登录,再评论

暂无回复,快来写下第一个回复吧~

为你推荐

不起眼,但是足以让你有收获的JVM内存分析案例
分析 这个问题说白了,就是说有些int[]对象不知道是哪里来的,于是我拿他的例子跑了跑,好像还真有这么回事。点该 dump 文件详情,查看相关的 int[] 数组,点该对象的“被引用对象”,发现所
从一起GC血案谈到反射原理
前言 首先回答一下提问者的问题。这主要是由于存在大量反射而产生的临时类加载器和 ASM 临时生成的类,这些类会被保留在 Metaspace,一旦 Metaspace 即将满的时候,就会触发 Fu
关于内存溢出,咱再聊点有意思的?
概述 上篇文章讲了JVM在GC上的一个设计缺陷,揪出一个导致GC慢慢变长的JVM设计缺陷,可能有不少人还是没怎么看明白的,今天准备讲的大家应该都很容易看明白 本文其实很犹豫写不写,因为感觉没有
协助美团kafka团队定位到的一个JVM Crash问题
概述 有挺长一段时间没写技术文章了,正好这两天美团kafka团队有位小伙伴加了我微信,然后咨询了一个JVM crash的问题,大家对crash的问题都比较无奈,因为没有现场,信息量不多,碰到这类问题我
又发现一个导致JVM物理内存消耗大的Bug(已提交Patch)
概述 最近我们公司在帮一个客户查一个JVM的问题(JDK1.8.0_191-b12),发现一个系统老是被OS Kill掉,是内存泄露导致的。在查的过程中,阴差阳错地发现了JVM另外的一个Bug。这个B
JVM实战:优化我的IDEA GC
IDEA是个好东西,可以说是地球上最好的Java开发工具,但是偶尔也会卡顿,仔细想想IDEA也是Java开发的,会不会和GC有关,于是就有了接下来对IDEA的GC进行调优 IDEA默认JVM参数: -
不起眼,但是足以让你收获的JVM内存案例
今天的这个案例我觉得应该会让你涨姿势吧,不管你对JVM有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得