从一次线上OOM问题排查说起

问题描述

线上docker实例报错OOM然后自动重启，打到该实例的请求在重启期间报502。

配置

java应用启动项配置：

JAVA_OPTS=" $JAVA_OPTS -Dspring.profiles.active=product -Xms2048m -Xmx2048m -Xss1m -Xmn768m -XX:PermSize=256m -XX:MaxPermSize=512m -XX:SurvivorRatio=6 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=**   -Dfile.encoding=UTF-8   -XX:+PrintGCDateStamps  -XX:+PrintHeapAtGC  -Xloggc:/**/logs/gc.log"
# skywalking链路追踪
JAVA_OPTS=" $JAVA_OPTS -javaagent:/ ***/skywalking_agent/skywalking-agent.jar"
JAVA_OPTS=" $JAVA_OPTS -Dskywalking.logging.level=INFO"
 ## 省略一部分敏感信息

每个docker实例配置了4G内存双核CPU。

docker实例中运行的进程：java-app和logstash。

第一个java进程是业务应用，第二个是logstash

问题定位

0.排查的难点

当docker重启后，原有实例会被销毁，生成的heapdump文件以及其他信息都不能被保存，gc日志通过logstash发到kibana上但是OOM时的日志因重启不能被记录。

所以只能从集群中其他实例入手来查找问题的原因。

1. 排查堆上内存

当发现一台实例重启时，查看另外非重启实例的内存占用率在90%以上，自然地怀疑是java发生了堆内存泄漏。
但是查看gc日志，gc频率和每次的耗时都很正常。

top命令查看当前内存占用


top查看

java进程占用 2.84G，logstash0.8G。

从非重启实例上生成heap-dump文件，命令如下。

 jps   --查找进程号
 jmap -dump:format=b,file=heap-dump.bin [pid]    # 我的应用 pid = 443

使用eclipse提供的MAT工具进行分析，如图所示。


dump文件

堆上有可疑的泄漏信息：

  1. ConcurrentHashMap（46.6MB） 与Velocity模板相关
  2. LaunchedURLClassLoader（18.2MB） 与tomcat相关
  3. AutoLoadHandler（11MB）与AutoLoadCache（一个第三方缓存框架）相关。
ConcurrentHashMap

但是整个堆对象仅仅使用202m，远小于配置的堆的最大值 xmx=2g的上限。


对象数量和占用空间

再次确认堆上内存和GC信息。 jstat -gcutil 443 1000 10
在线上jstat打印gc的信息，确认各个区域占用比例。结果heap区域占用率确实不高。

jstat打印gc信息

因此可以排除是堆上的问题。暂时猜测是堆之外的问题了。

2. java应用的内存占用

在继续排查问题之前，先搞清楚一个java进程在linux中占用多少内存。


java8的内存占用

在容器中使用top命令查看的时候，java应用占用2.8G的物理内存（Res Rss）。

问题1：为什么系统进程占用的物理内存(Res/Rss)会远远大于设置的Xmx值呢？

这是因为在java8当中。

 java进程的内存  =  Heapsize + MetaSpace + OffHeap size  
 OffHeap size = 线程栈 + 缓冲区 + 库（* .jars）+ JVM代码本身组成
问题2：为什么xms=2g，但是java启动时内存占用少于2g？

这是因为操作系统为了让资源得到最大合理利用，在物理内存之上搞一层虚拟地址，同一台机器上每个进程可访问的虚拟地址空间大小都是一样的。
操作系统做了进程虚拟地址向物理内存的映射，开始时操作系统向java进程分配了少量的物理内存，当jvm需要更多物理内存，当前虚拟地址又没有映射到物理内存上的时候，就会发生缺页中断，由内核去为之准备一块物理内存，所以即使分配了2G堆内存，也只是虚拟内存。物理内存上不会立即有一块2G的空间与之对应。

问题3：那java进程的虚拟内存块到底映射了多少物理内存呢？

在linux下可以通过/proc/<pid>/smaps这个文件中看到，其中的Size表示虚拟内存大小，而Rss表示的是物理内存，所以从这层意义上来说和虚拟内存块对应的物理内存块不应该超过此虚拟内存块的空间范围。

通过执行命令cat /proc/443/smaps > smaps.txt得到smap.txt的输出文件。

00400000-00401000 r-xp 00000000 fd:5a 134087                             /home/work/jdk1.8.0_111/bin/java
Size:                  4 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Rss:                   4 kB
Pss:                   4 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         4 kB
Private_Dirty:         0 kB
Referenced:            4 kB
Anonymous:             0 kB
LazyFree:              0 kB
AnonHugePages:         0 kB
ShmemPmdMapped:        0 kB
Shared_Hugetlb:        0 kB
Private_Hugetlb:       0 kB
Swap:                  0 kB
SwapPss:               0 kB
Locked:                4 kB
VmFlags: rd ex mr mw me dw 
00600000-00601000 rw-p 00000000 fd:5a 134087                             /home/work/jdk1.8.0_111/bin/java
Size:                  4 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Rss:                   4 kB
Pss:                   4 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         0 kB
Private_Dirty:         4 kB
Referenced:            4 kB
Anonymous:             4 kB
LazyFree:              0 kB
AnonHugePages:         0 kB
ShmemPmdMapped:        0 kB
Shared_Hugetlb:        0 kB
Private_Hugetlb:       0 kB
Swap:                  0 kB
SwapPss:               0 kB
Locked:                4 kB
VmFlags: rd wr mr mw me dw ac 
0225c000-0227d000 rw-p 00000000 00:00 0                                  [heap]
Size:                132 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Rss:                  16 kB
Pss:                  16 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         0 kB
Private_Dirty:        16 kB
Referenced:           16 kB
Anonymous:            16 kB
LazyFree:              0 kB
AnonHugePages:         0 kB
ShmemPmdMapped:        0 kB
Shared_Hugetlb:        0 kB
Private_Hugetlb:       0 kB
Swap:                  0 kB
SwapPss:               0 kB
Locked:               16 kB
VmFlags: rd wr mr mw me ac 
80200000-e8900000 rw-p 00000000 00:00 0 
Size:            1711104 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Rss:               77824 kB
Pss:               77824 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         0 kB
Private_Dirty:     77824 kB
Referenced:        77824 kB
Anonymous:         77824 kB
LazyFree:              0 kB
AnonHugePages:     77824 kB
ShmemPmdMapped:        0 kB
Shared_Hugetlb:        0 kB
Private_Hugetlb:       0 kB
Swap:                  0 kB
SwapPss:               0 kB
Locked:            77824 kB
VmFlags: rd wr mr mw me ac 
e8900000-580100000 ---p 00000000 00:00 0 
Size:           19259392 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Rss:                   0 kB
Pss:                   0 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         0 kB
Private_Dirty:         0 kB
Referenced:            0 kB
Anonymous:             0 kB
LazyFree:              0 kB
AnonHugePages:         0 kB
ShmemPmdMapped:        0 kB
Shared_Hugetlb:        0 kB
Private_Hugetlb:       0 kB
Swap:                  0 kB
SwapPss:               0 kB
Locked:                0 kB
VmFlags: mr mw me nr 

……………………

7f42fc021000-7f4300000000 ---p 00000000 00:00 0 
Size:              65404 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Rss:                   0 kB
Pss:                   0 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         0 kB
Private_Dirty:         0 kB
Referenced:            0 kB
Anonymous:             0 kB
LazyFree:              0 kB
AnonHugePages:         0 kB
ShmemPmdMapped:        0 kB
Shared_Hugetlb:        0 kB
Private_Hugetlb:       0 kB
Swap:                  0 kB
SwapPss:               0 kB
Locked:                0 kB
VmFlags: mr mw me nr 

……………………

经过简单的脚本处理根据RSS值倒叙排序，得到了下图这样的文件。


导入到了excel（实际一千多行）

最大块的RSS占用是2158144KB，这块内存与堆空间大小相似。

3. 排查堆外内存

堆内存正常，那么继续来看堆外内存。

再贴一张 Arthas的截图


Arthas dashboard

metaspace = 82M

codeCache = 66M。

库（* .jars） = 没查到

JVM代码 = 没查到

那么剩余内存的开销就来自线程栈和缓冲区。

缓冲区

java的nio为了提高效率会使用DirectByteBuffer ，这部分内存直接申请系统内存。netty框架通过手动调用System.gc() 来释放内存。

该应用中使用了skywalking做调用链监控，其中用到了netty，因此有一部分缓冲区的使用。

线程栈

jvm的xss参数设置线程栈的大小，默认为1m。与堆内存申请类似，linux并不会直接分配1m的物理内存，会分配8k。

Linux实际物理内存映射。事实上linux对物理内存的使用非常的抠门，一开始只是分配了虚拟内存的线性区，并没有分配实际的物理内存，只有推到最后使用的时候才分配具体的物理内存，即所谓的请求调页。

命令jstack 443 > jstack-443-test.txt打印出当前应用活跃线程。


"ForkJoinPool.commonPool-worker-60" #8057 daemon prio=5 os_prio=0 tid=0x00007f4618119800 nid=0x28d2 waiting on condition [0x00007f4286aeb000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000826d9a90> (a java.util.concurrent.ForkJoinPool)
    at java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1824)
    at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1693)
    at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

"grpc-default-executor-706" #8050 daemon prio=5 os_prio=0 tid=0x00007f4670045800 nid=0x28c7 waiting on condition [0x00007f42848de000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000008027d960> (a java.util.concurrent.SynchronousQueue$TransferStack)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
    at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
    at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1066)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

………………………………


"grpc-default-worker-ELG-1-1" #29 daemon prio=5 os_prio=0 tid=0x00007f46c4033800 nid=0x269 runnable [0x00007f46f133e000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000802237d8> (a org.apache.skywalking.apm.dependencies.io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000000802237f0> (a java.util.Collections$UnmodifiableSet)
    - locked <0x0000000080223790> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at org.apache.skywalking.apm.dependencies.io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at org.apache.skywalking.apm.dependencies.io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:755)
    at org.apache.skywalking.apm.dependencies.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:410)
    at org.apache.skywalking.apm.dependencies.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
    at org.apache.skywalking.apm.dependencies.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:745)

"Service Thread" #28 daemon prio=9 os_prio=0 tid=0x00007f47ecbf3000 nid=0x267 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread14" #27 daemon prio=9 os_prio=0 tid=0x00007f47ecbef800 nid=0x266 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

其中线程标题中有虚拟内存地址，可以与smaps中的内存地址对应上。

问题解决：扩大容器内存

运维出于经验考虑扩大了容器内存，将原来4g内存加到6g。到目前为止，没有再次发生OOM使容器重启的情况。

对错误情况的猜测：

由于对线程内存开销估计的不足，
java进程+logstash进程会大于4g的情况。java应用的线程占用内存太高。

总结回顾

  1. MAT工具辅助堆上内存的分析
  2. Arthas查看各部分内存占用
  3. java进程内存占用的分析
  4. 线程栈内存占用
image.png
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 218,036评论 6赞 506
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 93,046评论 3赞 395
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 164,411评论 0赞 354
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 58,622评论 1赞 293
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 67,661评论 6赞 392
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 51,521评论 1赞 304
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 40,288评论 3赞 418
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 39,200评论 0赞 276
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 45,644评论 1赞 314
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,837评论 3赞 336
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,953评论 1赞 348
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 35,673评论 5赞 346
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 41,281评论 3赞 329
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,889评论 0赞 22
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 33,011评论 1赞 269
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 48,119评论 3赞 370
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 44,901评论 2赞 355