首页 > 代码库 > 工作小记——程序卡顿固定时长

工作小记——程序卡顿固定时长

有个问题,困扰我们很久很久很久。甚至每天生产上也会偶然发生几次。最近在测试环境中,更是能在一定压力下必现。那就是程序莫名其妙卡顿,而且时长固定。

技术分享

截图不是最典型的,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文件。在应用代码中作缓存。就此作罢

工作小记——程序卡顿固定时长