一个神奇的 bug:OOM?优雅终止线程?系统内存占用较高?
摘要:该项目是DAYU平台的数据开发(DLF),数据开发中一个重要的功能就是ETL(数据清洗)。ETL由源端到目的端,中间的业务逻辑一般由用户自己编写的SQL模板实现,velocity是其中涉及的一种模板语言。
Velocity之OOM
Velocity的基本使用
Velocity模板语言的基本使用代码如下:
1. 初始化模板引擎
2. 获取模板文件
3. 设置变量
4. 输出
在ETL业务中,Velocity模板的输出是用户的ETL SQL语句集,相当于.sql文件。这里官方提供的api需要传入一个java.io.Writer类的对象用于存储模板的生成的SQL语句集。然后,这些语句集会根据我们的业务做SQL语句的拆分,逐个执行。
java.io.Writer类是一个抽象类,在JDK1.8中有多种实现,包括但不仅限于以下几种:
![](https://static001.geekbang.org/infoq/8a/8a9fdd615151b22e0b8037bcdce38955.png)
由于云环境对用户文件读写创建等权限的安全性要求比较苛刻,因此,我们使用了java.io.StringWriter,其底层是StringBuffer对象,StringBuffer底层是char数组。
简单模板Hellovelocity.vm:
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
HelloVelocity.java
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
控制台输出
![](https://static001.geekbang.org/infoq/a3/a331164a3364fa745181bc11d97f6df8.png)
OOM重现
大模板文件BigVelocity.template.vm
(文件字数超出博客限制,稍后在附件中给出~~)
模板文件本身就379kb不算大,关键在于其中定义了一个包含90000多个元素的String数组,数组的每个元素都是”1”,然后写了79层嵌套循环,循环的每一层都是遍历该String数组;最内层循环调用了一次:
这意味着这个模板将生成包含96372的79次方个SQL语句,其中每一个SQL语句都是:
将如此巨大的字符量填充进StringWriter对象里面,至少需要10的380多次方GB的内存空间,这几乎是不现实的。因此OOM溢出是必然的。
BigVelocity.java
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
控制台输出
![](https://static001.geekbang.org/infoq/28/2822f32e77fc37d61552efbe54f55704.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
OOM原因分析
Velocity模板生成的结果写入StringWriter对象中,如前面分析,其底层是一个char数组。直接产生OOM的代码在于java.util.Array.copyOf()函数:
![](https://static001.geekbang.org/infoq/f5/f5f42657e0d6405b55ba16535f578809.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
StringWriter底层char数组容量极限测试
StringWriterOOMTest.java
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
Jvm参数设置(参考硬件配置)
环境:JDK8 + Windows10台式机 + 32GB内存 + 1TB SSD + i7-8700
如果你的硬件配置不充分,请勿轻易尝试!
![](https://static001.geekbang.org/infoq/8c/8c5ccb936101e45af4214e1186f2874e.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
测试结果
StringWriterOOMTest运行时的整个进程内存大小在Windows任务管理器中达10300多MB时,程序停止。
控制台输出
![](https://static001.geekbang.org/infoq/60/60293c6d28e974e0d68743350b01f2b3.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
测试结果分析
char数组元素最大值不会超过Integer.MAX_VALUE,回事非常接近的一个值,我这里相差20多。网上搜索了一番,比较靠谱的说法是:确实比Integer.MAX_VALUE小一点,不会等于Integer.MAX_VALUE,是因为char[]对象还有一些别的空间占用,比如对象头,应该说是这些空间加起来不能超过Integer.MAX_VALUE。如果有读者感兴趣,可以自行探索下别的类型数组的元素个数。我这里也算是一点拙见,抛砖引玉。
OOM解决方案
原因总结
通过上面一系列重现与分析,我们知道了OOM的根本原因是模板文件渲染而成的StringWriter对象过大。具体表现在:
如果系统没有足够大的内存空间分配给JVM,会导致OOM,因为这部分内存并不是无用内存,JVM不能回收
如果系统有足够大的内存空间分配给JVM,char数组中的元素个数在接近于MAX_VALUE会抛出OOM错误。
解决方案
前面分析过,出于安全的原因,我们只能用StringWriter对象去接收模板渲染结果的输出。不能用文件。所以只能在StringWriter本身去做文章进行改进了:
继承StringWriter类,重写其write方法为:
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
其他代码保持不变
BigVelocitySolution.java
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
控制台输出
如果velocity模板渲染后的sql语句集大小在允许的范围内,这些语句集会根据我们的业务做SQL语句的拆分,逐句执行。
如何优雅终止线程
在后续逐句执行sql语句的过程中,每一句sql都是调用的周边服务(DLI,OBS,MySql等)去执行的,结果每次都会返回给我们的作业开发调度服务(DLF)后台。我们的DLF平台支持及时停止作业的功能,也就是说假如这个作业在调度过程中要执行10000条SQL,我要在中途停止不执行后面的SQL了——这样的功能是支持的。
在修改上面提到OOM那个bug并通过测试后,测试同学发现我们的作业无法停止下来,换句话说,我们作业所在的java线程无法停止。
线程停止失败重现
一番debug与代码深入研读之后,发现我们项目中确实是调用了对应的线程对象的interrupt方法thread.interrupt();去终止线程的。
那么为什么调用了interrupt方法依旧无法终止线程?
TestForInterruptedException.java
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
控制台输出
![](https://static001.geekbang.org/infoq/e2/e2e3642a7316a1a40ce430290bf105b8.png)
测试结果分析
TestForInterruptedException.main函数中做的事情足够简单,先产生一个大一点的字符串,拆分成10段小字符串,for循环中逐段打印小字符串;并企图从第5段(初始段为0)开始,去终止线程。结果发现线程并没有终止!
这是怎么回事?为什么调用了线程的interrupt方法并没有终止线程?或者说是因为jvm需要一点时间去响应这个方法?其实并非如此,感兴趣的同学可以把循环次数加的更大一些,在循环开始几次就进行interrupt,你会发现结果还是这样。
经过一番探索,线程终止的方法无外乎两种:
使用该Thread对象的stop()方法能让线程马上停止,但是这种方法太过于暴力,实际上并不会被使用到,详见JDK1.8的注释:
Deprecated. This method is inherently unsafe. Stopping a thread with Thread.stop causes it to unlock all of the monitors that it has locked (as a natural consequence of the unchecked ThreadDeath exception propagating up the stack). If any of the objects previously protected by these monitors were in an inconsistent state, the damaged objects become visible to other threads, potentially resulting in arbitrary behavior. Many uses of stop should be replaced by code that simply modifies some variable to indicate that the target thread should stop running. The target thread should check this variable regularly, and return from its run method in an orderly fashion if the variable indicates that it is to stop running. If the target thread waits for long periods (on a condition variable, for example), the interrupt method should be used to interrupt the wait…
第二种方法就是上面JDK注释中提到的设置标志位的做法。这类做法又分为两种,无论哪一种都需要去被终止的线程本身去“主动”地判断该标志位的状态:
设置一个常规的标志位,比如:boolean类型变量的true/ false, 根据变量的状态去决定线程是否继续运行——代码里去主动判断变量状态。这种一般用在循环中,检测到相应状态就break, return或者throw exception。
使用Thead类的实例方法interrupt去终止该thread对象代表的线程。但是interrupt方法本质上也是设置了一个中断标识位,而且该标志位一旦被捕获(读取),“大部分时候”就会被重置(失效)。因此它并不保证线程一定能够停止,而且不保证马上能够停止,有如下几类情况:
interrupt方法设置的中断标识位后,如果该线程往后的程序执行逻辑中执行了Object类的wait/join/sleep,这3个方法会及时捕获interrupt标志位,重置并抛出InterruptedException。
类似于上一点,java.nio.channels包下的InterruptibleChannel类也会去主动捕获interrupt标志位,即线程处于InterruptibleChannel的I/O阻塞中也会被中断,之后标志位同样会被重置,然后channel关闭,抛出java.nio.channels.ClosedByInterruptException;同样的例子还有java.nio.channels.Selector,详见JavaDoc
Thread类的实例方法isInterrupted()也能去捕获中断标识位并重置标识位,这个方法用在需要判断程序终止的地方,可以理解为主动且显式地去捕获中断标识位。
值得注意的是:抛出与捕获InterruptedException并不涉及线程标识位的捕获与重置
怎么理解我前面说的中断标识位一旦被捕获,“大部分时候”就会被重置?Thread类中有private native boolean isInterrupted(boolean ClearInterrupted);当传参为false时就能在中断标识位被捕获后不重置。然而一般情况它只会用于两个地方
Thread类的static方法:此处会重置中断标识位,而且无法指定某个线程对象,只能是当前线程去判断
![](https://static001.geekbang.org/infoq/08/0864fd716272c6adb05feb90bc64dd33.png)
Thread类的实例方法:这个方法也是常用的判断线程中断标识位的方法,而且不会重置标识位。
![](https://static001.geekbang.org/infoq/3a/3acd20d653a30bdc875eebda07c0524e.png)
小结
要终止线程,目前JDK中可行的做法有:
自己设置变量去标识一个线程是否已中断
合理利用JDK本身的线程中断标识位去判断线程是否中断
这两个做法都需要后续做相应处理比如去break循环,return方法或者抛出异常等等。
线程何时终止?
线程终止原因一般来讲有两种:
线程执行完他的正常代码逻辑,自然结束。
线程执行中抛出Throwable对象且不被显式捕获,JVM会终止线程。众所周知:Throwable类是Exception和Error的父类!
线程异常终止ExplicitlyCatchExceptionAndDoNotThrow.java
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
控制台输出
![](https://static001.geekbang.org/infoq/c6/c67461712a362cd71fb1a6a2d8486771.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
测试结果分析
这个测试验证了前面关于线程异常终止的结论:
线程执行中抛出Throwable对象且不被显式捕获,JVM会终止线程。
优雅手动终止线程
线程执行中需要手动终止,最好的做法就是设置标识位(可以是interrupt也可以是自己定义的),然后及时捕获标识位并抛出异常,在业务逻辑的最后去捕获异常并做一些收尾的清理动作:比如统计任务执行失败成功的比例,或者关闭某些流等等。这样,程序的执行就兼顾到了正常与异常的情况并得到了优雅的处理。
TerminateThreadGracefully.java
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
控制台输出
![](https://static001.geekbang.org/infoq/1f/1f1b80e5d38385148416bc01a897372c.png)
为何项目中的线程终止失败?
我们项目中确实是调用了对应的线程对象的interrupt方法thread.interrupt();去终止线程的。
那么为什么线程不能相应中断标识位并终止呢?
回到我们项目的业务逻辑:
整个job分为模板读取、渲染以及SQL执行三个阶段,一般而言前两个阶段时间会比较快。在后续逐句执行sql语句的过程中,每一句sql都是调用的周边服务(DLI,OBS,MySql等)去执行的,结果每次都会返回给我们的作业开发调度服务(DLF)后台。我们的DLF平台支持及时停止作业的功能,也就是说假如这个作业在调度过程中要执行10000条SQL,我要在中途停止不执行后面的SQL了——这样的功能是支持的。
因此问题就出在了SQL执行的过程。经过多次debug发现:在SQL执行过程中需要每次都往OBS(华为自研,第三方包)中写log,该过程不可略去。调用该线程对象的interrupt方法thread.interrupt(),interrupt标识位最早被OBS底层用到的java.util.concurrent. CountDownLatch类的await()方法捕获到,重置标识位并抛出异常,然后在一层层往上抛的时候被转变成了别的异常类型,而且不能根据最终抛的异常类型去判断是否是由于我们手动终止job引起的。
对于第三方包OBS根据自己的底层逻辑去处理CountDownLatch抛的异常,这本无可厚非。但是我们的程序终止不了!为了达到终止线程的做法,我在其中加入了一个自定义的标志变量,当调用thread.interrupt()的时候去设置变量的状态,并在几个关键点比如OBS写log之后去判断我的自定义标识位的状态,如果状态改变了就抛出RuntimeException(可以不被捕获,最小化改动代码)。并且为了能重用线程池里的线程对象,在每次job开始的地方去从重置这一自定义标识位。最终达到了优雅手动终止job的目的。
这一部分的源码涉及项目细节就不贴出来了,但是相关的逻辑前面已经代码展示过。
系统内存占用较高且不准确
在线程中运行过程中定义的普通的局部变量,非ThreadLocal型,一般而言会随着线程结束而得到回收。我所遇到的现象是上面的那个线程无法停止的bug解决之后,线程停下来了,但是在linux上运行top命令相应进程内存占用还是很高。
首先我用jmap -histo:alive pid命令对jvm进行进行了强制GC,发现此时堆内存确实基本上没用到多少(不关老年带还是年轻带都大概是1%左右。)但是top命令看到的占用大概在18% * 7G(linux总内存)左右。
其次,我用了jcmd命令去对对外内存进行分析,排斥了堆外内存泄露的问题
然后接下来就是用jstack命令查看jvm进程的各个线程都是什么样的状态。与job有关的几个线程全部是waiting on condition状态(线程结束,线程池将他们挂起的)。
那么,现在得到一个初步的结论就是:不管是该jvm进程用到的堆内存还是堆外内存,都很小(相对于top命令显式的18% * 8G占用量而言)。所以是否可以猜想:jvm只是向操作系统申请了这么多内存暂时没有归还回去,留待下次线程池有新任务时继续复用呢?本文最后一部分试验就围绕着一点展开。
现象重现
在如下试验中
设置jvm参数为:
其意义在于:
限制jvm初始内存为100M,最大堆内存为200M。并在jvm发生垃圾回收时及时打印详细的GC信息以及时间戳。而我的代码里要做的事情就是重现jvm内存不够而不得不发生垃圾回收。同时观察操作系统层面该java进程的内存占用。
![](https://static001.geekbang.org/infoq/bf/bf3cd11593e22dd09018e987c722fd5e.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
SystemMemoryOccupiedAndReleaseTest.java
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
![](https://static001.geekbang.org/infoq/51/51e409b11aa51c150090697429a953ed.gif)
上述代码里我先定义了三个Thread对象,这三个对象都是在run()方法里分配了100M大小的char[],然后线程休眠(sleep)5秒。然后new一个线程池,并将这三个线程对象依次交给线程池去execute。线程池每两次execute之间相隔10秒,这是为了给足时间给上一个线程跑完并让jvm去回收这部分内存(200M的最大堆内存,一个线程对象要占用100多M,要跑下一个线程必然会发生GC),这样就能把GC信息打印下来便于观察。最后等到三个线程都执行完毕sleep一段时间(大概20秒),让我有时间手动在cmd执行jmap -histo live pid,该命令会强制触发FullGC,jmap命令之后你也可以试着执行jmap -heap pid,该命令不会触发gc,但是可以看下整个jvm堆的占用详情.
控制台输出
![](https://static001.geekbang.org/infoq/a0/a09b025e5f7223bd1971fdada55cf018.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
在jmp -histo:live执行之前进程在操作系统内存占用:
![](https://static001.geekbang.org/infoq/8b/8b3e261316ba4baa14baf59cdf01ab3d.png)
执行jmp -histo:live之后
![](https://static001.geekbang.org/infoq/c2/c21152e1971c776d553b226a9402fc89.png)
执行jmap -heap pid的结果:
![](https://static001.geekbang.org/infoq/50/505f24e1c37384e7f38cdbfe2701947c.png)
测试结果分析/win10任务管理器不准确
t1分配了100M空间给数组之后,t2结束:
![](https://static001.geekbang.org/infoq/86/864b72bb1dbd08b3fcda12168af50d32.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
内存占用:107042K,总可用堆空间大小:166400K
无法给t2分配100M,触发FullGC:
103650K->1036K(98304K)
t2分配了100M空间给数组之后,t2结束:
![](https://static001.geekbang.org/infoq/8c/8cd0dfbd465798b7e36a70cdf82e4ed1.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
内存占用:104461K,总可用堆空间大小:166400K
无法给t3分配100M,触发FullGC:
103532K->1037K(123904K)
t3分配了100M空间给数组之后,t3结束.
jmap -histo:live pid by cmd:
103565K->997K(123904K)
最后jmap -heap pid结果中堆大小也是123M。
这一过程中,操作系统层面jvm进程内存占用不会超过122M,jmap -histo:live pid触发FullGC之后维持在87M左右(反复几次试验都是这个结果)
那么为什么jvm的堆栈信息大小与资源管理器对应的不一致呢?
这个问题在网上搜了一圈,结论如下:
提交内存指的是程序要求系统为程序运行的最低大小,如果得不到满足,就会出现内存不足的提示。
工作集内存才是程序真正占用的内存,而工作集内存=可共享内存+专用内存
可共享内存的用处是当你打开更多更大的软件时,或者进行内存整理时,这一部分会被分给其他软件,所以这一块算是为程序运行预留下来的内存专用内存,专用内存指的是目前程序运行独占的内存,这一块和可共享内存不一样,无论目前系统内存多么紧张,这块专用内存是不会主动给其他程序腾出空间的
所以总结一下就是,任务管理器显示的内存,实际上是显示的程序的专用内存而程序真正占用的内存,是工作集内存
![](https://static001.geekbang.org/infoq/8b/8b3e261316ba4baa14baf59cdf01ab3d.png)
![](https://static001.geekbang.org/infoq/89/891e6bde504c9ee10ea92b007ed08013.png)
上面两张图能对的上:
如下两张图“勉强”能对的上:
![](https://static001.geekbang.org/infoq/ca/ca262521f013062ca6421615ff3bfe88.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
![](https://static001.geekbang.org/infoq/0e/0e9d9eba016e7048f3f5790541233524.jpeg?x-oss-process=image/resize,p_80/auto-orient,1)
但是和jmap触发gc之后的堆内存123904K还有点差距,这部分差距不大,暂时网上找不到比较靠谱的回答,笔者猜想可能这一部分用的是别的进程的可共享内存。我去linux上试了一把,也有这个内存算不准的问题。这个问题留待下次填坑吧~~
结论
线程结束可以是正常结束,也可以是抛出不被catch的Throwable对象而异常终止
线程结束后,线程所占内存空间会在jvm需要空间时进行回收利用,这些空间主要包括:分配在堆上的对象,其唯一引用只存在于该线程中
JVM在进行FullGC后虽然堆空间占用很小,但并不会仅仅向操作系统申请xms大小的内存,这部分看似很大的可用内存,实际上会在有新的线程任务分配时得到利用
JVM进程堆内存占用比操作系统层面统计的该进程内存占用稍高一些,可能是共享内存的原因,这点留待下次填坑!
写在最后
附上本文中描述的所有代码以及对应资源文件,供大家参考学习!也欢迎大家评论提问!
VelocityExperiment.zip 19.40KB
本文分享自华为云社区《一个神奇的bug:OOM?优雅终止线程?系统内存占用较高?》,原文作者:UnstoppableRock。
版权声明: 本文为 InfoQ 作者【华为云开发者社区】的原创文章。
原文链接:【http://xie.infoq.cn/article/eeff46c483c391a106d3bd1c4】。文章转载请联系作者。
评论