记录服务不可用及 JVM 调优实战

贪吃的猫~

已于 2022-10-22 18:33:47 修改

阅读量265

点赞数 2

文章标签： jvm java 开发语言

于 2022-10-22 18:26:29 首次发布

本文链接：https://blog.csdn.net/qq_57125737/article/details/127465202

版权

记录一次服务不可用及 JVM 调优过程

事件背景

2022年9月24日17点42分，收到通知说服务不可用了，后续观察主要发生在 cust 服务上，偶尔 bus 服务也会发生，后面频繁出现不可用的情况，内心非常想要找到原因，也很好奇到底是什么原因使得服务不可用了。

排查线索

由于我是9月20日才签完入职手续，对于整个系统架构，业务等情况完全是两眼一抹黑，这种情况下想找到原因就更麻烦了，况且本身也没有调优经验，只是在工作之余有非系统性的去学习过该方面知识，最后就在这种情况下开展了排查的工作。

排查过程

一开始处理该问题是领导商量开会一起讨论，阅读系统日志想要找到什么错误导致的服务不可用，由于日志量过大（6~7个G），当时未发现什么重要线索，只有一堆数据打印、空指针异常、数组下标越界，当然这些都都通过异常捕获机制进行捕获，不会导致服务崩溃。于是就想着是否是最近发布的内容跟以前业务产生冲突，试着进行版本回退，于是对上一次的发布的内容进行讨论，发现上线的内容并不会跟以前的产生冲突。继续读日志，发现有大量推送的消息，就考虑是否是因为近期有大量推送的消息，导致服务处理不了大并发的情况出现的奔溃。
在这里插入图片描述

想到就做，于是开始检查服务的线程情况，一开始在本地启动服务，利用 cmd 命令 jvisualvm 启动JVM 可视化工具查看线程启动时数量在三百左右，经过一个小时左右线程数涨到六百，利用 jstack -l 进程id > jstack.log 命令 dump 生产环境线程数量，使用 https://fastthread.io/ 网址进行分析，发现线程数量飙到了一千多，是否更线程有关呢，阅读代码发现服务中大量的有开启线程池，且数量还挺大，而且都是使用无界队列。起初到这里就以为是线程数量过大导致服务资源耗尽出现奔溃。

通过上图可以看出来，线程数开的太大，有界队列因素确实会导致服务出现奔溃。于是想着减少线程的创建，把多个线程池利用统一线程池进行管理，于是观察线程，发现大量线程处于等待以及阻塞的状态，当线程等待的时候是不会抢占CPU资源的，并且推送业务就那几天，可是服务奔溃已经持续一个多星期了（中间国庆放了七天假期）。推送消息肯定没有了，服务还是在奔溃。说明服务的奔溃不完全是线程导致的，还有其他情况？正当纠结如何继续排查的时候，获得了一个重要的消息，运维每次重启服务的时候都要先杀死服务进程才能启动服务。进程还在！！！原来服务并不是奔溃，只是出现假死状态，为了验证服务是否真的一直都是假死，于是下来就联系运维，获取了服务器的 message.log 日志文件（我没有下载日志的权限）。

注：

/var/log/messages — 包括整体系统信息，其中也包含系统启动期间的日志。此外，mail，cron，daemon，kern和auth等内容也记录在var/log/messages日志中。
/var/log/dmesg — 包含内核缓冲信息（kernel ring buffer）。在系统启动时，会在屏幕上显示许多与硬件有关的信息。可以用dmesg查看它们
/var/log/boot.log — 包含系统启动时的日志。
/var/log/daemon.log — 包含各种系统后台守护进程日志信息。
/var/log/dpkg.log – 包括安装或dpkg命令清除软件包的日志。
/var/log/kern.log – 包含内核产生的日志，有助于在定制内核时解决问题。
/var/log/lastlog — 记录所有用户的最近信息。这不是一个ASCII文件，因此需要用lastlog命令查看内容。
/var/log/maillog /var/log/mail.log — 包含来着系统运行电子邮件服务器的日志信息。例如，sendmail日志信息就全部送到这个文件中。
/var/log/user.log — 记录所有等级用户信息的日志
/var/log/Xorg.x.log — 来自X的日志信息
/var/log/alternatives.log – 更新替代信息都记录在这个文件中
/var/log/btmp – 记录所有失败登录信息。使用last命令可以查看btmp文件。例如，”last -f /var/log/btmp | more“
/var/log/cups — 涉及所有打印信息的日志
/var/log/anaconda.log — 在安装Linux时，所有安装信息都储存在这个文件中
/var/log/yum.log — 包含使用yum安装的软件包信息
/var/log/cron — 每当cron进程开始一个工作时，就会将相关信息记录在这个文件中
/var/log/secure — 包含验证和授权方面信息。例如，sshd会将所有信息记录（其中包括失败登录）在这里
/var/log/wtmp或/var/log/utmp — 包含登录信息。使用wtmp可以找出谁正在登陆进入系统，谁使用命令显示这个文件或信息等
/var/log/faillog – 包含用户登录失败信息。此外，错误登录命令也会记录在本文件中
/var/log/httpd/或/var/log/apache2 — 包含服务器access_log和error_log信息
/var/log/lighttpd/ — 包含light HTTPD的access_log和error_log
/var/log/mail/ – 这个子目录包含邮件服务器的额外日志
/var/log/prelink/ — 包含.so文件被prelink修改的信息
/var/log/audit/ — 包含被 Linux audit daemon储存的信息
/var/log/samba/ – 包含由samba存储的信息
/var/log/sa/ — 包含每日由sysstat软件包收集的sar文件
/var/log/sssd/ – 用于守护进程安全服务

当收获系统日志后感觉阅读系统日志，进过长时间的阅读配合着网上的资料，发现日志里并未记录有服务进程挂掉，说明服务的确是处于假死状态。服务假死，一个重要的转折线索。

当确定服务是处于假死状态的时候，开始对服务假死进行排查。经过之前的排查，这次决定要确定好排查思路，以及排查方向，于是总结出导致服务假死的情况如下：

	cpu造成假死的话一般是会有服务器cpu使用率100%的现象。可以通过 `top -H` 找到使用过高的进程id
 
	内存造成假死的话，基本就是内存耗尽，程序OOM，而OOM多数又是大量数据一次性加载到内存所致，主要考虑sql查询范围问题
 
	数据库引起的假死可能是因为慢sql，所有进程日志都停在相同或者相似的地方，日志没有明显报错，这种情况主要是因为慢sql超时时间较长，全部进程都阻塞在了数据查询上
 
	IO其实包含多种类型，磁盘IO或者网络IO。常见的一个问题是java获取本机ip的方法`InetAddress.getLocalHost()`,非常容易因为服务器未配置hostname对应的ip导致长时间的阻塞，可以通过`hostname -i` 验证是否是因为这个问题导致

在这里插入图片描述

使用 top 命令可以看出 10996 和 14661 的CPU占用率很高，其中10996是cust的进程，14661是bus的进程

通过上图发现CPU使用率的确很高，于是使用 jstat gcutil 进程id 查看 gc 情况，观察如下（图片不是同一时间的截图，所以进程id不一致）：

早上9点4分的 GC 情况

在这里插入图片描述

中午 15点43的 GC 情况

在这里插入图片描述

通过上面两张图监控发现 cust 服务的 GC 次数明显不正常，且经过六个多小时的运行内存已经占满，且FGC频率非常高，到此已经大概清楚服务器的假死的确是以为内存不足导致。

接下来排查内存情况，因为以前未出现过不可用的情况，于是猜测可能是数据库慢查询、大数据查询导致，且日志中大量的大数据打印，随后拷贝了一份数据库的慢查询日志，经常慢查询日志发现数据库查询效率平均在一秒多，可以排除慢查询导致，接下来就是大数据查询，阅读查询日志观察查询语句，发现有两个语句查询语句很长，查询的数据也很大，锁定该查询语句。观察内存使用堆栈信息

在这里插入图片描述

跟日志打印的大量信息，数据库大数据查询吻合，看来的确是大数据造成的内存爆满，于是开始排查为何会有这么多大数据压入内存无法释放，经过多方排查最后将目标锁定在 session 上，通过代码发现每次在获取信息的时候，若 result 为空，请求都会将查到的 result 信息存入 session ，并且 session 的过期时长为一小时，所以大量的大数据字段存在 session 中，导致服务频繁 FGC 不说，内存也会因此而爆满出现假死情况。找到问题接下来就是处理 session 数据了，最终将根据情况选择是去除 session 字段的数据量还是使用 spring session+redis 做分布式 session 存储。