现象

线上服务在线推理接口出现跳点问题，秒级监控可以发现TP99每半小时会出现10次左右的跳点，而且是正常耗时的20倍左右

TP99Jump01
TP99Jump01

下游特征服务也出现接口跳点的问题，但可以看出有些跳点在出现的时间点以及TP99是和推理接口的跳点能对应上的

TP99Jump02
TP99Jump02

分析各个环节监控粗略看出推理服务自身和离线特征服务都带来了一些跳点问题。

问题排查

排查思路

排查思路不能乱，对于某些请求响应慢，可能是以下原因：

  1. 是否有 GC 导致的长时间 STW
  2. 是否 IO 花了太长时间（磁盘IO、网络IO）
  3. 是否 CPU占用过高导致的
  4. 是否线程池配置不合理，由于流量突增导致任务在阻塞队列中等待的情况
  5. 是否存在锁竞争导致长时间等待

一、是否有 GC 导致的长时间 STW

通过JVM相关的监控可以看到整体堆内存的使用率是正常的，Young GC的频率很低，整体GC时间也比较短，而且每次也能触发堆的正常回收，并没有能严重影响线程 STW 很长时间的情况。

TP99Jump03
TP99Jump03

二、是否 IO 花了太长时间（磁盘IO、网络IO）

通过MDC监控排查磁盘相关的指标，也是正常的。

TP99Jump04
TP99Jump04

留意到写磁盘的等待时间和出现跳点的时间、耗时是能吻合上的，但整体推理接口涉及到写磁盘的动作只有日志，而日志配置了异步Logger，先跳过看看有没有其他问题。
TP99Jump05
TP99Jump05

对于特征服务来说网络IO只有查询Jimdb特征数据产生的，但通过ump监控看也是正常的。
TP99Jump06
TP99Jump06

三、是否 CPU占用过高导致的

对应时间内CPU使用率很低、很稳定。

TP99Jump07
TP99Jump07

四、是否线程池配置不合理，由于流量突增导致任务在阻塞队列中等待的情况

特征服务中是没有使用线程池的，而对于增值服务来说，阻塞队列长度是100比较合理，而且对线程池阻塞队列容量进行埋点，也是没有出现大规模任务进入队列的情况。

五、是否存在锁竞争导致长时间等待

由于TP99响应时间异常只有短暂的一两秒，一、我们并不能通过JStack来分析产生线程阻塞的原因；二、由于Pfinder的采样规则，能抓取调用链路也比较少，在艰难的抓取到一次调用异常的请求后也由于记录节点比较少（没有显示的埋点下只有JSF Consumer、JSF Provider、JSON、Jimdb等），没有留下有价值的信息

后来发现一个工具：Java Flight Recorder，可以记录被阻塞的线程信息，更容易定位到问题，但对接口性能会有损耗，可以在定位线上问题使用。
https://skyscribe.github.io/post/2017/08/22/performance-tuning-with-java-flight-recorder/

定位

整体看下来，和跳点相关的问题比较吻合的是磁盘的等待时间。只能在从日志配置中仔细看看能不能发现点蛛丝马迹了。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="3600">

    <Appenders>
        <!-- 文件输出 -->
        <RollingRandomAccessFile name="file" fileName="${LOG_HOME}/${LOG_FILE_NAME}"
                                 filePattern="${LOG_HOME}/${BACKUP_LOG_FILE_NAME}}"
                                 bufferSize="2048" immediateFlush="false" append="true" >
            <!-- 控制台只输出level及以上级别的信息(onMatch),其他的直接拒绝(onMismatch) -->
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <!-- 输出日志的格式 -->
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS}[%-5level]%m[%C.%M:%L][%X{traceKey}]- %X{PFTID}%n" />
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
            </Policies>
            <DefaultRolloverStrategy max="8" />
        </RollingRandomAccessFile >
    
        <RollingFile name="error" fileName="${LOG_HOME}/${ERROR_LOG_FILE_NAME}"
                     filePattern="${LOG_HOME}/${BACKUP_ERROR_LOG_FILE_NAME}}">
            <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS}[%-5level]%m[%C.%M:%L][%X{traceKey}]- %X{PFTID}%n"/>
            <SizeBasedTriggeringPolicy size="500MB"/>
            <DefaultRolloverStrategy max="8" />
        </RollingFile>
    
        <!-- AB分流日志文件输出 -->
        <RollingRandomAccessFile name="abTestFile" fileName="${ABTEST_LOG_HOME}/${ABTEST_LOG_FILE_NAME}"
                                 filePattern="${ABTEST_LOG_HOME}/${ABTEST_BACKUP_LOG_FILE_NAME}}"
                                 bufferSize="1024" immediateFlush="false" append="true" >
            <!-- 控制台只输出level及以上级别的信息(onMatch),其他的直接拒绝(onMismatch) -->
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <!-- 输出日志的格式 -->
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{PFTID}] %-5level %logger{36} %F:%L - %msg %ex%n" />
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
            </Policies>
            <DefaultRolloverStrategy max="8" />
        </RollingRandomAccessFile >
    
        <!-- AB分流结果日志文件名称 -->
        <RollingRandomAccessFile name="abTestRouteResultFile" fileName="${ABTEST_LOG_HOME}/${ABTEST_ROUTE_RESULT_LOG_FILE_NAME}"
                                 filePattern="${ABTEST_LOG_HOME}/${ABTEST_ROUTE_RESULT_BACKUP_LOG_FILE_NAME}}"
                                 bufferSize="1024" immediateFlush="false" append="true" >
            <!-- 控制台只输出level及以上级别的信息(onMatch),其他的直接拒绝(onMismatch) -->
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <!-- 输出日志的格式 -->
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{PFTID}] %-5level %logger{36} %F:%L - %msg %ex%n" />
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
            </Policies>
            <DefaultRolloverStrategy max="8" />
        </RollingRandomAccessFile >
    
        <!-- 算法计算结果日志文件名称 -->
        <RollingRandomAccessFile name="abTestPredictResultFile" fileName="${ABTEST_LOG_HOME}/${ABTEST_PREDICT_RESULT_LOG_FILE_NAME}"
                                 filePattern="${ABTEST_LOG_HOME}/${ABTEST_PREDICT_RESULT_BACKUP_LOG_FILE_NAME}}"
                                 bufferSize="1024" immediateFlush="false" append="true" >
            <!-- 控制台只输出level及以上级别的信息(onMatch),其他的直接拒绝(onMismatch) -->
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <!-- 输出日志的格式 -->
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{PFTID}] %-5level %logger{36} %F:%L - %msg %ex%n" />
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
            </Policies>
            <DefaultRolloverStrategy max="8" />
        </RollingRandomAccessFile >
    
        <!-- 算法包内部日志输出文件 -->
        <RollingRandomAccessFile name="algoPkgFile" fileName="${ALGO_PKG_LOG_HOME}/${ALGO_PKG_LOG_FILE_NAME}"
                                 filePattern="${ALGO_PKG_LOG_HOME}/${ALGO_PKG_BACKUP_LOG_FILE_NAME}}"
                                 bufferSize="1024" immediateFlush="false" append="true" >
            <!-- 控制台只输出level及以上级别的信息(onMatch),其他的直接拒绝(onMismatch) -->
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <!-- 输出日志的格式 -->
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{PFTID}] %-5level %logger{36} %F:%L - %msg %ex%n" />
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
            </Policies>
            <DefaultRolloverStrategy max="8" />
        </RollingRandomAccessFile >
    
        <OnlineServingLogAppender name="onlineServingLogAppender">
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS}[%-5level]%m[%C.%M:%L][%X{traceKey}]- %X{PFTID}%n" />
        </OnlineServingLogAppender>
    
    </Appenders>
    
    <Loggers>
        <!-- 自定义AB分流日志 -->
        <AsyncLogger name="ccom.jdl.shenji.sdk.ab.impl.AbRoutingFacadeImpl" level="INFO" additivity="false">
            <appender-ref ref="abTestFile" />
        </AsyncLogger>
        <!-- 预测结果日志 -->
        <AsyncLogger name="com.jdl.shenji.sdk.ab.impl.AbRoutingDetailSaveServiceImpl" level="INFO" additivity="false">
            <appender-ref ref="abTestPredictResultFile" />
        </AsyncLogger>
        <!-- AB分流结果日志 -->
        <AsyncLogger name="com.jdl.shenji.sdk.ab.impl.AbRoutingRespSaveServiceImpl" level="INFO" additivity="false">
            <appender-ref ref="abTestRouteResultFile" />
        </AsyncLogger>
        <!-- 算法包内部日志 -->
        <AsyncLogger name="algoPkgLogger" level="INFO" additivity="false">
            <appender-ref ref="algoPkgFile" />
        </AsyncLogger>


        <!-- 在线推理调用日志 -->
        <logger name="com.jdl.shenji.sdk.predict" level="debug" additivity="true">
            <appender-ref ref="onlineServingLogAppender" />
        </logger>
        <logger name="com.jdl.shenji.sdk.ab" level="debug" additivity="true">
            <appender-ref ref="onlineServingLogAppender" />
        </logger>
        <logger name="com.jdl.shenji.plugin" level="debug" additivity="true">
            <appender-ref ref="onlineServingLogAppender" />
        </logger>
    
        <Asyncroot level="info">
            <appender-ref ref="file"/>
            <appender-ref ref="error"/>
        </Asyncroot>
    
    </Loggers>

</Configuration>

借助网上一张图片介绍一下Log4j2使用Disruptor的RingBuffer进行异步日志打印的流程。当Appender的日志消费速度跟不上日志的生产速度，且Disruptor的RingBuffer已满时，指定如何处理尚未正常打印的日志事件，默认为阻塞（Default），这可能就是磁盘写入等待的原因了。

TP99Jump08
TP99Jump08

问题处理

针对上述可能产生跳点的问题，我们采用将队列容量调大了一点，而且配置了不阻塞的策略。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="3600">

    <Appenders>
        // ...
    
    </Appenders>
    
    <Loggers>
        <!-- 自定义AB分流日志 -->
        <AsyncLogger name="ccom.jdl.shenji.sdk.ab.impl.AbRoutingFacadeImpl" level="INFO" additivity="false">
            <appender-ref ref="abTestFile" />
    		<AsyncQueueFullPolicy>Discard</AsyncQueueFullPolicy>
    		<bufferSize>256</bufferSize>
        </AsyncLogger>
        <!-- 预测结果日志 -->
        <AsyncLogger name="com.jdl.shenji.sdk.ab.impl.AbRoutingDetailSaveServiceImpl" level="INFO" additivity="false">
            <appender-ref ref="abTestPredictResultFile" />
    		<AsyncQueueFullPolicy>Discard</AsyncQueueFullPolicy>
    		<bufferSize>256</bufferSize>
        </AsyncLogger>
        <!-- AB分流结果日志 -->
        <AsyncLogger name="com.jdl.shenji.sdk.ab.impl.AbRoutingRespSaveServiceImpl" level="INFO" additivity="false">
            <appender-ref ref="abTestRouteResultFile" />
    		<AsyncQueueFullPolicy>Discard</AsyncQueueFullPolicy>
    		<bufferSize>256</bufferSize>
        </AsyncLogger>
        <!-- 算法包内部日志 -->
        <AsyncLogger name="algoPkgLogger" level="INFO" additivity="false">
            <appender-ref ref="algoPkgFile" />
    		<AsyncQueueFullPolicy>Discard</AsyncQueueFullPolicy>
    		<bufferSize>256</bufferSize>
        </AsyncLogger>


        <!-- 在线推理调用日志 -->
        <logger name="com.jdl.shenji.sdk.predict" level="debug" additivity="true">
            <appender-ref ref="onlineServingLogAppender" />
        </logger>
        <logger name="com.jdl.shenji.sdk.ab" level="debug" additivity="true">
            <appender-ref ref="onlineServingLogAppender" />
        </logger>
        <logger name="com.jdl.shenji.plugin" level="debug" additivity="true">
            <appender-ref ref="onlineServingLogAppender" />
        </logger>


        <Asyncroot level="info">
            <appender-ref ref="file"/>
            <appender-ref ref="error"/>
    		<AsyncQueueFullPolicy>Discard</AsyncQueueFullPolicy>
    		<bufferSize>512</bufferSize>
        </Asyncroot>
    
    </Loggers>

</Configuration>

调整日志配置后线上服务跳点问题得到解决，TP99基本稳定在50ms以下。

TP99Jump09
TP99Jump09

总结

排查时间比较长的问题是对于这种跳点，我们线上没有很好的工具很难抓到问题，预发压测也比较难复现。关于磁盘问题一开始也是有考虑过，观察了磁盘使用率和磁盘繁忙这两个比较基础的指标，没有发现问题。京东泰山平台有个健康度功能，里面会扫出来哪些监控配置的不完善，对于“平均每次设备I/O操作的等待时间”有提示的，但可能不是高危，我们会忽视这个问题，后续我们可以深入了解有哪些监控配置，做一个分享，确认一下哪些监控配置是需要加上的。