背景:
运营发现请求异常,简单的获取版本需要46s,改接口未访问数据库等其他额外组件,仅仅内存获取值返回,正常是几毫秒的时间。
请求 time curl http://localhost/getVer
客户端请求花了46秒,服务端记录的时间才39ms,看起来像大部分时间都花在等待,同时没有监控的metric信息,监控面板看不到数据
查看监控的ss请求,40分之前 经常有很多SYN-RECV的连接占用队列,导致建联很慢
for file in ls ss.log*; do grep SYN-RECV $file |wc -l; echo $file; done
原因分析:
运维初步判断是网络的问题,想调大accept;
登录机器初步查看,等待服务端 accept() 的 TCP 连接满了,backlog 128
正常情况下Recv-Q 为0,Send-Q表示backlog的大小。
发送异常时候,待accept队列堆积:
同时accept队列溢出:
观察堆栈,看到三组nioEventLoopGroup,可以看到都是正常的,也就是不存在nio接收线程卡主导致不能接收,另外react模型可以支持c10k问题,我们并发很小不是这个原因。
"nioEventLoopGroup-2-2" #68 prio=10 os_prio=0 tid=0x0000000003f9f000 nid=0x1554e runnable [0x00007f73e413a000]
"nioEventLoopGroup-2-1" #67 prio=10 os_prio=0 tid=0x0000000003fb0000 nid=0x1554d runnable [0x00007f7424064000]
"nioEventLoopGroup-4-4" #489 prio=10 os_prio=0 tid=0x00007f72a03ba800 nid=0x202b1 runnable [0x00007f7288cec000]
"nioEventLoopGroup-4-3" #477 prio=10 os_prio=0 tid=0x00007f7388003800 nid=0x1f104 runnable [0x00007f7288f6e000]
"nioEventLoopGroup-4-2" #466 prio=10 os_prio=0 tid=0x00007f73b411f000 nid=0x1dc3d runnable [0x00007f7288f2d000]
"nioEventLoopGroup-4-1" #443 prio=10 os_prio=0 tid=0x00007f73188e2000 nid=0x1b637 runnable [0x00007f7288faf000]
"nioEventLoopGroup-3-120" #214 prio=10 os_prio=0 tid=0x00007f73a80d4000 nid=0x17bd0 runnable [0x00007f728bc2f000]
"nioEventLoopGroup-3-119" #213 prio=10 os_prio=0 tid=0x00007f73a80d2000 nid=0x17bcf runnable [0x00007f728bc70000]
"nioEventLoopGroup-3-118" #212 prio=10 os_prio=0 tid=0x00007f73a80d1000 nid=0x17bcd runnable [0x00007f728bcb1000]
"nioEventLoopGroup-3-117" #201 prio=10 os_prio=0 tid=0x00007f73a80cf800 nid=0x173f2 runnable [0x00007f728bcf2000]
看下当前的状态:
ss| grep ‘ip’ | awk ‘{print $2}’|sort -n |uniq -c
导出堆栈的时候很慢,怀疑是机器的问题,看gc日志,内存溢出,full gc导致的问题
果然看到GC出现异常,full GC频繁,并且不能释放内存,说明内存泄漏了。
看jmap
jmap -histo pid
发现都是metric相关的类,找到对应的日志目录,发送确实没有打印改日志,怀疑线程跑飞或者没启动。最终去过滤日志,找到启动当前的启动日志,发现确实是metric的问题,没有打印导致堆积。
查看代码发现是初始化的异常被捕获但是没有继续抛出,只打印了异常,导致即使错误也能正常启动服务。
解决:
当初始化出现问题的时候应该直接抛出异常,避免未正确初始化导致的问题,比如本次的metric线程未启动,或者部分参数没有正常初始化导致。