首页 > 代码库 > 工作小记——程序卡顿固定时长
工作小记——程序卡顿固定时长
有个问题,困扰我们很久很久很久。甚至每天生产上也会偶然发生几次。最近在测试环境中,更是能在一定压力下必现。那就是程序莫名其妙卡顿,而且时长固定。
截图不是最典型的,10s不到一点。其实大部分都是10s超一点。给人的感觉像是执行了sleep(10000)一样。
应用为
public ResultBean<List<Withdraw>> query(Withdraw tpWithdraw) { List<Withdraw> tpWithdrawQuery = tpWithdrawMapper.query(tpWithdraw); return new ResultBean<List<Withdraw>>(ConstantCode.SUCCESS, tpWithdrawQuery); }
1.
起初考虑,是否SQL语句有问题,导致查询太慢,或者全量数据太多传输耗时。可是反复确认SQL后,是通过主键查询,且数据量很小。而且通过日志可以发现,
是在releasing transactional之后卡顿,即是说是在sql查询处理完后,才卡顿的。
2.
难道是mybatis的问题,难道是releasing transactional释放了10s钟才释放掉?通过代码发现其实releasing transactional之后只做了自减一件事
SqlSessionUtils
if (logger.isDebugEnabled()) { logger.debug("Releasing transactional SqlSession [" + session + "]"); } holder.released();
ResourceHolderSupport
public void released() { this.referenceCount--; }
3.
是不是变量锁等待?并不是……变量和方法都没加锁
ResourceHolderSupport
private int referenceCount = 0;
4.
在这里,我犯了个错误。让测试人员帮忙加两句System.out。可是他忘记加了,而每到卡顿的时候,每次打出“releasing transactional ……”并卡住的时候,我就直接ctrl+c了,为了看上面的日志。
public ResultBean<List<Withdraw>> query(Withdraw tpWithdraw) { List<Withdraw> tpWithdrawQuery = tpWithdrawMapper.query(tpWithdraw); System.out.println("query-end");//查错用日志1 ResultBean<List<Withdraw>> resultBean=new ResultBean<List<Withdraw>>(ConstantCode.SUCCESS, tpWithdrawQuery); System.out.println("new-resultBean-end");//查错用日志2
return resultBean; }
这句没打出来的"query-end",我一直以为是卡住了,其实他压根不存在。
5.
于是我判断,控制权一直在spring和mybatis手上,没有回到应用。悲剧的我,花了很多很多天来研究spring的aop,事务管理,mybatis的代码执行顺序。加了很多很多句日志。
可是每次都是打出最后一句我以为是spring控制权出口的地方再卡住。然后只能继续努力,继续探找更深的出口。直到有一天我发现,测试人员压根没加那句日志……所以我抽空还能谢谢sping还有mybatis相关的一些代码执行顺序,类的调用关系……
6.
于是重新打日志,发现10s是卡在"query-end"与"new-resultBean-end"之间的。又要黑人问号脸.jpg了……new一个ResultBean要耗时这么久?List<Withdraw>数据量也很小。于是在ResultBean里加了一些日志。发现卡住的时候,连构造函数都没进去,构造函数第一句System.out都没打出来
7.
这是怎么回事?问题出在new关键字上?这个问题怎么找???new关键字已经没有JDK代码可以看了,已经是JVM底层的工作了。提到JVM想起了new初始化对象的执行顺序。关注到ResultBean有这么一个成员变量
private String serverName = CommUtil.getHostName();
public static String getHostName() { if (System.getenv("COMPUTERNAME") != null) { return System.getenv("COMPUTERNAME"); } else { return getHostNameForLiunx(); } }
private static String getHostNameForLiunx() { try { return (InetAddress.getLocalHost()).getHostName(); } catch (java.net.UnknownHostException uhe) { String host = uhe.getMessage(); // host = "hostname: hostname" if (host != null) { int colon = host.indexOf(‘:‘); if (colon > 0) { return host.substring(0, colon); } } return "UnknownHost"; } }
简而言之,就是在环境变量里漏掉设置名为“COMPUTERNAME”的环境变量,而导致需要调用InetAddress.getLocalHost()从操作系统处获取
8.
经过一番研究,结果如下:
InetAddress.getLocalHost()操作过程
(1)从/etc/hostname(debian系统)或/proc/sys/kernel/hostname(centos系统)取出hostname
(2)用hostname去/etc/hosts文件中查找IP地址,找到则返回
(3)找不到,则去/etc/resolv.conf中配置的DNS服务器进行查询
(4)默认每个服务器(最多3个)超时时间为5s(/usr/include/resolv.h中RES_TIMEOUT),重试次数为2次(resolv.h中RES_DFLRETRY)
9.
结论(伪)是:
没有设主机名相关的环境变量——》不得不去系统里取——》hostname里配的主机名没有配到hosts文件里去——》去DNS查询——》大压力下DNS失去服务能力——》重试2次,每次超时为5S,总共10S——》程序卡顿10S后继续执行
10.
然而其实现实很残酷,还有如下问题解释不通
(1)经过一段时间的压力后,10S卡顿必现。可是将压力停掉之后,单次请求依然100%出现10S卡顿。这时候DNS应该已经没压力了,为什么无法响应
(2)假设DNS被完全压死,为什么将应用所在的tomcat进程重启,DNS就恢复正常能快速响应呢
(3)应用遇到10S卡顿,符合默认值。可是另外用java调用getLocalHost()遇到的卡顿却是固定5S,只是重试了一次。怎么都无法重新10S卡顿
(4)调整resolv.conf中的option中的timeout与attempts参数。timeout能完全起作用。而attempts的影响却完全找不到规律。比如将attempts设为5,实际的重试次数可能1次,可能2次,可能3次。感觉完全看心情
(5)debian系统里压根找不到resolv.h文件,centos系统里找到resolv.h文件,修改默认配置也没用,应该是因为已经被编译到.so库里了
11.
由于C源码可以看,国内外也基本没这方面的资料,实验了很久依然没有抓到规律。只能将结论(伪)作为最终结论。并增加相关环境变量,修改hosts文件。在应用代码中作缓存。就此作罢
工作小记——程序卡顿固定时长