记一次服务器响应慢问题的排查

这次问题查了一个星期，期间有点紧张，慌得一比，确定问题原因之前都是懵的。

1.发现日志里面有mysql连接超时（Communications link failure，The last packet sent successfully to the server was 0 milliseconds ago. Caused by: java.net.ConnectException: Connection timed out）的情况；

2.发现有的请求花了6s，有的花了12s，有的15s超时报异常；
3.baidu搜了一番没什么结果，到“MySQL技术大牛群”QQ群里咨询，大牛们各种说法都有

 

 

 

考虑是连接池不够大，达到连接池上限，于是调大resin数据源连接池上限配置，从20调到50；查数据库慢日志，发现没有业务查询的记录

4.问题仍然存在，想分析日志，没有找到能用的工具，于是自己写java程序分析日志，统计连接请求时间分布，发现91%在1s内响应，有部分1-2s，有部分3s，有部分6s，有部分12s，很有规律，1.5->3->6->12，成倍增长，其它响应时间的很少

接口主要的开始和结束日志是这种格式：

2022-01-19 08:09:32,469 INFO   -[http://*:8080-4] - [AgentController] requestId=xxxx,进入AgentController的loginAndCall()方法，参数：{"agentId":"","ani":"2","dn":"xxxx","number":"xxxx","requestId":"xxxx","um":"xxxx"}

2022-01-19 08:09:32,499 INFO   -[pool-1-thread-1] - [AgentController] requestId=xxxx,强制登录----start

分析代码如下，用了正则表达式提取关键信息

public static void main(String[] args) throws ParseException {
        List<String> list = readFile("E:\\Document\\CRM\\CDesk\\2022年1月\\日志0124\\AgentController59-0124.log");
        Pattern pattern = Pattern.compile("(.*) INFO.*http.*AgentController.*requestId=(.*?),.*|(.*) INFO.*AgentController.*requestId=(.*?),.*强制登录.*start.*");
        Map<String, List<String>> requestIdMap = new LinkedHashMap<String, List<String>>();
        for (String s : list) {
            Matcher matcher = pattern.matcher(s);
            if (matcher.find()) {
                String time = matcher.group(1);
                String requestId = matcher.group(2);
                if (time == null) {
                    time = matcher.group(3);
                    requestId = matcher.group(4);
                }
                List<String> timeList = requestIdMap.get(requestId);
                if (timeList == null) {
                    timeList = new ArrayList<String>();
                    timeList.add(time);
                    timeList.add(time);
                    requestIdMap.put(requestId, timeList);
                }
                if (timeList.get(1).compareTo(time) < 0) {
                    timeList.set(1, time);
                }
                //System.out.println(matcher.group(1) + "\t" + matcher.group(2));
            }
        }
        List<Long> statistic = new ArrayList<Long>();
        for (int i = 0; i < 50; i++) {
            statistic.add(0L);
        }
        for (String requestId : requestIdMap.keySet()) {
            List<String> timeList = requestIdMap.get(requestId);
            SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss,SSS");
            Date begin = sdf.parse(timeList.get(0));
            Date end = sdf.parse(timeList.get(1));
            long diff = (end.getTime() - begin.getTime()) / 1000;
            int interval = (int) diff;
            if (interval > 6) {
                System.out.println(requestId + " " + diff);
            }
            statistic.set(interval, 1 + statistic.get(interval));
        }
        //System.out.println(statistic);
        long sum = 0;
        for (int i = 0; i < 50; i++) {
            System.out.println(i + "s 请求数" + statistic.get(i));
            sum += statistic.get(i);
        }
        System.out.println(sum);
    }

5.考虑数据库连接池50还是不够，获取连接池可能有间隔时间递增的算法，于是把连接池从50调到500；
6.问题仍然存在，没有办法，考虑网络问题。对程序所在机器进行数据库端口3306的抓包；
7.抓包文件中出现大量TCP Retransmission，有的重传6次才成功得到响应，正好花了6s；每次重传间隔时间倍增；

8.网络组最后排查网络问题，查到是keepalive的id重了，于是解决了网络问题，再分析日志，已经正常了，一天内两个实例的10979个http请求中只有1个超过了1s，其他都在1s内响应了

总结：愚以为网络问题是找不到问题真正原因时用来搪塞的借口，所以一直没有想到去抓包查网络问题，浪费了几天时间，没想到真是网络问题。