JAVA OOM 问题的定位

那天,我们的spark集群又出了幺蛾子,一条SQL导致了大面积的Executor OOM。

OOM 就是OutOfMemory,出现这个信息的后果通常都很严重。如果确实是内存不够倒也还罢了,通过配置参数调调内存也就好了。就怕是程序有bug,比如内存泄露之类,那就需要花点功夫去定位了。

幸运的是,Java是一门非常易用的语言,内存问题定位起来相对简单。下面我们就用这个问题,展示一下JAVA OOM问题的定位吧。

JVM 内存管理基础知识

我们先简单复习一下JVM的内存区域。

PC

即Program Counter Register。其实是非常小的一块区域。我们知道JVM是对计算机的一个虚拟,这里的PC就和计算机组成的PC是类似的概念,是当前线程执行的字节码的行号指示器。每线程私有。

PC是唯一没有规范OOM的区域。

JVM Stacks

也是线程私有的区域。每个方法执行的时候产生一个Stack Frame。熟悉C语言的同学应该很容易理解这个区域的作用。

Native Method Stacks

本地方法栈,和前面JVM stack的区别是本地方法栈是为JVM使用的Native方法服务的。

Java Heap

Heap是JVM虚存管理的大头,也是OOM最多发之地。这个区域就是用来存放对象实例的。

这个区域是各线程共享的。

Method Area

方法区,用于存储已被虚拟机加载的类信息,常量,静态变量,JIT编译后的代码。

也是各线程共享的。

运行时常量池(Runtime Constant Pool)也是方法区的一部分。

堆外内存

因为效率(包括使用效率和运行效率)的关系,应用程序会有自己直接从DirectBuffer申请内存的需求。

堆外内存最特殊的地方在于它是你的Java程序申请的内存,却不被JVM管理。普通Java程序员大概是懒得去趟这浑水的。

定位堆外内存的问题就是本文之外的话题了,可能就要借助像google-pertool这样的工具。

Heap的再划分

本次遇到的Spark OOM是一个Heap OOM的例子,我们的重点还是看Heap的内存情况。

Heap是GC的主要区域,所以也叫Garbage Collected Heap。

主流的GC方法都是分代收集算法,基本思想就是把对象按生命周期划分到不同的区块,比如Young Generation,Old Generation和Perm Generation。Young的区块还可以再细分为Eden,From,To等小区块。

对象先在Eden区放置,当Young 内存不够的时候进行Minor的GC,对Young区的对象进行整理,该搜集的搜集,还存活的往Old去丢。

与之对应是Major GC,即Old区的整理。

程序员最怕的就是Full GC,需要同时整理Young和Old,所谓Stop the World,所有线程都被冰封了,对系统性能影响极大。

浅显的基础知识列完,下面说说这个问题的具体定位步骤吧。

第一步:观察dump文件

如果你的java程序启动参数中加了-XX:+HeapDumpOnOutOfMemoryError,就会在OOM时产生一个dump文件。我们可以从这个文件分析出一些内存使用情况。

我们使用jhat工具来分析。这个工具会打开dump文件,解析信息,并打开web server端口,允许你以web方式访问浏览。

执行之后如下显示就是成功了:

[dtdream@btson ~]$ jhat executor.hprof 
Reading from executor.hprof...
Dump file created Wed Jul 27 19:32:10 CST 2016
Snapshot read, resolving...
Resolving 1045245 objects...
Chasing references, expect 209 dots.................................................................................................................................................................................................................
Eliminating duplicate references.................................................................................................................................................................................................................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

很可惜,这次产生的dump文件没有什么明显占用内存太多的对象信息。这导致我出现了定位的方向错误:我误以为是堆外内存使用有问题,还好后来分析相关代码排除了这个可能性。

分析死亡现场没有可用的信息,我决定复现问题,实时去抓到可疑的对象。

第二步:复现问题

使用jmap观察jvm

我们先通过输入jmap -heap,接上进程的PID,就可以查看到正常运行时的java进程的Heap信息。因为不适合在生产环境去复现、解决这个问题,所以这里我们看到的是一个比较小的Spark进程来模拟。

[dtdream@btson sbin]$ jmap -heap 27107
Attaching to process ID 27107, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.79-b02

using thread-local object allocation.
Parallel GC with 8 thread(s)

Heap Configuration:
   MinHeapFreeRatio = 0
   MaxHeapFreeRatio = 100
   MaxHeapSize      = 1073741824 (1024.0MB)
   NewSize          = 1310720 (1.25MB)
   MaxNewSize       = 17592186044415 MB
   OldSize          = 5439488 (5.1875MB)
   NewRatio         = 2
   SurvivorRatio    = 8
   PermSize         = 21757952 (20.75MB)
   MaxPermSize      = 268435456 (256.0MB)
   G1HeapRegionSize = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 329777152 (314.5MB)
   used     = 96467848 (91.99890899658203MB)
   free     = 233309304 (222.50109100341797MB)
   29.252435293030853% used
From Space:
   capacity = 13631488 (13.0MB)
   used     = 0 (0.0MB)
   free     = 13631488 (13.0MB)
   0.0% used
To Space:
   capacity = 12582912 (12.0MB)
   used     = 0 (0.0MB)
   free     = 12582912 (12.0MB)
   0.0% used
PS Old Generation
   capacity = 716177408 (683.0MB)
   used     = 44330880 (42.2772216796875MB)
   free     = 671846528 (640.7227783203125MB)
   6.189929967743411% used
PS Perm Generation
   capacity = 149422080 (142.5MB)
   used     = 149376824 (142.45684051513672MB)
   free     = 45256 (0.04315948486328125MB)
   99.9697126422012% used

28136 interned Strings occupying 3045568 bytes.

动态观察,确认复现

使用jmap查看倒也没有看到什么可疑信息。

我们需要的是能够动态观察复现过程中的异动,所以要推介一下jstat这个命令,它可以按照给定频率和次数打印内存信息的统计。

简单说一下各列的信息:

  • S0 Heap上的 Survivor space 0 段已使用空间的百分比
  • S1 Heap上的 Survivor space 1 段已使用空间的百分比
  • E Eden的使用百分比
  • O Old的使用百分比
  • P Perm的使用百分比
  • YGC Young GC的次数
  • YGCT Young GC的耗时
  • FGC Full GC的次数
  • FGCT Full GC的耗时
  • GCT 总共的GC耗时

观察进程27865, 按照200ms的频率,打印500次:

[dtdream@btson ~]$ jstat -gcutil 27865 500 200
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
 99.99   0.00  48.97   1.47  99.76      4    0.238     0    0.000    0.238
 99.99   0.00  48.97   1.47  99.76      4    0.238     0    0.000    0.238
 99.99   0.00  48.97   1.47  99.76      4    0.238     0    0.000    0.238
 99.99   0.00  48.97   1.47  99.76      4    0.238     0    0.000    0.238
 99.99   0.00  48.97   1.47  99.76      4    0.238     0    0.000    0.238
 99.99   0.00  48.97   1.47  99.76      4    0.238     0    0.000    0.238
 99.99   0.00  50.41   1.47  99.78      4    0.238     0    0.000    0.238
 99.99   0.00  68.56   1.47  99.97      4    0.238     0    0.000    0.238
 99.99   0.00  74.20   1.47  99.78      4    0.238     0    0.000    0.238
 .....

幸运的是这个问题很容易出现,我稍微做了点操作上的调整,找到一个临界点,在问题发生时,我们能看到连续的、迅猛的内存增长和反复的FullGC而不至于立刻因为OOM死去。

  0.00   0.00  97.25  51.36  99.85     44    2.084    50   14.282   16.366
  0.00   0.00  98.74  96.60  99.85     44    2.084    51   14.282   16.366
  0.00   0.00  98.15  96.67  99.86     44    2.084    51   14.512   16.596
  0.00   0.00  98.15  96.67  99.86     44    2.084    52   14.512   16.596
  0.00   0.00   0.00  51.36  99.86     44    2.084    52   14.902   16.986
  0.00   0.00  98.95  96.60  99.86     44    2.084    53   14.902   16.986
  0.00   0.00  98.95  96.60  99.86     44    2.084    53   14.902   16.986
  0.00   0.00  98.63  96.60  99.86     44    2.084    54   15.252   17.336
  0.00   0.00  97.02  51.42  99.86     44    2.084    54   15.491   17.574
  0.00   0.00  98.07  96.66  99.87     44    2.084    55   15.491   17.574
  0.00   0.00  98.07  96.66  99.87     44    2.084    55   15.491   17.574
  0.00   0.00  98.16  96.61  99.87     44    2.084    56   15.852   17.935
  0.00   0.00  98.16  96.61  99.87     44    2.084    56   15.852   17.935
  0.00   0.00  98.18  96.61  99.87     44    2.084    57   16.230   18.314
  0.00   0.00  98.18  96.61  99.87     44    2.084    57   16.230   18.314
  0.00   0.00  97.58  96.61  99.87     44    2.084    57   16.620   18.704
  0.00   0.00  98.51  96.61  99.88     44    2.084    58   16.620   18.704
  0.00   0.00  98.16  96.67  99.88     44    2.084    59   16.837   18.921
  0.00   0.00  98.16  96.67  99.88     44    2.084    59   16.837   18.921
  0.00   0.00  98.07  96.61  99.88     44    2.084    60   17.203   19.287
  0.00   0.00  98.07  96.61  99.88     44    2.084    60   17.203   19.287
  0.00   0.00  98.06  96.61  99.88     44    2.084    61   17.559   19.642
  0.00   0.00  98.06  96.61  99.88     44    2.084    61   17.559   19.642
  0.00   0.00  97.54  96.61  99.88     44    2.084    61   17.922   20.005
  0.00   0.00  98.50  96.61  99.89     44    2.084    62   17.922   20.005
  0.00   0.00  98.23  96.66  99.89     44    2.084    63   18.173   20.257

第三步:实时产生dump文件,再次分析

在问题出现时输入jmap -dump 命令得到实时的dump文件:

jmap -dump:file=/home/dtdream/executor.hprof 27865  
jhat executor.hprof

再继续进行分析。

登录Web后

这次得到的dump文件大小就和实际设置的JVM内存比较吻合了。 我们从jhat的信息里也顺利地看到了我们想要的。

从申请记录里找到了大的对象,类型是Object,占用了1G多内存

Object有很多,这是其中比较大的,也就是我们想抓到的,一个Object的大Array:

还可以继续定位到这Array中具体的内容,这里我们遇到的全是null。

接下来的问题就是继续分析这个巨大的Object数组是怎么来的。结合具体操作和现象看,这个地方是反复申请释放了这个大数组。本问题因为是Object而不是一个具体的class类型,对定位不是特别有帮助。具体能不能很快定位问题,就看你对问题产生的流程的熟悉程度了。

其他分析工具

Jhat 的功能相对还是比较简单,我用它是因为够方便。一些工具的功能更加强大,遇到问题可以尝试使用。比如:

  • VisualVM
  • Eclipse Memory Analyzer
  • IBM HeapAnalyzer

总结

本文通过一个实际的Spark内存问题(这个问题本身有机会再写一篇分析吧),简单展示了一系列优秀的命令行工具来分析定位问题。希望对你有所帮助。



最后更新: 2016-07-26 16:01