业务服务经常假死故障排查 踏雪扬尘

目录

• 概述
• 故障回溯
• 补充说明
• 其他工具

概述

最近遇到线上故障，具体的情况就是后端服务请求一直 pending，服务经常假死重启。 但是观察 整个进程CPU + 内存消耗不是特别大， 没有明显的资源泄漏情况。

故障回溯

1. top -p 40872
   查看进程情况，发现没有明显的 内存和 CPU使用率过高
   

2. top -Hp 40872 查看进程下的所有线程，没有明显的线程 CPU + 内存使用率过高
   
   备注若遇到 某个线程 资源消耗非常高，可以采取把对应的 线程id转换为十六进制 ， 然后在 线程 dump文件查询具体的行为。
   printf "%x" 进程号

3. 到此步骤基本确定没有明显的内存泄漏和 线程死锁故障。但是还是得看下 GC 的情况， 因为经常的 FGC 会影响服务的稳定性，导致服务假死。

打印类加载器信息 执行命令 jmap -clstats 36001
此处主要观察 是否加载了很多自己的业务 class， 若是则需要考虑是否大量违规使用反射 ；需要调优甚至调大元数据区

显示堆中对象的统计信息 jmap -histo:live 36001
也是执行观察整个容器中的 对象的分布情况， 主要观察是否有非常多余的业务对象，若非常多需要考虑优化；
比如很多业务对象是会很快就销毁的， 需要考虑增大 Eden区， 尽量在 YGC时释放掉，避免堆积到 old触发 FGC 。若这些对象就是比如缓存等， 则需要长时间保存，可以适度考虑调大 old区，减少 FGC的次数。

堆栈扫描 jmap -heap 36001 > ./jmapheap.txt 总体来说这个命令非常有用 可以马上发现是否有明显的内存泄漏 ;
如下图所示基本是健康的, 整个 Eden Space、From Space、To Space、PS Old Generation 占用情况还比较合理，没有明显的占满情况。

生成堆转储快照dump文件，以hprof二进制格式转储Java堆到指定filename的文件中
jmap -dump:format=b,file=./jmapdump2.hprof 6230 以上文件使用 jhat(Java堆分析工具) 分析
以上文件可以 在 https://gceasy.io 工具中直接上传分析， 本人在使用过程中发现太大没法打开，后续可以考虑减少导出的大小

生成 dump文件 一共2种方式：
其一，通过上面介绍的 jmap工具生成，可以生成任意一个java进程的dump文件；
其二，通过配置JVM参数生成，选项“-XX:+HeapDumpOnOutOfMemoryError ”和-“XX:HeapDumpPath”所代表的含义就是当程序出现OutofMemory时，将会在相应的目录下生成一份dump文件，而如果不指定选项“XX:HeapDumpPath”则在当前目录下生成dump文件。
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/biapp/m.hprof

接下来分析下实时的 GC情况；具体命令可以参考 https://www.cnblogs.com/yjd_hycf_space/p/7755633.html

打印 进程的 GC 明细 jstat -gc 6230 3000 这个命令呈现的具体的大小单位 KB

jstat -gcutil 30996 3000 这个命令展示是每个区域占用百分比

以上可以发现元数据区 已经快占满了， 触发了了 5次 FGC ， 元数据是有个初始大小的 默认是 28MB ， 当超过时会触发 FGC 回收掉不需要的 class， 然后回收的比例调节上限，所有若知道当前业务占用比较大的元数据区，可以直接设置一个比较大的元数据区
-XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m 减少FGC的次数
改为之后运行下述命令观察 ， 发现 FGC 已经去除了， 证明了猜想

//只查看年轻代的情况
jstat -gcnew 40872 1000 整个年轻代也是运行正常的

以上基本发现 内存 、GC 没啥问题，故考虑分析下线程堆栈：
执行如下 命令 jstack 12994 > ./jstack.txt
![](https://img2020.cnblogs.com/blog/646712/202112/646712-20211209194802643-391997802.png
结果如下图所示，发现很多在获取 Oracle连接时进行堵塞等待，并且出现了业务逻辑显示，故豁然开朗大概知道是啥问题了， 瓶颈应该是发生在获取 Oracle的数据库连接这块，于是分析下 每个对应的连接数 ;
获取本进程监听的端口被连接的连接数： netstat -nat | grep -i "10.xx:12080" | wc -l
67
获取 Oracle的连接数 ： netstat -nat | grep -i "172.xx:1621" | wc -l
57
获取 vertical的连接数 ： netstat -nat | grep -i "172.xxx:5433" | wc -l
17
结果看代码，整个这个库的连接数是 20 ， 遂发现可以提高数据库连接数，能缓解这种问题，然后调成 100 上线，观察下发现效果明显有些改善，但是随后又发现了大量的异常 :

上述异常的根本原因就是操作的时候在堵塞资源，导致客户端的请求直接超时；所以这种情况不是简单的增大连接数可以解决的了，随后在上述线程堆栈的提示追踪到 慢查询 SQL ，发现该表的 数据量到达的 一亿级别， 之前只有几千万，并且查询没有使用到索引。
然后我们观察一下基本都是一个查询从上述表中取出来 几十条数据，但是耗时到达 3MIN级别，故最终原因是 ORACLE表数据量暴增，慢SQL引起。 由于最终取出来的结果比较少，我们就采取了最终结果缓存 + 替换 Oracle 为 clickhouse OR vertical的解决方案；
基本亿级别数据， 筛选某些列 CK 表的话， 几十MS 就返回了。此处使用我司强大的数据中台，可以秒级配置化将一个 hive数仓数据导入 任意OLAP异构存储。未来我也会分享下我司关于数据中台的建设实战。
以上方案上线后就彻底解决上述问题，没再出现异常。
至于为啥依赖堵塞会导致 服务重启，可能是因为 Tomcat 连接线程过多，导致服务假死，重启。

补充说明

1. 目前 线程堆栈情况有更强大的分析工具 ：
   线程分析工具
   以上具体执行的效果如下： 可以快速发现死锁
   

2. netstat -nat 命令详解
   Proto Recv-Q Send-Q Local Address Foreign Address State
   
   Local Address 代表被连接的IP ， Foreign Address 代表连接着IP State 代表网络连接状态，参考如下：
   TCP连接状态详解：
   LISTEN： 侦听来自远方的TCP端口的连接请求
   SYN-SENT： 再发送连接请求后等待匹配的连接请求
   SYN-RECEIVED：再收到和发送一个连接请求后等待对方对连接请求的确认
   ESTABLISHED： 代表一个打开的连接
   FIN-WAIT-1： 等待远程TCP连接中断请求，或先前的连接中断请求的确认
   FIN-WAIT-2： 从远程TCP等待连接中断请求
   CLOSE-WAIT： 等待从本地用户发来的连接中断请求
   CLOSING： 等待远程TCP对连接中断的确认
   LAST-ACK： 等待原来的发向远程TCP的连接中断请求的确认
   TIME-WAIT： 等待足够的时间以确保远程TCP接收到连接中断请求的确认
   CLOSED： 没有任何连接状态
   SYN_RECV表示正在等待处理的请求数；
   ESTABLISHED表示正常数据传输状态；
   TIME_WAIT表示处理完毕，等待超时结束的请求数。

友情链接比较不错的资料：
https://mp.weixin.qq.com/s/mDnDjTWereF_ekLG1NNHRQ
https://mp.weixin.qq.com/s/zBfvjq3gry2zsMoMir6oZA
https://www.cnblogs.com/z-sm/p/6745375.html

其他工具

JProfiler :
是一款性能很强的分析工具，也就是 jconsule 界面的升级版，可以高效的分析线程、内存堆栈。并且还可以和 intellij idea wanmei
JOL（即Java Object Layout）：OpenJDK提供的库，用于查看Java对象的内存布局，这个很有用，可以借助它来跟踪锁升级等过程:
openJDK源码：查看 JDK native 方法的实现
strace：跟踪程序运行过程发起的系统调用
https://fastthread.io：线程栈分析的网站