服务器假死笔记、日志按时间统计排查

场景

服务器假死，进程还在，但是已经接不到请求了。因此有客户报事，发现服务假死了。

这种情况一般不会频繁发生，偶尔出现了重启即可。但是在要求比较高的厂会要求复盘，也是被折磨够了，好好整理下。

应该从哪几个方面排查

造成服务假死的原因很多，可以从以下几个方面排查。
1、磁盘满了(太基础，顺手列下)
2、服务配置的内存(如：-Xmx1024M 和 -Xms1024M)
3、cpu(top看下，如果cpu始终好几百，可能会有问题)
4、gc
5、线程太多
6、tcp卡死等

临时方案

如果有客户报事请求响应超时(我方接口调不通)，一定要高度重视。
1、迅速调用下查询接口，再分别调用节点查询接口(例如有两个微服务)。
2、当然也可以看下日志输出，正常生产服务器日志应该是一直会打印很多的。几分钟内日志如果较少，就可能挂了。(两台机器对比下)
3、备份gc日志。(因为重启后gc日志会丢失，所以先备份)
4、备份下线程tcp(只能实时抓，关掉服务就没法复现了)
netstat -anp | grep 8123 >/tmp/custom-185-tcp.log
结果：

tcp6       0      0 :::8123                 :::*                    LISTEN      98844/java          
tcp6       0      0 10.168.0.1:8123      10.12.2.193:50218     TIME_WAIT   -                   
tcp6       0      0 10.168.0.1:8123      10.12.2.193:48958     ESTABLISHED   -                   
tcp6       0      0 10.168.0.1:8123      10.12.2.194:59692     ESTABLISHED 98844/java   -                   
tcp6       0      0 10.168.0.1:8123      10.12.2.193:50618     TIME_WAIT   -              

一般来说BLOCKED的是有问题的。
time_wait 如果过多也需要注意，但是如果不是很多，问题应该不大。

然后jstack 98844(线程id)，这样可以跟踪到方法：
jstack 98844 > /tmp/custom-98844-jstack.log

5、重启服务，测试接口。

解决方案

这种假死问题一般不太好排查，常规来说有几种可能。
1、慢sql导致卡死。
2、大数据列表等导致内存占慢。
3、gc的回收问题。
4、多线程超时，例如大量使用future，偏偏请求端服务不在线。

线程阻塞问题解决

1、根据业务适当调整线程池数量。
例如controller和service都是单例，设置的线程池是共用的，可以适当调大。
2、增加超时时间，尤其是在循环调用future时，限制每个线程的超时时间，例如为5s。可以在serviceImpl类上加@Transactional(timeout = 5)
3、线程异常时记得回收掉。
这段代码加在future获取结果时：

try {
    future.get(); 
} catch (Exception e) {
    logger.error("future异常，error：", e);
    Thread.currentThread().interrupt();
}

2个节点，一台异常一台正常

为什么挂掉的总是其中一台呢?
其实这是个随机问题，代码一样，两台都可能挂掉，看脸吧。

如果一定要追问，为什么总是第一台挂掉呢? 那么要反问下，为什么两台用了这么久都没事呢?(所以就是随机的)

长期方案

光重启太不负责了，一定要找到原因。

jstack查看是否有阻塞

jstack 81173 | grep ‘WAITING’ -A 15
81173是线程号

gc日志统计排查

操作步骤：
1、首先要把gc日志备份，这一步一定要先做，因为常规的gc文件重启后就会覆盖，就找不到了。
2、然后才是重启。
3、后续的排查。

排查过程

首先是gc.out，很不幸忘了备份了，因为好久不遇到，忘了要先备份gc日志再重启。

那么没办法，从日志找吧。
服务假死，日志输出会明显减少，甚至不输出。 这个彻底死掉的时间很好判断，很长时间没日志，最后一条就是彻底死掉的时间。

假死比挂掉更麻烦。
因为如果挂掉，nginx会识别到，请求自动转到另外一个节点，服务还是好用。
但是假死，nginx识别不到，还会把请求转到这两个节点，现象就是时好时坏。到了好节点就正常，到了坏节点就不通。

但是如何排查何时开始变慢的呢?
有种思路就是根据分钟统计日志行数，正常来说基本会差不太多，如果某个时间日志条数明显减少，就说明开始有问题了。

命令：

例如日志为：
2023-09-22 11:26:47,266 [http-nio-8081-exec-244] - INFO  com.ttt.common.aop.ServiceDigestAop$$EnhancerBySpringCGLIB$$42f78b6 -
实际上我们截取到分钟就行了。

awk '{print $1FS$2}' business.log |cut -c 1-16 |sort | uniq -c 
	$1 是 2023-09-22
	FS是分隔符，默认是空格，加这个主要是可以区分日 和 时分
	$2 是 11:26:47
	cut -c 1-16 截取1-16个字符，正好到分钟

如果要根据数量倒序排序，可以加个 sort -nr
awk '{print $1FS$2}' business.log |cut -c 1-16 |sort | uniq -c | sort -nr

获取到的数据如：

4048 2023-09-22 11:28
2503 2023-09-22 11:29
3891 2023-09-22 11:30
4902 2023-09-22 11:31
  700  2023-09-22 11:32
  300 2023-09-22 11:33
      1 2023-09-22 11:34

很明显，700对应的时间就开始有问题了。

然后就可以把这30分钟的数据全拿出来。

 grep "2023-09-22 11:30" business.log > /tmp/11点30.txt 
 输处到/tmp目录，可以不受服务器账户权限限制，例如下载等

根据cost时间来筛选

还有一种思路，是根据cost时间来筛选，项目中一般都做了log日志拦截器，会打印耗费的时间，例如：

日志未：
2023-09-22 11:30:28,526 [http-nio-8081-exec-305] - INFO  com.www.common.aop.ServiceDigestAop - *** cost 77945 ms

grep "cost*ms" business > /tmp/cost-12点所有的.txt

这样导出的日志都是带时间的，找到比较大的，再根据线程号去看具体某条请求。

netstat的各个状态

netstat中的各种状态：
CLOSED
初始（无连接）状态。
LISTEN
侦听状态，等待远程机器的连接请求。
SYN_SEND
在TCP三次握手期间，主动连接端发送了SYN包后，进入SYN_SEND状态，等待对方的ACK包。
SYN_RECV
在TCP三次握手期间，主动连接端收到SYN包后，进入SYN_RECV状态。
ESTABLISHED
完成TCP三次握手后，主动连接端进入ESTABLISHED状态。此时，TCP连接已经建立，可以进行通信。
FIN_WAIT_1
在TCP四次挥手时，主动关闭端发送FIN包后，进入FIN_WAIT_1状态。
FIN_WAIT_2
在TCP四次挥手时，主动关闭端收到ACK包后，进入FIN_WAIT_2状态。
TIME_WAIT
在TCP四次挥手时，主动关闭端发送了ACK包之后，进入TIME_WAIT状态，等待最多MSL时间，让被动关闭端收到ACK包。
CLOSING
在TCP四次挥手期间，主动关闭端发送了FIN包后，没有收到对应的ACK包，却收到对方的FIN包，此时，进入CLOSING状态。
CLOSE_WAIT
在TCP四次挥手期间，被动关闭端收到FIN包后，进入CLOSE_WAIT状态。
LAST_ACK
在TCP四次挥手时，被动关闭端发送FIN包后，进入LAST_ACK状态，等待对方的ACK包。

主动连接端可能的状态有：
CLOSED SYN_SEND ESTABLISHED。
主动关闭端可能的状态有：
FIN_WAIT_1 FIN_WAIT_2 TIME_WAIT。
被动连接端可能的状态有：
LISTEN SYN_RECV ESTABLISHED。
被动关闭端可能的状态有：
CLOSE_WAIT LAST_ACK CLOSED。