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

Posted 2020-09-17

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

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