生产服务间隔6分钟就会有超1S交易的问题排查解决

近期，临近年关，突然线上有业务找，说是某些接口超时超1s，导致用户抢券失败。

因为是多系统多应用总链路时间小于3s，否则就会失败。经过多轮排查，最终加监控等之后，发现我们系统一开始无规律的，每时每刻都有超1s的接口，是所有接口都有超1s的，而且是按交易总量比列分布的。而涉及到调用发券相关的接口由于占总交易比例少，所以每天大概影响1-2笔。

第一步：使用arthas的trace命令查看top4接口的调用耗时。抓到部分接口在连接别的硬件时，会有阻塞，建立socket连接后，在read方法阻塞1-2秒，等待硬件返回。进行优化后，trace不到该阻塞问题了。

但是，还是存在超1s的交易，通过观察单台应用发现每隔6分钟大约就会有超时的，由于我们使用的是mina框架，处理请求的线程设置是150个，使用arthas的thread命令抓取线程阻塞，没有抓到（事后发现是因为阻塞时间太短，手动敲命令后很难抓到，而且间隔6分钟大概才阻塞）。由于是生产再跑的应用，交易量很大，又没法放开debug，只能通过经验进行排除法。

首先，排除是否是有不合理的定时任务，每次6分钟执行，同时执行时可能是锁表等操作引起阻塞，通过查看定时配置和定时的代码，发现确实有俩任务，其中有个任务涉及到加锁操作，但是定时时间是每天执行一次，所以排除掉。

其次，查看是否是GC引起的停顿。通过arthas的监测，发现ygc和频繁，一分钟4-6次，每次耗时很短20-30ms，fullgc次数很少，几乎10多天才一次，一次大概5-6s，排除掉GC的影响。

使用 thread --all  查看所有线程，重点查看TIMED_WAITING状态的线程，发现有

com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run 线程。

通过百度，是C3P0数据库连接池中的类，继续排除法观察。

使用 netstat -anpt |grep '生产数据库IP:端口'|grep '当前应用的pid/java' 命令每隔6分钟记录一次，数据库连接。通过观察发现数据库连接端口会更新，说明有旧连接释放，然后又生成了新的连接对象。而连接池生成新连接这个操作是加锁的操作，会引起阻塞。最后查看相关配置，发现空闲连接释放时间是5分钟，初始连接和最大连接都是80。修改空闲连接时间为0，即不释放空闲连接，长连接，问题解决。