OOM内存溢出汇总_swap 0k

OOM内存溢出汇总

http://hellojava.info/?p=319

 

CASE1

一.出现问题

在前一段时间日常环境很不稳定，前端调用接口会出网络异常或服务不存在的异常。查询了服务器上的服务会有偶尔挂死的情况，服务器上的接口服务都不可用。于是我们对服务器上的状况进行了排查。

二.排查问题的过程

三.排查问题的步骤

1.查看服务器大概情况

首先最容易想到的是top命令，它能够实时显示系统中各个进程的资源占用状况，经常用来监控linux的系统状况，比如cpu、内存的使用。我上下当时截图的状况

 

由于前段时间服务不可用了，于是我们重启了tomcat服务，发现Java进程重启之后最显著的问题就是占用内存挺多，虚拟内存总量占了5.5G+，43.2%。

2.查看Java进程突然不服务的原因

先查看过了一些业务日志与关系紧密的中间件，组件的日志，无明显历史错误。于是我们在考虑Java进程突然不可用的原因。这里推荐一个很实用的命令:dmesg。demesg可以用来查看开机之后的系统日志，其中可以捕捉到一些系统资源与进程的变化信息。dmesg |grep -E 'kill|oom|out of memory' 来搜索内存溢出的信息挺实用。我们这次就是用来这个命令查出来是内存溢出的原因。上图

 

由图可见，内存不足，Java进程被杀死的案发现场清晰可见。

1. 查看JVM状态

关于OOM出现的情况，一般可以猜想是内存泄露，或者是加载了过多class或者创建了过多对象，给JVM分配的内存不够导致。于是我们用一下常用的JDK自带工具来观察下JVM的状态:
1. ps -aux|grep java 当服务重新部署后，可以找出当前Java进程的PID
2. jstat -gcutil pid interval 用于查看当前GC的状态,它对Java应用程序的资源和性能进行实时的命令行的监控，包括了对Heap size和垃圾回收状况的监控。

 

图中可见，Full GC次数远大于Young GC 。由此可见可能是老年代空间大小不足，导致应用需要频繁Full GC，因为Full GC要将新生代、旧生代、持久代一起进行GC。
3. jmap -histo:live pid 可用统计存活对象的分布情况，从高到低查看占据内存最多的对象。上图

 

由图上看，Java进程top时发现占用虚拟内存5.5G,而byte[]数组占用了３G。很有可能它就是凶手！

4.Java dump分析问题

Java dump，也叫做 Thread dump，是 JVM 故障诊断中最重要的转储文件之一。JVM 的许多问题都可以使用这个文件进行诊断，其中比较典型的包括线程阻塞，CPU 使用率过高，JVM Crash，堆内存不足，和类装载等问题。
1. jmap -dump:format=b,file=文件名 [pid] 利用Jmap dump,但是执行时出现意外了，如图所示

 

在基础架构事业群同学的提示下，发现这是JDK 7的Jmap 的Bug，stack over flow 中有这个问题的回答文档链接
2. gcore 出现了这个问题后，再其他同学的提醒下，我们尝试了gcore。在排查问题的时候，对于保留现场信息的操作，可以用gcore [pid]直接保留内存信息，这个的执行速度会比jmap -dump快不少，之后可以再用jmap/jstack等从core dump文件里提取相应的信息。

• a 先生成core dump 主要命令有
  sudo gdb -q --pid　//启动gdb命令
  (gdb) generate-core-file //这里调用命令生成gcore的dump文件
  (gdb) gcore /tmp/jvm.core　//dump出core文件
  (gdb) detach //detach是用来断开与jvm的连接的
  (gdb) quit //退出
• b 把core文件转换成hprof
  jmap -dump:format=b,file=heap.hprof /opt/taobao/java/bin /tmp/jvm.core
  这样就可以使用可视化的内存分析工具来一探究竟了
• c 使用性能分析工具对hprof进行分析
  这里主要使用了２个工具：一个是 MAT，一个基于Eclipse的内存分析工具，它可以快速的计算出在内存中对象的占用大小，看看是谁阻止了垃圾收集器的回收工作，并可以通过报表直观的查看到可能造成这种结果的对象。第二个是 zprofile (阿里内部工具)。直接上图

MAT上的图

 

zprofile上的图
 

通过图中我们可以发现ali-tomcat的StandardClassLoader类加载器的*Retained Size*(当前对象大小+当前对象可直接或间接引用到的对象的大小总和)占用了内存的44.21%。并且类加载器的个数高达3212个。于是我们推测可能是ali-tomcat的StandardClassLoader的类加载时出了问题，导致引入的byte[]数组占用的堆大小过多,而Full GC回收不过来，导致了OOM。

5.通过tomcat查明真相

因为怀疑问题出现在StandardClassLoader，于是我们去查看了tomcat的日志，在Catalina引擎日志文件catalina.log找到了一些异样的报警和报错:

上面提示加载类时可能会有内存泄露。然后在tomcat的类加载过程中还出现了加载javassist.jar包出现了EOFException。后来拉进了中间件部门ali-tomcat的开发人员一看，原来是我们那个版本的ali-tomcat的会出现这样的问题，要升级新的版本问题就能解决。

心得体会

这次主要通过上线和师兄们一起尝试根据线上OOM的问题，并将我们排查问题的过程记录下来，觉得是一次耗时较长，跟进的人较多，比较宝贵的经验。最近我们的日常还是不够问题，出现了一些更不明显的问题，期待在这样的问题中不断磨砺提高自己！:)

 

 

 

 

 

 

 

CASE2一次JVM问题排查

现象：每个整点RT会突然升高。

排查：
随后到监控器上上面排查了一下各机房RT明细：选择“视图”->“应用视图”->“某个机房”->“核心指标”->“RT”，定位到是某个机房RT有问题，再逐一查看是一台机器RT异常。

当时的处理方案：直接把应用offline

然后登录到机器上，查看整点的tegnine的error_log。
问题：请求大量超时。

 

再查看整点access_log的记录。

问题：

• 普通jsonp请求RT非常大，大量超过1s；
• checkpreload的status.taobao(没有逻辑的静态文件)请求返回都非常慢，返回需要500ms，报499（499意思是 “client has closed connection”,因为服务器端处理的时间过长，客户端“不耐烦”了）。

•  

 

• 到这里可以判断出问题出在java应用上，因为status.taobao是通过tomcat提供访问的。

查看gc日志。
打开/home/admin/logs/gc.log，在整点找到如下信息：concurrent mode failure

 

CMS GC知识简介
CMS，全称Concurrent Mark and Sweep,用于对年老代进行回收，目标是尽量减少应用的暂停时间，减少full gc发生的机率，利用和应用程序线程并发的垃圾回收线程来标记清除年老代。
CMS并非没有暂停，而是用两次短暂停来替代串行标记整理算法的长暂停，内外的设置正常收集周期是这样的：
　　1、CMS-initial-mark 初始标记
　　2、CMS-concurrent-mark 并发标记的
　　3、CMS-concurrent-preclean 执行预清理
　　4、CMS-concurrent-abortable-preclean 执行可中止预清理
　　5、CMS-remark 重新标记
　　6、CMS-concurrent-sweep 并发清除
　　7、CMS-concurrent-reset 并发重设状态等待下次CMS的触发
其中，CMS-initial-mark和CMS-remark会stop-the-world。

再来看日志：

2016-12-12T16:00:06.218+0800: 693662.589: [GC [1 CMS-initial-mark: 1531574K(2097152K)] 2126997K(4019584K), 0.2728460 secs] [Times: user=0.26 sys=0.01, real=0.27 secs]2016-12-12T16:00:06.491+0800: 693662.862: [CMS-concurrent-mark-start]2016-12-12T16:00:08.442+0800: 693664.814: [GC2016-12-12T16:00:08.443+0800: 693664.814: [ParNew: 1922432K->1922432K(1922432K), 0.0000370 secs]2016-12-12T16:00:08.443+0800: 693664.814: [CMS2016-12-12T16:00:10.339+0800: 693666.710: [CMS-concurrent-mark: 3.750/3.848 secs] [Times: user=7.51 sys=0.46, real=3.85 secs] (concurrent mode failure): 1531574K->1317734K(2097152K), 11.1239540 secs] 3454006K->1317734K(4019584K), [CMS Perm : 262511K->262496K(524288K)], 11.1248200 secs] [Times: user=10.82 sys=0.25, real=11.13 secs]

日志分析：

• 1531574K(2097152K)] 2126997K(4019584K), 0.2728460 secs
  年老代使用了1531574K，年老代容量2097152K（2G），整个堆使用2126997K，整个堆容量4019584K，用时0.27s。
• ParNew: 1922432K->1922432K(1922432K), 0.0000370 secs
  Minor GC，年轻代使用了1922432K，回收后1922432K，总容量1922432K。
• concurrent mode failure
  concurrent mode failure会stop-the-world。 参考：https://blogs.oracle.com/jonthecollector/entry/what_the_heck_s_a

•  

 

• 1531574K->1317734K(2097152K)
  年老代使用了1531574K，回收后还占用1317734K，年老年容量2097152K（2G），用时11.12s
• 3454006K->1317734K(4019584K)
  整个堆大小变化。
• 262511K->262496K(524288K)
  永久代，回收前使用了262511K，回收后使用了262496K，总容量是524288K（即512M）。
• real=11.13 secs
  用时11.13s

也就是说CMS-initial-mark使应用暂停了0.27s，而concurrent mode failure导致Full GC应用被暂停了11.13s。所以，产生RT升高的现象。

那是什么原因导致concurrent mode failure？
导致concurrent mode failure的原因有两种：一个是在年老代被用完之前不能完成对无引用对象的回收；一个是当新空间分配请求在年老代的剩余空间中得不到满足。
原文
(if the concurrent collector is unable to finish reclaiming the unreachable objects before the tenured generation fills up,
or if an allocation cannot be satisfied with the available free space blocks in the tenured generation,
then the application is paused and the collection is completed with all the application threads stopped. )
摘自：http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html

 

 

但到这里我们其实并不知道是哪个原因导致的？？？

我们可以让故障重现。

我们重新回到监控平台，查看内存、CPU等其他指标，看到应用的CPU指标：整点突然升高。

 

于是决定重新将问题机器拉上线，在整点抓占用CPU最高的进程，查找相应的Java线程。
第一步：找到应用的java进程的PID

ps -ef | grep java

找到进程ID为227771。

第二步：显示各进程资源占用情况。

top -p 227771 -H　

 

在整点找到PID 251435，转换成十六进制3d62b，再使用jstack打印出线程堆栈：

jstack 227771|grep -A 13 0x3d62b

以下是线程堆栈日志：

"pool-73-thread-1" prio=10 tid=0x0000000001725800 nid=0x3d62b waiting on condition [0x000000006c50f000]   java.lang.Thread.State: WAITING (parking)       at sun.misc.Unsafe.park(Native Method)       - parking to wait for <0x000000076a32ea18> (a java.util.concurrent.locks.AbstractQueuedSynchronizerConditionObject)atjava.util.concurrent.locks.LockSupport.park(LockSupport.java:186)atjava.util.concurrent.locks.AbstractQueuedSynchronizerConditionObject)atjava.util.concurrent.locks.LockSupport.park(LockSupport.java:186)atjava.util.concurrent.locks.AbstractQueuedSynchronizerConditionObject.await(AbstractQueuedSynchronizer.java:2043)       at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)       at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)       at java.lang.Thread.run(Thread.java:745)

我们看到这个线程名字是pool-73-thread-1，无法直接看出问题在哪里。

还好，我们同时dump了一份线程堆栈到zprofile上面，使用线程名进行搜索。

 

根据堆栈信息，我们分析了代码，最终找到了问题：是一个每小时执行1次的定时任务，查询结果太大导致。

问题SQL如下：

SELECT * FROM XXXX c WHERE c.`is_deleted`='n' AND c.`is_success`='n' AND c.`retry_count`<5 ORDER BY retry_count,id

原因：该SQL执行后一下子返回了120多万条数据，需要申请非常大的堆内存空间。再结合刚才的日志一起看下。

 

问题到这里已经明了
原因：新空间分配请求在年老代的剩余空间中得不到满足。

突然想到，我在整点的时候还做了个Heap dump：可以找出占用内存最多的对象。（跟Thread dump找出的问题是对应的）

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

CASE3

背景：

3月3号的下午5点多，应用突然接到很多报警：hsf线程池满了。

大家登录到架空查看发现有1台机器184频繁fgc，登到184看下内存情况：

 

发现是永久区满触发了fgc，但是永久区没法回收，一直维持再92.19%的占用率，再这样下去，就是OOM了。

大家只能先降级机器，然后dump堆和线程堆栈，然后重启，保证业务不受影响。

 

接下来大家分析思路就是为什么永久区会满，分配的大小是256M，之前从来没出现过，而且1个月没动过线上代码了。

大家都觉得是永久区存在泄露！！！

怎么办，只能找一台线上机器，在vm参数加上-verbose:class，输出虚拟机装入的类的信息，到底频繁装载了哪些class造成满的。

发现大量都是UserDO、PersonProfileDO这2个有cglib生成的动态class。

这个时候线索断了，我们代码里面大量这样用了spring aop和ibatis的cglib代理啊。

 

=======================================================================================================================================

 

最好的办法就是把加载的堆栈打出来，我想到用btrace的方法。

我在ClassLoader#defineClass的方法上挂钩，打印出调用堆栈

wo打印出UserDO堆栈：

 

打印出PersonProfilerDO堆栈：

从堆栈发现问题了，这些class都是ibatis在填充参数时生成的，我根据堆栈追踪它的源码，发现：

这个开关是在sqlmap-config.xml配置的，enhancementEnabled="true"就是打开了，走cglib生成class

解决方法找到了，把enhancementEnabled设置成false，发布预发验证问题，问题解决，到此泄露问题解决了。

 

 

=======================================================================================================================================

 

但是为什么class生成这么多？难道没有cache，cglib这么差劲？

为什么class回收不了？

大家提出质疑，是不是没找到根本原因？
 

这时一下陷入僵局，找不到思路了。。。。。

我们深挖了下cglib的BulkBean代码，其实人家是对class做了cache

这时候回来我们去zprofiler上看看类视图，fgc多次的dump，发现很多这类的class的实例已经没了，但是它还是没法回收，class unloading不了

 

我印象中，应该这个class被回收的条件，就是这个class的的new实例对象都被gc，应该这个class就应该被卸载了啊，难道不是？

搜索google关键字：jvm class unloading，搜到一篇文章，其中一段话：

 

那结论就是：

1、JVM为了保护加载、执行的类的安全，它不允许ClassLoader直接卸载加载了的类，只有JVM才能卸载，在Sun JDK中，只有当ClassLoader对象没有引用时，此ClassLoader对象加载的类才会被卸载。

2、当一个ClassLoader加载多个类时，只要这些class中还有一个在用，那这个ClassLoader加载的所有class都无法回收。

 

=======================================================================================================================================

那这些cglib的class的ClassLoader是谁呢？

通过zprofiler查看类型引用，知道了：AliWebappClassLoader，它就是ali-tomcat定义的classloader，它是全局唯一的，只在tomcat shutdown时才会回收。

 

到现在，结论出来了，这些cglib生成的class其实是没法通过fgc回收卸载的。

 

 

=======================================================================================================================================

慢着，还有一个问题，为什么生成这么多class，其他应用也是这样配置的，为什么没有这种情况？

前面说到cglib其实会缓存生成的class，它的策略是：

WeakHashMap作为cache

key是classLoader实例

value为一个hashMap

这个hashMap中key就是KeyFactory生成的一个Object，value为cglib生成的Class对象。

 

其实只要key一样就会重用class，那class的生成策略呢？

 

那结论出来了：

是由于cglib的cache策略造成的，它cache的key生成策略是根据ibatis的参数组合生成key，而我们userDO有100多个字段，理论上的排列组合有2的100次方组合方式。

 

=======================================================================================================================================

至此，所有的原因都搞清楚了~~

在次感谢一起排查的小伙伴：       

 

 

参考文档：

http://www.blogjava.net/zhuxing/archive/2008/07/24/217285.html
http://www.cnblogs.com/mengdd/p/3594608.html
http://www.lightskystreet.com/2015/09/01/mat_usage/
http://iamzhongyong.iteye.com/blog/1774386
http://bjyzxxds.iteye.com/blog/1532937
http://www.atatech.org/articles/6018

 

 

=======================================================================================================================================

附录：

cglib class name的生成策略

 

 

 

 

OOM Killer导致Java进程Crash的案例回顾

天上掉下一个锅

最近业务上线时，由于改动点非常多，虽然是通过了测试也对原有业务进行了回归测试但为了以防万一，所以想通过长时间beta来看是否存在问题，但在beta了一台机器后，过了18分钟，就收到了一条GOC告警，提示刚才beta的那台线上机器里Java进程缺失。带着一脸懵逼赶紧登陆上beta的机器查看了机器进程，发现真的消失了。第一反应是使用下dmesg查看是否被oom-kill杀掉了，从搜索出的日志来看，确实被oom-kill杀了。

 

然后去看了service_stdout.log，可以看到末尾的日志有这样的打印信息

 

好吧，凶手果然是oom-kill，而且从crash的日志信息来看Problematic frame可疑的帧提示是HashMap的resize操作导致的。查看了hs_err_pid1771.log的错误报告。参考：oracle-felog

报告包含如下内容
1. 日志头文件
2. 导致crash的线程信息
3. 所有线程信息
4. 安全点和锁信息
5. 堆信息
6. 本地代码缓存
7. 编译事件
8. gc相关记录
9. jvm内存映射
10. jvm启动参数
11. 服务器信息

1) 日志头文件
# Problematic frame:
# J 5317 C2 java.util.HashMap.resize()[Ljava/util/HashMap$Node; (359 bytes) @ 0x00007f1f1852988a [0x00007f1f185296c0+0x1ca]
主要告诉我们大概的原因是HashMap的resize操作导致的，其中C2表示是被JIT即时编译后产生的代码

2) 导致crash的线程信息
Current thread (0x00007f1ed5637800): JavaThread "SchedulerX-Grid-Task-Processor_668404441_5834563133_2018-12-03 23:00:00#0" daemon [_thread_in_Java, id=11937, stack(0x00007f1ec51f8000,0x00007f1ec52f9000)]

其中是java线程SchedulerX-Grid-Task-Processor在执行java代码时发出的JVM Fata指令, _thread_in_Java表示当时线程正在执行java代码

 

 

以上信息已经可以知道Java类和执行的方法了
类: com.cainiao.tmsx.decision.schedulerx.TransPlanJobProcessor
方法: createTransPlanTask
导致crash的操作:
1. java.util.HashMap.put
2. java.util.HashMap.resize

11) 服务器信息
Memory: 4k page, physical 8388608k(15976412k free), swap 0k(0k free)

vm_info: OpenJDK 64-Bit Server VM (25.102-b46) for linux-amd64 JRE (1.8.0_102-b46), built on Sep 14 2016 10:39:08 by "admin" with gcc 4.4.7

time: Mon Dec 3 23:00:04 2018
elapsed time: 1099 seconds (0d 0h 18m 19s)

 

这部分表述是错误的，这个swap区一直是0k的

确切的被oom-kill杀死的时间: 2018-12-03 23:00:04
应用运行时长: 1099秒 也就是 18分钟左右就导致了OOM了。

查看了sunfire里beta机器那段时刻的监控数据，内存表现平稳，cpu表现平稳，IO表现有峰刺，GC正常，load正常。

哥德巴赫的猜想

这个哥德巴赫是什么鬼？好吧，我乱写的。现在凶手有了，可疑的错误信息也有了，开始猜想是什么问题导致的。从目前收集上来的信息来看不像是HashMap高并发下的死循环问题，因为该问题会导致CPU100%。也不太像内存泄漏的问题，因为从GC监控和日志以及内存的使用率来看都不是稳步上涨最终导致内存不够而被Kill。更像是一种突然死亡。上面监控可以看到IO在23点01份时密集操作，是不是因为IO的密集操作导致内存被占用，然后上面有一个DTS的定时任务被触发，内部触发了一个resize操作359字节，最终因为swap内存区没有足够的空间进而被OOM呢？

尝试1

为了复现问题，我在日常环境写了一个每秒200次IO的写入，然后再触发DTS任务，发现一切正常，进程没有被kill，也没有触发任何OOM。排查下来后，其实这个IO密集操作就是java进程crash后在写core这个文件有足足6G那么大，写了很多cpu的操作，内存的信息等所以才会产生出那么多的IO操作，在crash的那一时刻。

尝试2

在beta的那两台机器上分别加JVM参数，第一台加 -XX:+PrintCompilation && -XX:+PrintInlining 用于打印出resize操作的JIT编译后的stack栈，第二台加 -XX:CompileCommand=exclude,java.util.HashMap::resize 用于屏蔽resize操作不经过JIT而直接执行。最终发现第一台被crash打印出来的信息中resize操作的大J变成了小j。其他信息都没变。第二台也被crash了，说明跟JIT编译后的代码没关系，由于意外原因没有保留住第二台的日志现场，有点可惜。

尝试3

从DTS的入口方法进去看，哪里有操作HashMap的put操作，从头到尾看了好几遍都没看到put操作，然后就想试试用arthas去trace方法里的put操作是从哪里触发的，结果拿到的stack栈居然是TDDL相关
开始怀疑tddl的ThreadLocalMap的put操作是不是存在问题，最后事实证明虽然该操作会导致多线程内存可见，但不会发生并发问题。

尝试4

感觉这样排查还是没有头绪，为了能100%复现问题，这样对于排查问题更有利，所以在预发环境里执行了线上出问题的那个DTS任务，发现预发一点事情都没有，没有复现。然后往线上多beta了一台机器，等着DTS任务被触发，果然在漫长等待中，DTS触发了该台beta机器，果然该台机器瞬间进程被kill掉了。

期间还经历了前端用户访问的时候导致页面直接跳转到err页面，虽然在psp里将该两台beta的机器操作了offline操作，也会出现相同的问题，为了不影响线上用户，只能直接回滚发布的分支，回滚回来后，发现一切都那么的正常了，包括DTS任务被执行也完全没有事情。

期间还发现了jdk的bug列表中，有一个bug跟这个表现的差不多bugs-JDK-8190377

为此还怀疑了是不是某些代码触发了JDK的bug

锅是我的，但你的这个操作，让我猝不及防

有一点是非常要值得注意的，就是原先的代码没问题，而新上的分支代码会导致crash，很明显就是业务代码问题，在之前已经codeReview过，但是没有看到可疑的问题代码，现在再次对比master代码来看导致什么代码变动了，以及怀疑一切。在codeReview中，发现有一个地方非常可疑，就是原先的一个DTO类被重命名成了Model层的类名。这个重构，看上去没什么问题，但是如果结合序列化和反序列化两步骤分开的前提下，是存在问题的。而且还注意到我用的DTS任务是网格Grid任务，他会有一个主任务以及分发出许多子任务，在主任务中对一个对象做了序列化操作，在子任务中反序列化回来，使用该java对象。这里的序列化和反序列化就被异步的分成了两步，而且在分布式的机器上执行。

尝试在本地重现

package com.cainiao.tmsx.decision.serializeoomcrash; import java.io.ByteArrayInputStream;import java.io.ByteArrayOutputStream;import java.io.IOException; /** * 序列化导致 OOM Crash 测试用例 * * @author <a href="mailto:ake.tkp@cainiao.com">tukeping</a> * @date 2018/12/4 */public class SerializeOOMCrashTest {    public static void main(String[] args) throws IOException {       // ----- step one -----       //com.cainiao.tmsx.decision.serializeoomcrash.Foo foo = new com.cainiao.tmsx.decision.serializeoomcrash.Foo();       //foo.setStr("test it");       //FooBar fooBar = new FooBar();       //fooBar.setFoo(foo);       //byte[] bytes = serialize(fooBar);       //String hex = byte2hex(bytes);       //System.out.println(hex);        // ----- get hex and modify FooBar.Foo to Foo1, step two -----       String hex = "4d740032636f6d2e6361696e69616f2e746d73782e6465636973696f6e2e73657269616c697a656f6f6d63726173682e466f6f426172530003666f6f4d74002f636f6d2e6361696e69616f2e746d73782e6465636973696f6e2e73657269616c697a656f6f6d63726173682e466f6f530003737472530007746573742069747a7a";       testUseHessian(hex);       //testUseDtsHessian(hex);   }    /**     * 原生hessian序列化和反序列化     */   private static void testUseHessian(String hex) throws IOException {       byte[] bytes = hex2byte(hex);        // exception here       Object object = deserialize(bytes);       System.out.println(object);        // it's ok       FooBar fooBar = (FooBar)object;       System.out.println(fooBar);        // ...       System.out.println(fooBar.getFoo().getStr());   }    /**     * DTS 改写的hessian 序列化和反序列化     */   private static void testUseDtsHessian(String hex) {       byte[] bytes = hex2byte(hex);        // it's ok       Object object = bytesToObject(bytes);       System.out.println(object);        // it's ok       FooBar fooBar = (FooBar)object;       System.out.println(fooBar);        // crash here       System.out.println(fooBar.getFoo().getStr());   }    private static byte[] serialize(Object obj) throws IOException {       if (obj == null) { throw new NullPointerException(); }        ByteArrayOutputStream os = new ByteArrayOutputStream();       com.caucho.hessian.io.HessianOutput ho = new com.caucho.hessian.io.HessianOutput(os);       ho.writeObject(obj);       return os.toByteArray();   }    private static Object deserialize(byte[] by) throws IOException {       if (by == null) { throw new NullPointerException(); }        ByteArrayInputStream is = new ByteArrayInputStream(by);       com.caucho.hessian.io.HessianInput hi = new com.caucho.hessian.io.HessianInput(is);       return hi.readObject();   }    private static byte[] objectToBytes(Object object) {       if (null == object) {           throw new RuntimeException("object is null");       } else {           ByteArrayOutputStream byteArrayOutputStream = new ByteArrayOutputStream();           com.alibaba.dts.shade.com.taobao.hsf.com.caucho.hessian.io.HessianOutput hessianOutput               = new com.alibaba.dts.shade.com.taobao.hsf.com.caucho.hessian.io.HessianOutput(byteArrayOutputStream);            try {               hessianOutput.writeObject(object);           } catch (Exception e) {               throw new RuntimeException("write object error", e);           }            return byteArrayOutputStream.toByteArray();       }   }    private static Object bytesToObject(byte[] bytes) {       if (null == bytes) {           throw new RuntimeException("bytes is null");       } else {           ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(bytes);           com.alibaba.dts.shade.com.taobao.hsf.com.caucho.hessian.io.HessianInput hessianInput               = new com.alibaba.dts.shade.com.taobao.hsf.com.caucho.hessian.io.HessianInput(byteArrayInputStream);            Object object;           try {               object = hessianInput.readObject();               return object;           } catch (Exception e) {               throw new RuntimeException("read object error", e);           }       }   }    private static String byte2hex(byte[] b) {       String hs = "";       String hex;       for (int n = 0; n < b.length; n++) {           hex = (Integer.toHexString(b[n] & 0XFF));           if (hex.length() == 1) {               hs = hs + "0" + hex;           } else {               hs = hs + hex;           }       }       return hs;   }    private static byte[] hex2byte(String str) {       if (str == null) {           return null;       }       str = str.trim();       int len = str.length();       if (len == 0 || len % 2 == 1) {           return null;       }        byte[] b = new byte[len / 2];       try {           for (int i = 0; i < str.length(); i += 2) {               b[i / 2] = (byte)Integer.decode("0x" + str.substring(i, i + 2)).intValue();           }           return b;       } catch (Exception e) {           return null;       }   }}package com.cainiao.tmsx.decision.serializeoomcrash; import java.io.Serializable; /** * @author <a href="mailto:ake.tkp@cainiao.com">tukeping</a> * @date 2018/12/5 */public class FooBar implements Serializable {   private static final long serialVersionUID = -55125587835222182L;    /**     * com.cainiao.tmsx.decision.serializeoomcrash.Foo 7758258L     * com.cainiao.tmsx.decision.serializeoomcrash.Foo1 7758258L     */    // --------- serialize use foo ---------   //private com.cainiao.tmsx.decision.serializeoomcrash.Foo foo;   //   //public Foo getFoo() {   //   return foo;   //}   //   //public void setFoo(Foo foo) {   //   this.foo = foo;   //}    // --------- deserialize use foo1 ---------   private com.cainiao.tmsx.decision.serializeoomcrash.Foo1 foo;    public Foo1 getFoo() {       return foo;   }    public void setFoo(Foo1 foo) {       this.foo = foo;   }}package com.cainiao.tmsx.decision.serializeoomcrash; import java.io.Serializable; /** * @author <a href="mailto:ake.tkp@cainiao.com">tukeping</a> * @date 2018/12/5 */public class Foo implements Serializable {   private static final long serialVersionUID = 7758258L;   private String str;    public String getStr() {       return str;   }    public void setStr(String str) {       this.str = str;   }}package com.cainiao.tmsx.decision.serializeoomcrash; import java.io.Serializable; /** * @author <a href="mailto:ake.tkp@cainiao.com">tukeping</a> * @date 2018/12/5 */public class Foo1 implements Serializable {   private static final long serialVersionUID = 7758258L;   private String str;    public String getStr() {       return str;   }    public void setStr(String str) {       this.str = str;   }}

这个例子总共就4个类，会进行两阶段进行序列化和反序列化，在第一阶段中序列化，我把FooBar里的Foo序列化进去，然后在反序列化的时候把Foo注释掉，使用Foo1进行反序列化，其中serialVersionUID不变，就变了类名，模仿我之前代码里重构的部分，然后使用了DTS使用的序列化类ByteUtil。果然在反序列化的时候进程被crash了。我又尝试了hessian默认包里的反序列化，发现在反序列化的那步时会报RuntimeException异常，而DTS里使用的反序列化，则会完完整整的反序列化对象出来，并把内存指针也返回出来，而此时的内存指针指向的是序列化时的Foo对象，而反序列化时Foo对象早已不存在了，只有Foo1对象，导致了非法内存地址访问，导致直接crash了整个进程。
问题原因找到后，把对象类名改回来，发布到线上beta，到执行到DTS任务时，果然没有出现任何问题了，进程也没有crash掉，问题解决。

题外话：
其实这个问题，在日常环境遇到过，当时的表现是前端访问都处于瘫痪状态以及会提示出网络错误或者直接跳转到err错误页，当时一直以为是前端的某个类库出现问题了，还找到了walle组的tars组件里面询问，排查到最后发现是后端的日常两台服务器的java进程都不在了，当时在日常分析了一波，最终得出来的结论是DTS的任务进入到死循环进而把内存吃爆了，由于实在无法复现，后面就不了了之了，在业务showcase的环节前又遇到过一次，为了showcase能顺利就直接重启了应用。后续在日常环境，尝试了几次复现，都不成功。现在问题解决后，回过头来看，终于能知道问题出在哪里了。是因为我们组同时在进行着两个业务项目，然后业务项目A在日常部署了，而业务项目B还是老的代码在他们本地启动了，而恰好DTS任务触发后，请求到了业务项目B的本地机器，从那里发出了主任务以及派发了子任务出来，日常环境的两台机器接收到了子任务，并在反序列化时就直接crash掉了。

思考

其实我是一个比较喜欢重构的人，每次重构完也会跑一遍单测以及集成测试来验证重构是否正确，而上面的案例中，即使单测还是集成测试都是无法提前发现问题的。所以重构javaBean类名时，切记，需要去考虑是否存在两步骤序列化的过程。这个也给我敲响了警钟，重构切记要谨慎。另外也给DTS团队给了这个crash的案例，因为反序列化的时候应该要去检查所有类型以及javaBean里内部属性的所有类型，像是hessian就会这么做，然后不符合就会直接抛RuntimeExcetpion，而不是直接将非法的内存地址返回出来，最终导致了crash，这么严重的后果