场景:
线上一个功能打开日志显示如下,ClientAbortException客户端中止异常,此功能在公司测试环境正常,另外线上的服务都是docker部署的,使用的是动态数据源,微服务库用的mysql库,业务库用的postgreSql库。
Finished to call API:/process/getTaskAndFileBag/cf192870-e1a1-11ed-891a-5a5fd865df76/zb
Elapsed time : 68596 msorg.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe
at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:341)
排查工具:
arthas
现象分析:
发现日志接口响应时间约69s了,而网关gateway中设置的响应时间为60s,超时所以客户端断开了,按理讲此时只要修改gateway客户端响应时间就可了,但是一个简单的接口怎么如此耗时呢?
用arthas追踪了一下接口,发现两个问题。
第一:
用arthas的trace命令显示如下,在对象实例化的时候非常耗时。
第二:
在接口从请求发出到arthas的追踪请求方法的过程中,非常慢!!!大概要1~2分钟才触发arthas
分析:
按理讲一个简单的构造函数怎么会如此耗时呢,根据arthas使用过程中发现的第二个问题,初步定位在网关转发有问题,因为第一个问题在追踪的过程中,内部调用了其它服务的接口,因为网关转发很慢,所以追踪到的接口就非常耗时,那么网关为什么转发的如此慢呢?代码在测试环境是没问题的(网关已经很多地方都在用了,而且还用的很久),所以排除是代码的问题。
配置排查。
cpu排查
top命令发现cpu正常
(注:131785这个进程cpu占比100%,但是网上查阅资料由于占用内存是0,所以对系统的性能是没有影响,项目经理讲这样做是提供cpu利用率)
负载排查:
uptime查看负载,负载最大的是5.39
线上cpu是16核,正常
内存,网络、磁盘IO排查
free -h
iftop
iotop
项目经理图未截取,告诉我正常的。
数据库:
索引,慢查询sql排查
SETGLOBALslow_query_log=’ON’;
SETGLOBALlong_query_time=5;
FLUSHLOGS;
索引和本地测试环境建立的索引一样,且没有生成超过5秒的慢sql.因此结果正常
表死锁排查
SHOWOPENTABLESWHEREIn_use>0;
结论:mysql是表级锁,未查到任何,因此没有锁问题。
SELECTpid,relname,modeFROMpg_locksJOINpg_classONpg_locks.relation=pg_class.oid;
结论:postgresql是行级锁,虽然查到了存在但是与我的业务表没有任何关系,因此没有问题。
数据库的连接数排查
HOWSTATUSWHERE`variable_name`=’Threads_connected’;
注:配置文件中数据库设置的最大连接数200,而线上排查是60,因此正常。
docker stats命令
docker stats这个命令之前排查问题的时候很少使用,因此使用docker部署的服务有时候性能问题可以尝试使用这个命令。
问题原因终于找到了,问了运维在部署gateway和oauth服务内存大小限制在1G,线上内存占用都超过50%那不鸡鸡了!!!!,修改后正常了