0
点赞
收藏
分享

微信扫一扫

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

哈哈镜6567 2022-01-25 阅读 58

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

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.考虑是连接池不够大,达到连接池上限,于是调大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内响应了

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

举报

相关推荐

0 条评论