背景\

从5月7号上线后，生产上两台机器出现内存溢出现象，第一次5月20号上午，5月20号晚上上线，然后5月27号又出现，接着是6月2号,6月21号等都出现。前期由于没有获取生产上内存溢出记录信息，只获取了27号的javacore文件和heapdump ,当时javacore 文件获取的还不完整。后来研究对应的was 下面的系统日志，才发现native_stderr.log中记录了内存溢出时的记录。具体这部分请参考后面was相关部分。

两台溢出记录如下

142机器

5月20号 2022/05/20 16:04:41

5月27号 2022/05/27 14:40:34  6月2号 2022/06/02 11:55:25

6月9号 2022/06/09 16:25:44   6月14号 2022/06/14 17:59:24

6月15号 2022/06/15 10:55:47 6月21号 2022/06/21 18:16:49

141机器

5月24号 2022/05/24 22:06:07 5月31号 2022/05/31 22:07:45

6月14号 2022/06/14 17:52:40 6月15 号 2022/06/15 10:19:44

6月21 号 2022/06/21 18:14:49 

正文

WAS 堆栈信息

Java dump and core files的作用

javacore

Java core files like a picture of what occurs in Java virtual machine.

When it is used, this kind of file is useful to analyze scenarios where the CPU is reaching 100% of utilization, when threads are hanging or where the performance is slow.

heapdump

Java dump and system dump files are a picture of the objects that were in Java virtual machine memory and are helpful in diagnosing memory related problems such as memory leaks.

core.dmp 区别与可分析的headdump.phd文件，是不能用IBM Thread and Monitor Dump Analyzer for java 分析的文件。Core.dmp 是当前进程的内存情况，当前进行消耗了多大内存，这个文件就对应多大。是操作系统进行的内存快照，文件大，也没有实际的分析价值，可以分析一下javacore文件。

javacore文件是关于cpu 的(线程调用栈信息)，heapdump 关于内存的(java对象信息)

如何生产手动生成heapdump 和javacore 文件

Javacore 文件可以使用kill -3 pid  直接生产

WebSphere 8 可以从控制台生成不需要重启机器

官网给的答案 多看官网

heapdump 文件分析

Heapdump 文件分析软件的使用

上面需要借助IBM 提供的heapdump 分析工具ha*.jar。从官网下载ha456.jar。

IBM 的文档由于之前的社区废弃了，好多链接都失效了，下面的是最新地址

IBM HeapAnalyzer 和 ****IBM Thread and Monitor Dump Analyzer for java(TMDA) 两个软件搜索了好久才找到对应的文档 具体链接见下文,对应jar 取官网自取。

www.ibm.com/support/pag…

Windows 下启动

启动

java -Xmx10000m -jar ha456.jar

-Xmx 设置内存大小10G

启动成功，界面如下：

导入heapdump 文件进行分析

File –open 找到对应的文件，点击是即可。

\

\

加载完成后的界面

\

点击Leak Suspects (泄漏嫌疑犯)

选项中为软件认为可能发生内存泄漏的地方。需要根据具体情况排查。

我们选择第一个90.16%的

org/apache/ibatis/executor/result/DefaultResultHandler at 0x70672bd0

从上面可以看出和ibatis 有关，应该是数据库查询结果有关。

为了验证上面的正确性，我设计了个实验。

验证猜想

如何验证自己的猜想或者如何进行复现 对比法类比法？

\

Mr_dcm_trans_log 表数据造近2000W 条。

发送请求 发现内存没溢出。

查看was 当时的内存大小

没有达到最大堆内存。于是并发发送多个请求，造成内存溢出。(测试环境模拟内存溢出 获取javacore 和heapdump 文档)

分析heapdump 文件

从上图看

First single ancestor

org/apache/ibatis/executor/result/DefaultResultHandler at 0xba5c6490

和生产上一致，验证生产上是sql 查询导致。

题外话：

85% 主要所有上面的23 21 14 12 组成。共用10个DefaultResultHandler对象，从上面看出我同时进行五次sql 查询才造成内存溢出。

Javacore 文件分析

Javacore 文件分析下文分析。（从上面看内存溢出的线程可能是正在运行的线程）。

技巧 如何确定那个线程 看调用栈50以上的。

技巧 先栈深度降序 再state 排序

排查深度在50以上的。(涉及ibatis 调用栈很深 如果看到源码就知道大致流程)

SelectList ibatis 流程大致如下

言归正传，回归生产问题。

sql 结果有405027个hashmap实例，占用内存1.83G（90.16%）.

Javacore文件分析

Javacore 文件分析借助IBM 提供的工具IBM Thread and Monitor Dump Analyzer for java(TMDA).

去官网下载。

www.ibm.com/support/pag…

\

Javacore 文件分析工具使用

Windows 下直接双击文件就能打开，打开界面如下：

点击左上角文件夹打开对应的文件。

导入四个文件，从图上看四个文件产生时间6月 21 18:16:49 2022 到6月 21 18:18:29 2022，持续大约两分钟。

选中第一个文件点击选择Thread Detail

界面如下

\

线程的状态

注：parked 停止

\

主要关注线程状态status 为

Deadlock 死锁 从图上看没有

Waiting on condition 条件等待 有

Waiting on monitor 等待监视器 没有

Blocked阻塞 有

Runnable 也需要关注

Javacore1分析

线程执行应该很快，如果四个文件中都有同一个线程在阻塞或者执行，那这个线程就应该有问题。从堆内存分析知道应该是个sql 查询 一直占用内存。

1.先对stack 调用栈深度降序，再对state 排序，如下图

逐个排查栈深在50以上的和ibatis 有关的线程调用栈。

很幸运Block 第一个线程就符合线程名字WebContainer : 4 ****（记着这个名字）

Parked 和ibatis 有关的也很多，暂时不看。

\

Runnable栈深很小，不符合 

Waiting on condition 有，再从上往下排查

inner-job-com.ahzx.mdfc.elastic.job.CreativityAutoModelJob-4248

\

涉及ibatis

nner-job-com.ahzx.mdfc.elastic.job.CreativityAutoModelJob-4244

这个和上面一样。从线程名字也能看出执行的任务是一样的。

第一个javacore 文件

线程state

Block 有一个线程和ibatis 有关

Waiting on condition 有两个线程和ibatis 有关。

javacore2 分析

步骤如一：

很巧，第二个文件block 线程也有一个和ibatis 有关 线程名**WebContainer : 4 **

和第一个文件中是同一个线程 一直阻塞。

第三个第四个文件一样。

Javacore3分析

Javacore4分析

WebContainer : 4 线程阻塞了将近2分钟。线程一般都是执行很快的，长期阻塞，一般有问题。目前来说这个线程嫌疑很大。

上面的调用栈找到具体代码调用如下

at com/ahzx/dao/impl/HshyDao.queryForList(HshyDao.java:31(Compiled Code))
at com/ahzx/service/impl/menu/innovateevaluate/InnovateEvaluateServiceImpl.queryQuarterInnoEvals(InnovateEvaluateServiceImpl.java:133)
at com/ahzx/service/impl/menu/innovateevaluate/InnovateEvaluateWs.downloadQuarterInnoEvals(InnovateEvaluateWs.java:113)

从文件前缀看不是我的项目。我们项目是com/ahzx/mdfc

溢出从5月20号之后，产生的，大概为五天为一个周期（前期以为是周期问题，扩充过堆大小 也不起作用）对排查方向进行了干扰。

在不获取别人项目的源码的情况下，如何验证这个问题和自己项目无关呢，由于同一台服务器的生产版本在一起。

从生产版本服务器获取5月20号后和我们同一个服务器的所有的项目的版本war。使用beyond Compare4 工具反编译源码

\

0507

InnovateEvaluate文件内容

\

0624

\

\

生产上这个sql 返回126W,并且字段返回有40几个，内存爆满了。

Sql 结果上126W , 40.5W条占用1.83G,数据加载完估计要126/40.5*1.83=5.69G  

6G左右内存才不能溢出。这也解释了，之前从2G 内存调整到4G内存还是会出现溢出的情况。

联系对应的开发，解释，上面的操作，是下载一张报表，数据量百万级别，

其实是数据发散导致的，已经优化。

报表下载的话，最好搞成分页下载，数据量1000-2000条获取一次。

验证：

通过查生产操作日志，验证时间点是否一致。

验证 下载异常的

涉及5月27号，6月2号，6月9号，6月14号，6月15号，6月21号都在上面的异常内容中。但是5月20号的溢出不在上面异常的信息中。20号从操作记录来看，确实操作了。

这个时间肯定不可能是人下载，并且我们的定时任务是22点开始。

扫描项目日志：

有个sql查出来1061850条数。

1号发现问题，将批量未跑的数据直接处理掉了。该sql 每个定时任务晚上十点只跑一次。

并且6月10 号将堆内存由2G调整到4G。结果还是出现内存溢出的情况。6月17号晚上将夜间定时任务停掉。

从时间上看 141机器上的5月24号和5月31号导致的堆溢出应该是批量作业导致的。

其他

线程的名字自定义

这个线程的名字是可以改成自己命名，根据对应的线程名的话，如果是自己项目的话，一眼就能确定是哪块逻辑有问题。

阿里开发手册要求如下

\

线程多次创建

排查中查看日志遇到的问题

有个定时任务，CreativityAutoModelJob ，查看栈信息时如下：

**
**

从上图看线程名字inner-job-com.ahzx.mdfc.elastic.job.CreativityAutoModelJob-4248 ，重点是4248，因为这个是线程池创建的。默认是十个，所以这个应该是0-9，从4248可以看出，应该是重新创建的。什么原因导致的呢？为什么和其他的定时任务不同呢

正常的类似这种XEDOutAreaApproveModelJob-7。正常名字0-9 ,那源码应该使用线程池创建线程，而这个名字为4248 应该是之前的线程过期了，下一个线程重新创建的，应该和线程存活时间有关。

CreativityAutoModelJob 为五分钟执行一次，XEDOutAreaApproveModelJob为20秒执行一次，测试环境将CreativityAutoModelJob的定时时间调整为20秒一次，发现CreativityAutoModelJob 在0-9之间变化，说明猜测正确。

验证

由于使用的是当当开源的框架elasticjob 线程池创建的线程，所以去源码中找答案。

从github 上拉对应版本的的源码到idea 中。我们用的是2.1.5.

源码目录结果如下：

如果不知道源码在哪里？

可以直接搜索ThreadPool关键字试试

结果只有一个，直接点进去看看

正好是我们要找的，但是需要验证对不对。直接搜索哪里有调用这个构造函数

从结果可以看出有四处，其中第一处和colud 有关，我们没用，这个可以排除

剩下三处来自同一个模块

common-core 一看名字就能确定找对地方了

三个中从名字看应该是DefaultExecutorServiceHandler.

*/**
** 默认线程池服务处理器 *.
*
*  @author zhangliang
/

zhangliang 是elasticjob的开源作者,大神级别的。

从上面的注释知道，我们找的是对的。

Runtime.getRuntime **() **.availableProcessors () * 2

这个是cpu的2倍。核心线程数

超时时间为五分钟,而这个定时任务的时间正好是每五分钟执行一次，正好一个任务执行完，就过期了，原线程被回收了，下一次线程池重新创建线程。这个可以优化一下，调整为3分钟一次，这个不用大量创建线程。Elasticjob 原理不同情况，这个有时间还需要去了解一下源码及其原理。这个定位很顺利，得益于堆线程池的创建流程比较熟悉。

总结反思

5月7号上线后，首次内存溢出为20号，当时没有认真对待，以为是偶然现象，直接将dump 文件删除了，并且对javacore 和heapdump 文件只有初步认识，从没有真正的分析过。直到27号，又出现溢出现象，才开始重视。开始查阅资料，准备分析问题.

首先弄清楚各个文件的作用，以及需要从生产上拿哪些文件，需要获取哪些信息

由于前期对文件作用和如何分析不清楚，从生产上获取的文件不全，javacore 和 heapdump 文件都只拿了一部分，heapdump 文件分析中发现hashmap实例太多，但是具体原因也没有分析出来，结果不了了之。

5月31发生内存溢出的时候，怀疑可能系统资源不够，不足以支持系统正常运行，6月10号将生产上的堆内存由2G调整到4G，但是之后还是有内存溢出，并且javacore 和heapdump 文件过大，不好从生产上拿下来。hashmap实例太多 分析可能有内存泄漏，有的hashmap 没有被释放，逐渐累加，堆满内存。并且项目中有用到threadLocal,threadLocal有内存泄漏的情况，并且排查项目后，发现项目中有一种业务逻辑，threadLocal 使用过没有remove操作，可能存在内存泄漏想象，发现后，对其优化，但生产版本并没有投产。

10号当天查看日志时，想到可能是sql 返回结果过多导致的，于是扫描了一下日志文件，

扫描出生产返回结果在1000条以上的语句，结果发现了一个sql，查询批量日期的，返回了一百多万条重复的数据，然后对其优化，分析代码确实会对内存消耗过大。对代码进行了优化，但是当时并没有投产，生产版本没有更新。这个sql 涉及批量脚本 批量时间为晚间十点，5月24号和5月31号内存溢出应该是这个原因导致的。至此以为定位到问题了。6月17号将生产上定时任务停掉，并且将was 堆内存调整回2G。

6月21号，又发生内存溢出现象。

之后开始测试环境下模拟内存溢出，并发进行数据查询，实时查看堆内存大小，直到内存溢出。知道是数据返回太多，导致内存溢出的情况，开始分析javacore 文件，通过stack 深度，state 等排序，查到对应的栈信息，之后开始真实分析21号的日志，21号日志javacore 文件获取完整，通过前后分析，发现有个线程阻塞，并知道原因。

期间 知道是sql 查询返回很多的原因，也让DBA导出AWR 报告，但是没有看到对应的语句。

这次生产排查得到了总行的很多领导的支持，再次感谢各位老师的支持，这次排查收益良多。

涉及到was 的其他内容

server1目录下的各文件作用

不知道各个文件的具体用途，生产上无法获取对应的信息。

以上是Was 系统目录下的文件

native_stdout.log 和native_stderr.log

能看到详细的GC输出信息，但是需要was中配置，生产上被禁用了

Native process logging.

Messages sent to stdout and stderr from native code segments are directed to the native_stdout.log file and the native_stderr.log file, respectively.

Use for problems that occur in native code or code written using the Java Native Interface(JNI).

Verbose GC(Garbage Collection) output goes to the native_stderr.log for IBM JDKs.

server1.pid

当前was线程id.

startServer.log 和stopServer.log

保存server 启动 停止的记录

SystemErr.log  和SystemOut.log

系统错误日志 （常用） 系统输出日志 （常用）

SystemErr.log.owner 和SystemOut.log.owner

打开这两个文件看了一下，看来这两个文件的后缀名是名副其实的，因为文件内容就是指明了Cell/Node/Server这些信息，以下是我本机看到的文件内容：

如何设置对内存大小(查看堆内存大小)

服务器 > 应用程序服务器 > server1> Java 和进程管理 > 进程定义 > Java 虚拟机

Java 虚拟机内存大小

初始化为512MB 最大堆内存为1024MB

修改初始堆大小 最大堆大小后，重启was 即可。

如何查看当前堆内存大小

was如何查看一段时间内的堆内存变化

通过native_stdout.log文件，如何使用软件分析native_stdout文件

IBM Pattern Modeling and Analysis Tool for Java Garbage Collector (PMAT)

IBM Pattern Modeling and Analysis Tool for Java Garbage Collector is a tool that parses verbose GC trace, analyzes Java heap usage, and recommends key configurations based on pattern modeling of Java heap usage.

www.ibm.com/support/pag…

Garbage Collection and Memory Visualizer

垃圾收集和内存可视化器

The IBM Monitoring and Diagnostic Tools - Garbage Collection and Memory Visualizer (GCMV) tool analyzes verbose garbage collection to investigate Java performance and OutOfMemoryError issues.

www.ibm.com/support/pag…

上面两个文件都可以分析native_stdout.log 文件，但是生产上没有输出gc 详细日志，这个需要测试环境开启进行使用软件分析一下，可以看看堆内存大小的变化，看看系统是否有不合理不处，后续是否有优化的地方。

如何确定系统的分配的最大堆内存是否低于系统需要的内存

分析堆内存使用变化，分析最终是否趋于平稳

如何查看WAS 版本信息

通过console

登录was控制台，首页就会显示was版本 目前我们使用生产8.5.5.2版本

通过SystemOut.log 日志

SystemOut.log中看到Environment信息，包括WAS的版本、操作系统的版本、JDK的信息等

执行versioninfo.sh

在安装目录的bin下,执行versioninfo.sh脚本

WebContainer 线程池

修改webContainer线程池server.xml