问题描述
最初出现的时候,是在每天的早上8-10这个时间范围内,服务A上的有一个接口时不时报警,内容不一,有
connect timeout
、connect reset
、connect reject
等,其中connect reject
比较频繁。在后续观察中,发现tomcat
的nio
线程一般正常运行下为100
以下,但是在异常重启前一个小时内会飙升至1000
也就是配置的最大线程数。
问题处理
初步分析
线上部署的服务A有4个pod,每台机器的配置是1g。是springboot项目,tomcat配置如下
server:
tomcat:
uri-encoding: UTF-8
accept-count: 1000
max-connections: 2000
max-threads: 1000
min-spare-threads: 10
connection-timeout: 60000
乍一看线程数量有一点多。之后看了一下是不是有问题的接口逻辑,主要交互节点如下
1、接收请求,根据token查缓存获取用户数据
2、feign调用用户服务获取用户信息
3、根据获取的信息查数据库,然后组装结果返回
整体逻辑看着也很简单,feign调用耗时也不是很高。查缓存的话,应该也没有问题,不然就单是一个服务的问题了。那就是查库的问题了,我把执行sql分析了一下,走了索引,表的数据量也不是很大,那是哪一步出问题了。。
http配置即服务整体情况
接口处理时间变长的一种情况是,并发请求太大,导致服务请求处理不过来(如果接口有限流配置那么其实就直接拒掉了,这个服务没有配置)。我在ES上看了一个服务的峰值请求量,秒级不超过一千。异常接口峰值秒级也只有3、4百,分到每台机器上也就100多,1000个线程怎么都处理的过来吧。除非其他接口请求量也大,而且处理时间长,占用了线程。但是我在ES上看了一下接口处理耗时,报警的那一会的确有耗时变长的情况,请求量的确也有所上升。
此外,我看了一个物理机的tcp配置
net.core.somaxcon // 128
net.ipv4.tcp_max_back_log // 1000
这两配置有点小了。
此时,我的推测如下:
1、connect timeout 是因为处理请求不过来
2、connect reset 是因为 http全连接 半连接池太小,被请求占满导致
3、connect reject 服务不可用
经过灰度测试,发现不明显。connect reject 仍出现。
整体排查
服务重启
connect reject出现的原因,理论上是服务寄了。但是怎么能知道它寄没寄呢。突然想到,这个服务有注册到注册中心,也就是eureka。上去一下,没有下线信息,但是报错那个时间点有上线信息。
于是,推测那个时间点是不是服务重启了。看了一下线上服务的日志,发现日志归档了,gc信息也归档了。然后看技术上线记录,发现没人手动上线,于是推测是服务自动重启,然后找运维确定了一下,的确有重启记录。容器默认配置3分钟内5次心跳没通过重启。。
gc
将运行时的gc日志文件分析后,发现gc很频繁。而且full gc后内存下降不是很明显。但是gc停顿时间最长就1.7秒,不可能3秒内都不可用,所以gc有问题,但可能不是主要问题。
CPU
可以看到,使用情况还是挺高的。具体看进行的CPU情况,发现基本是在100%。
// 看进行下哪个线程使用的cpu比较高
top -Hp 进程id
// 10进制 转为 16进制
printf '%x\n' 线程id
// 定位线程的信息 d8为上面转换后的16进制
jstack 进程id | grep '0xd8'
这里拍的有点糊哈,最终定位到是
AsyncReporter 190行代码
,我这里zipkin
版本是2.7.10
,对应的就是flush
节点。
这里服务配置的是zipkin
收集方式是kafka
,大小是默认的1000000
,可以认为是1M
,时间的话配置了60s
’.
然后在线上用
arthas
看了一下方法运行信息
最后推测出可能是
AsyncReporter
第265
行的问题,因为一直没到配置的最大大小(1M),导致一直在死循环。
// ByteBoundedQueue#offer 131行
@Override
public boolean offer(S next, int nextSizeInBytes) {
int x = messageSizeInBytes(nextSizeInBytes);
int y = maxBytes;
int includingNextVsMaxBytes = (x < y) ? -1 : ((x == y) ? 0 : 1); // Integer.compare, but JRE 6
if (includingNextVsMaxBytes > 0) return false; // can't fit the next message into this buffer
addSpanToBuffer(next, nextSizeInBytes);
messageSizeInBytes = x;
if (includingNextVsMaxBytes == 0) bufferFull = true;
return true;
}
// 这里可以看到,只有刚好填充满,bufferFull才可能等于true
// BoundedAsyncReporter#flush()
void flush(BufferNextMessage<S> bundler) {
if (closed.get()) throw new IllegalStateException("closed");
pending.drainTo(bundler, bundler.remainingNanos());
// record after flushing reduces the amount of gauge events vs on doing this on report
metrics.updateQueuedSpans(pending.count);
metrics.updateQueuedBytes(pending.sizeInBytes);
// loop around if we are running, and the bundle isn't full
// if we are closed, try to send what's pending
if (!bundler.isReady() && !closed.get()) return;
// ...省略
}
// 这里的 bundler.isReady() 判断逻辑如下
boolean isReady() {
return bufferFull || remainingNanos() <= 0;
}
// 也就是说,如果时间没到,且没满,那么返回false,此时 flush方法return。这样就开始死循环了,类似while(true)。
// 如果超时时间比较短,例如默认的1s,那其实也能接受。但是这里我们自己改了默认值,配置了60s,
// 也就是说在这一分钟内,如果大小刚好卡死,例如当前buffer使用了950kb,下一个100kb,
// 两者相加不等于1000kb,此时剩余时长都在死循环,CPU自然使用率高了。
修改配置,变为默认值后灰度发布
这里可以看到,明显降低了,使用率基本在1%左右,原先都是10%以上。。后面去看了一下最新版本实现,发现这个bug已经修复了。
可以看到,这里大于最大值后也会认为满了,而不是一定要等于最大值。。
JVM
可以看到,这里的堆使用也不能说有啥大的问题,最多
full gc
有点多吧,相对而言。但是非堆的话,明显感觉有点问题,理论上来说应该是稳定的。它这里有起伏。
后面用
arthas
执行memory
看了一下内存使用情况,发现没设置mataspace
的大小。所以理论上来说它可以无限占用物理机内存。图片可以看到,目前已经用了1.9g了,不太合理。metaspace
主要放的是类的信息,所以推测是不是在运行过程中在动态创建类。dump
线上的堆栈信息,用visualvm
打开。默认是类实例数正向排序的。
这么看其实看不出啥问题,最多会看看类实例多的是不是内存泄露了。但这次我们得反向排序,因为
matespace
异常大,说明类都是不一样的。
这么一看,是不是明显发现问题了。都是
Script_
前缀开头的。本地起一下项目,用arthas
找一下类信息sc -d -n 10 Script_*
这里看到是
aviator
,它是谷歌开发的一个表达式引擎。在代码里全局搜了一下,发现就一个地方在使用,看了一下具体内容,发现是没有开启缓存导致反复创建代码。
改为之后,灰度发布,过一天运行结果
这里可以看到,非堆使用基本稳定了,堆使用也基本平滑了。但是那两次异常GC看着还有点问题。
暂存疑问点
1、最后平稳后的gc原因,是什么触发的。
2、tomcat线程数异常飙升的原因 是因为metaspace没法分配空间导致线程阻塞么。。
3、服务重启的原因 nio处理线程都被阻塞了,导致心跳接口没人处理么。。
总结
启动参数要配全
像gc具体信息、最大mataspace大小、OOMdump等配置参数最好都加上,不然出现问题了手上都没啥资料。。
监控体系健全
有良好的监控,分析问题起来事陪功半。一开始没有cpu、堆等使用的监控图表,光靠脑子想还是太抽象了
科学使用jar包
使用开源jar包,最好自己看一下实现方法,别直接拿来用。不然坑了自己都不知道文章来源:https://www.toymoban.com/news/detail-461079.html
降配参数是参数得动态变
1g内存配了1000个线程,有点不太合理了吧。降配不能单单改内存,其他配置也得一起变化。。。文章来源地址https://www.toymoban.com/news/detail-461079.html
到了这里,关于connect reset/timeout/reject 排查的文章就介绍完了。如果您还想了解更多内容,请在右上角搜索TOY模板网以前的文章或继续浏览下面的相关文章,希望大家以后多多支持TOY模板网!