引言
生产环境不出问题时像只小绵羊一样温顺可爱,左手一杯coffee右手熟练敲击键盘输出日志丝滑平稳,对于一闪而过的warn警告丝毫不慌,心想肯定是哪个下饭同事写了一个下饭的BUG.时间过去两三分钟,突然发现负载的四台服务器日志有两台突然不动了,直觉告诉我这不是个好兆头,果然几秒后就收到了接口超时预警,打开客户端发现请求接口出现概率超时.在确认另外两台没有问题后,我及时从负载均衡中下掉了这两台假死的服务器并替换上两台临时服务器,启动客户端发现一切正常才暂时放下心.屏气凝神准备看看究竟是什么导致发生服务宕机现象.
排查
排错指南
排查路线1
公司买的是阿里云的服务器组,那么排查方向我就先从服务器的监控上去寻找端倪.打开监控发现出问题的那个时间段处于用户活跃时间,系统负载和ECS同时连接数指标明显处于峰值,因此初步判断应该和这两组异常数据有关.
排查路线2
打开ssh工具分别连接这两台服务器.首先输入命令netstat -ntlp |grep java,查询该服务器中所有部署的java服务
[root ~]# netstat -ntlp |grep java
tcp 0 0 0.0.0.0:8088 0.0.0.0:* LISTEN 11772/java
tcp 0 0 0.0.0.0:33880 0.0.0.0:* LISTEN 21705/java
tcp 0 0 0.0.0.0:8091 0.0.0.0:* LISTEN 619/java
tcp 0 0 0.0.0.0:45661 0.0.0.0:* LISTEN 21705/java
tcp 0 0 0.0.0.0:11110 0.0.0.0:* LISTEN 16039/java
tcp 0 0 0.0.0.0:11112 0.0.0.0:* LISTEN 16039/java
tcp 0 0 0.0.0.0:9099 0.0.0.0:* LISTEN 21705/java
tcp 0 0 0.0.0.0:8080 0.0.0.0:* LISTEN 10901/java
tcp 0 0 0.0.0.0:8082 0.0.0.0:* LISTEN 21705/java
tcp 0 0 172.18.234.25:39892 0.0.0.0:* LISTEN 619/java 发现并无异常,我们的8080服务还在线程运行中.可排查服务异常终止导致请求超时的情况
排查路线3
既然服务没有异常终止,那说明服务目前处于假死状态.开放8080端口打开日志并用本地postman请求这台服务器,发现请求全都是挂起状态.日志也还是无输出的情况.突然想到也许是连接数过多导致的服务异常.用命令 netstat -n | grep tcp | grep 8080 | wc -l,查询8080端口的TCP线程数.
[root@www ~]# netstat -n | grep tcp | grep 8080 | wc -l
1500果然问题出现在这里,这个线程数偏高了,我们用的springboot内置的tomcat,默认程序线程最大为200,连接数最大10000.因为用户量的增大,之前用配置优化过这个参数,把最大线程数调到了1500,连接数没有调,配置如下,这边暂时只调整了max-threads,其他配置供大家参考
application.yml文件
# Tomcat
server:
tomcat:
uri-encoding: UTF-8
#最小线程数
min-spare-threads: 500
#最大线程数
max-threads: 1500
#最大连接数
max-connections: 10000
#最大等待队列长度
accept-count: 1000
#请求头最大长度kb
max-http-header-size: 1048576
#请请求体最大长度kb
max-http-post-size: 2097152
#服务http端口
port: 8080
#链接建立超时时间
connection-timeout: 12000 但是这个指数明显处于峰值,因为这两台服务器已经停止访问了,所以可以排除是恶意攻击的问题.如果是恶意攻击也可用
- netstat -n | grep tcp | grep 8080,查看8080端口的实际调用ip
- netstat -na | grep 8080| grep ESTABLISHED | awk '{print$5}' | awk -F : '{print$1}' | sort | uniq -c | sort -r,查看现成开销最多的ip
这里先不进行扩展了.经过这一轮的排查,我们就能排除恶意攻击和tomcat配置不当的情况
排查路线4
经过上面3轮排查,我们最终定位到我们自己程序的问题,灵光一闪,刚才在看日志的时候出现warn日志,是不是因为他导致的问题呢?用cat|grep定位到warn日志的日志点,发现这个问题还挺频繁出现的,直觉告诉我应该就是这里的问题.通过warn日志定位到具体问题的行数.伪代码如下
//查询各平台相似商品
public ResponseResult similarGoodsRecommend(String goodsId) {
CountDownLatch latch = new CountDownLatch(3);
//查询出淘宝相似商品
ThreadPool.getInstance().addCachedThread(()->{
......
latch.countDown(); //错误在定位在这个位置
}
//查询出京东相似商品
ThreadPool.getInstance().addCachedThread(()->{
......
latch.countDown();
}
//查询出拼多多相似商品
ThreadPool.getInstance().addCachedThread(()->{
.....
latch.countDown();
}
try {
latch.await();
} catch (InterruptedException e) {
e.printStackTrace();
}
//处理结果
......
}
破案了,问题就出在CountDownLatch计数器的使用方法上,这个方法原本是依次查询,但是因为都是第三方API调用,所以速率很差,所以做了改良用三个线程去跑这个任务,然后用每完成一个查询任务就在计数器上-1,latch.await();直到计数器清零才会去执行数据合并返回结果.但是需要考虑到计数器如果在查询API过程中出现错误,计数器就永远不会减1,导致latch.await()会一直等待,然后该接口线程就会一直处于挂起状态,如果峰值超过tomacat1500最大线程数,程序就会呈现假死状态.简单的处理了一下这部分代码.
ThreadPool.getInstance().addCachedThread(()->{
try{
........
}catch (Exception e){
log.error("淘宝相似商品查询失败:",e);
}finally {
//在finally块中执行计数器的减1操作,能保证该API即使报错也可减少计数,不影响后面的聚合操作和latch.await()等待.
latch.countDown();
}
}
把业务处理模块用try/catch包裹起来,把计数器的减法操作放入finally块中,这样即使报错也会减计数器的计数值,latch.await()就不会一直处于等待状态了,等处理完后面的结果返回,线程就会被释放.
思考总结
关于代码 : 在一些耗时的多步操作中,我们可以使用多线程进行分线处理,执行效率会得到优化,但是需要注意的是线程的创建和释放问题,要多考虑意外情况,不要让程序线程死锁,等待的问题.1.8jdk也开放了CompletableFuture工具类,也可实现这种异步然后归并的操作,处理比计数器的方式更加友好.
关于排错 : 生产环境上的BUG排查是一个耐心的过程,我们要通过一点点的线索去解锁这个问题的根源,所以出现生产环境问题,最好是有备选服务器支撑服务,然后再通过监控,日志等手段去排查.
一些建议 :
- 在一些关键位置打上合理的日志,异常输出ERROR,可能报错的关键点尽量也打上WARN日志,这次的BUG就是日志立了大功.
- java程序员也需要多了解一些运维知识,一方面扩充我们的知识面,一方面在遇到问题时,我们也不至于没有排查思路.
- 代码规范问题老生常谈,把写代码当做职业也当做爱好,不要只是为了业务实现,要有一颗追求完美的心,能够把程序做到相对完美才是最优解.
最后祝大家少出BUG,少掉头发,健康生活.