1.背景

工单系统对于http的请求, 同样的接口, 同样的参数, 偶尔会有请求很慢的情况, 如下图:

image

关键点有3个:

1. 慢的时候基本上都是比正常的请求慢2秒左右(好像是这个规律).
2. 这个跟数据库查询没有关系, 就算是一个空的接口也会有偶尔2秒的请求时间.
3. 本地无法重现这个问题.

问题的影响面为:

1. 所有工单web页面的请求
2. 所有PHP中对于工单dubbo的rest接口调用(商家中心等)

2.分析及解决

2.1 获取debug日志

既然问题不是由业务代码引起的, 那么剩下就是框架问题或者是环境问题.

在毫无头绪的情况下, 首先我想到的是开启debug日志, 从日志中排查.

但是, 大家都知道, debug日志一般是不允许在生产环境开启的, 会极大增加日志文件以及污染正常的业务日志.

在咨询了 @修冶 之后, 打算用开关的方式, 去动态控制debug日志的开启与关闭. 关键代码如下:

    @RequestMapping("/changelog")
    public String changelog(String loggerName, String level){
        LOGGER.info("change log : loggerName={}, level={}", loggerName, level);
        LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
        Logger logger=loggerContext.getLogger(loggerName);
        logger.setLevel(Level.toLevel(level));
        return "success";
    }

并且增加了一段logback的配置:

    <appender name="debugFileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>/opt/domino/logs/domino-debug.log</File>
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%t] %-5p [%C:%line] - %m%n</pattern>
            <charset>UTF-8</charset>
        </encoder>
 
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>/opt/domino/logs/domino-debug.%d{yyyyMMdd}.log</fileNamePattern>
            <maxHistory>7</maxHistory>
        </rollingPolicy>
    </appender>
 
    <root level="INFO">
        <appender-ref ref="debugFileAppender" />
    </root>

注意:

这里我配置的root默认还是INFO, 只不过我可以通过请求动态修改成DEBUG

---

日志开关功能上线之后, 我用curl命令, 直接在一台机器上发起了修改日志级别的请求:

curl "http://localhost:8080/changelog?loggerName=root&level=debug"
curl "http://localhost:8080/changelog?loggerName=org.springframework.amqp.rabbit.listener.BlockingQueueConsumer&level=info"
curl "http://localhost:8080/changelog?loggerName=org.apache.zookeeper.ClientCnxn&level=info"
curl "http://localhost:8080/changelog?loggerName=com.alibaba.dubbo&level=info"

这里说2点:

1. 为什么不在浏览器上请求, 而且在服务器上请求?

因为浏览器请求不知道对应到哪一台服务器, 你必须要去一台一台的确认, 如果服务器多了就搞死了...

2. 为什么修改日志级别需要这么多请求?

其实主要是第一个请求, 修改root的(为了让框架的日志都打出来), 后面那3个, 主要是为了去除干扰项(有一些后台线程定时在跑的日志)

---

到此, 日志级别修改完毕, 接下来就是获取日志.

给应用发起一个正常的http请求(随便什么请求都行), 为了测试方便, 我调用的是healthCheck接口, 因为这个接口没有任务业务逻辑, 直接返回一个字符串.

curl "http://localhost:8080/healthCheck"

调用很多次之后, 出现过2次很慢的响应(都在2秒左右), 其他的几次都是很快.

停止测试之后, 马上把debug日志下载到本地

2.2 分析日志

分析日志的思路:

1. 找到每个请求的完整日志
2. 找到日志时间间隔比较长的请求, 那么这个就是之前的慢请求
3. 分析慢请求的每一行日志, 找出最耗时的步骤

2.2.1 找到每个请求的完整日志

2.2.1.1 http请求日志的第一行

经过本地查看, 发现每个http请求的第一行的格式都是如下:

[2017-12-04 15:04:44.348] [http-nio-8080-exec-1] DEBUG [org.apache.juli.logging.DirectJDKLog:179] - Received [GET /healthCheck HTTP/1.1

其中/healthCheck是请求的URL.

这样我就可以定位到一次http请求日志的第一行, 这一步属于比较简单的.

2.2.1.1 http请求日志的最后一行

如何定位到请求日志的最后一行, 这个比较麻烦.

http请求的最后一行的格式都是如下:

[2017-12-01 17:59:51.327] [http-nio-8080-exec-6] DEBUG [org.apache.juli.logging.DirectJDKLog:179] - Counting down[http-nio-8080-exec-6] latch=3

从上面的日志来看, 完全没有明显的特征表示, 这个日志属于哪个http请求, 也就是说不管你的请求的URL是什么, 最后一行都长这个样子.

并且主要的问题是线上的请求很多, 一段日志中可能穿插着2个以上的http请求日志, 我怎么去确定这一行日志到底是属于哪一个请求.

后来, 我仔细观察了一下日志的格式, 其实日志整体格式可以被拆分这几部分:

[日期时间] [线程名称] 日志级别 [类名:代码行数] - 日志信息

这个地方比较关键的就是[线程名称], 因为同一个http请求中的日志肯定属于同一个线程, 也就是线程名称是保持一致的.

大家可以反过来观察上面的2行日志信息, 就可以得出如下的结论:

image

所以通过上面的这个结论, 继而可以定位到每一个请求的最后一行了.

2.2.2 找到慢请求日志

既然可以定位每一个请求的第一行和最后一行, 那么请求的时间就可以算出来了:

请求时间 = 最后一行日志的时间 - 第一行日志的时间

找到请求时间在2秒左右的就是慢请求日志了, 那么怎么找 ?

这里我没有特别好的办法, 就是靠人肉, 一个请求一个请求的看. 所以之前我也是尽可能在最短时间内收集日志, 为的就是保证信息量相对简短.

可能这里有人会问, 之前不是说每个请求的日志中, 线程名称是保持一致的吗, 那么根据线程名称分个组就行了吧.

这里还有个坑, 就是http请求的线程用的是线程池, 即线程是被复用的, 不能保证每个请求的线程名称都是唯一.

如果有人有更好的过滤办法, 请告知.

2.2.3 整理日志及分析

经过一番人肉之后, 找到了慢请求日志, 单独截取片段, 保存到另一个文件中以便分析.

虽然不能保证每个请求的线程唯一, 但是一次请求的线程肯定就是一个, 那么截取的那段日志中间掺杂着的其他线程的日志我是可以过滤掉的, 这里用到了正则表达式^((?!http-nio-8080-exec-8).)*$

表达式中间那个http-nio-8080-exec-8就是http请求线程的名称, 这个表达式的意思是匹配不包含http-nio-8080-exec-8的日志行, 找出这些行然后替换成空白, 就整理成干净的一次完整请求的日志了, 关键内容如下:

image

经过上面的观察, 我们可以看到有很多次redis连接的open和close, 而最耗时的地方就是最后一次redis的操作, 将近2秒的过程.

那么问题来了, healthCheck接口是没有任何业务逻辑的, 为什么会有redis操作呢 ?

2.3 debug代码

带着上面的疑问, 我开始进入debug阶段. 根据日志中代码行的提示, 我把断点打在了RedisConnectionUtils这个类中.

image

通过观察, 发现这些redis的操作都是和session有关, 于是想到了应该是spring使用了redis来管理session.

再观察了其他的应用, 发现相同位置的断点没有进来, 说明redis管理session的机制应该是配置的, 或者是需要额外添加依赖的.

网上搜了一下, 基本就是2种配置方案, 一种是基于xml的, 一种是基于注解@EnableRedisHttpSession.

接下来就是在代码上搜索一下, 看看有没有相关配置.

最后, 第1种没在代码上找到, 第2种注解的找到了:

image

之前说过, 最耗时的操作是在最后一次redis的open和close之间, 那么理论上只要分析最后一次redis操作的代码运行情况就行了.

image

通过深入debug, 发现最后一次redis的操作是在commitSession的时候, 本来想再调试进去看看, 发现里面代码比较深, 估计短时间应该看不出来, 所以想着先快速解决问题, 后面有时间再分析根本原因.

2.4 修改代码及验证

既然耗时出现在redis管理session的地方, 那么是不是去掉redis管理session的配置, 是不是就可以解决问题?

带着这个思路, 去把原先@EnableRedisHttpSession注解的地方注释掉了, 然后再运行起来看效果.

结果是, 能正常运行, 但是日志上还是出现了多次redis的操作, 应该是有一些默认的配置或者其他的开关.(后来知道这个开关是一个配置项spring.session.store-type=none, 感谢 @冠纯)

这个时候也不想找了, 直接把spring-session这个依赖在pom.xml中去掉.

重启应用, 再次请求, 发现redis的操作已经没有了.

---

接下来就是线上验证

同样还是healthCheck的调用, 快速调用几十次, 没有出现慢的情况.

第二天再次观察原先商家中心慢日志调用情况, 没有发现有工单系统的慢调用.

至此, 问题算是解决了.

3.总结

最终的解决方案是简单的, 而且也不算是找到了根本的原因, 只能说做了一个排除法, 快速绕过了这个问题.

但是整个排查的过程还是遇到了一些问题, 也思考了很多, 希望看到的同学对于以后的故障排查会有所启发.

如果有时间的话, 再去研究一下里面的源码, 看一看究竟是哪一步的问题.

另外还有一个是对于动态修改日志级别的思考:

1. root的debug日志确实不能随便开, 因为包含了所有的日志, 日志量太多了, 目前我已经去掉了.
2. 如果对于线上的问题排查需要临时开放debug日志, 建议指定具体的包或者类, 比如com.beibei.domino.dao这个包设置成debug级别, 这样就会把SQL日志输出, 方便排查问题, 但是排查完之后一定要把日志级别再改回来.
3. 动态修改日志级别的功能, 如果仔细想想, 可以做成通用的功能, 并且可以有一些保护开关, 延时自动关闭debug之类的东西.