应用发版期间服务响应超时

系统管理员 2022-08-29 05:58 159阅读 0赞

# 描述 #

负责的应用正式环境发版期间，下游应用调用服务告警，查看监控发现这个时间段内偶发下游调用查询接口超时，服务耗时波动如下图：

![在这里插入图片描述][35ad8ee9721147a6ac6f55ea07a736df.png]

并且当应用的所有节点服务发布完成后，偶发的接口超时告警自动恢复，因此盲猜是服务发布时的抖动导致该问题，于是有以下几个猜测：

1.  服务注册发现流程问题：节点下线后未及时从注册中心剔除下线节点，导致下游调用到了下线节点
2.  服务注册发现流程问题：节点上线后先在注册中心注册节点，再开放服务端口，导致中间的时间差服务无响应
3.  资源初始化问题：节点上线后资源未初始化完成，下游调用服务后资源首次初始化耗时长导致服务超时

# 排查 #

每个请求都对应一个唯一的traceId做链路追踪，下游服务调用超时错误日志中对应的traceId为`0be82447162640690309714432565`，找到该请求路由到的具体容器节点后，查看日志发现，应用于2021-07-16 11:41:42启动完成，而超时请求于2021-07-16 11:41:47路由到该节点，也就是节点先启动注册完成后，再出现服务响应超时的情况，因此猜想1排除。

接着排查该节点启动后的接口响应耗时情况，于是查看tracelog目录下rpc-server-digest.log的日志数据，前10条记录如下：

$head -n 10 rpc-server-digest.log
    2021-07-16 11:41:44.727,-,0be8f46916264069044543518ece12,0.1.1.3.8.5,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.232.36.96,-,,,156ms,1ms,SOFA-SEV-BOLT-BIZ-12200-6-T3,00,,,0ms,,CROSS_INVOKE=F&locale=in_ID&abskey=999&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&contextUUID=202107162908810be8f46903m999335b9qps14ci&tenantId=GNETW7CN&
    2021-07-16 11:41:45.933,-,0b44677c162640690583081332085,0.2.7.15,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.36.91.190,-,,,6ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T6,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    2021-07-16 11:41:46.007,-,0be8245a162640690588427692543,0.2.7.51,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.233.58.137,-,,,8ms,1ms,SOFA-SEV-BOLT-BIZ-12200-6-T7,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    2021-07-16 11:41:47.004,-,0b449955162640690509553972138,0.2.7.5,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.36.91.190,-,,,1791ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T5,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    2021-07-16 11:41:47.004,-,0be82447162640690309714432565,0.2.7.30,-.api.ContentManageFacade:1.0,queryContentByIds,,,33.155.229.40,-,,,3737ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T1,02,,,2ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    2021-07-16 11:41:47.007,-,0be93bcf162640690402076042573,0.2.7.4,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.232.36.96,-,,,2900ms,1ms,SOFA-SEV-BOLT-BIZ-12200-6-T2,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    2021-07-16 11:41:47.007,-,0b259e2b162640690475128552587,0.2.7.29,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.233.58.139,-,,,2106ms,1ms,SOFA-SEV-BOLT-BIZ-12200-6-T4,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    2021-07-16 11:41:47.030,-,0b4466d0162640690691812432668,0.2.7.9,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.36.91.174,-,,,2ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T8,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    2021-07-16 11:41:48.202,-,0b449955162640690806458942138,0.2.7.168,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.232.187.43,-,,,4ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T9,00,,,1ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=ms_MY&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    2021-07-16 11:41:48.439,-,0b449955162640690818059192138,0.2.7.156,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.36.91.174,-,,,2ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T10,00,,,1ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=zh_CN&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&

以上几个请求链路均为查询接口，请求的流程图如下：

![在这里插入图片描述][c1c400a2c3fc4198962256029ef48a34.png]

由日志可得，该节点应用启动完成后，前3次服务响应耗时正常，第4-7次的响应耗时明显过长，但从第8次起响应耗时又恢复正常。于是通过以上几个链路的traceId查看每个请求的调用链路情况：

第1次请求直接命中tair缓存，响应耗时正常。

$grep -E 0be8f46916264069044543518ece12 *
    rpc-server-digest.log:2021-07-16 11:41:44.727,-,0be8f46916264069044543518ece12,0.1.1.3.8.5,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.232.36.96,icdpcore,,,156ms,1ms,SOFA-SEV-BOLT-BIZ-12200-6-T3,00,,,0ms,,CROSS_INVOKE=F&locale=in_ID&abskey=999&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&contextUUID=202107162908810be8f46903m999335b9qps14ci&tenantId=GNETW7CN&
    zdal-tair-digest.log:2021-07-16 11:41:44.578,-,0be8f46916264069044543518ece12,0.1.1.3.8.5.1,-,success,6ms,SOFA-SEV-BOLT-BIZ-12200-6-T3,,CROSS_INVOKE=F&locale=in_ID&abskey=999&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&contextUUID=202107162908810be8f46903m999335b9qps14ci&tenantId=GNETW7CN&

第2次请求直接命中堆内缓存，响应耗时正常。

$grep -E 0b44677c162640690583081332085 *
    rpc-server-digest.log:2021-07-16 11:41:45.933,-,0b44677c162640690583081332085,0.2.7.15,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.36.91.190,icdpcore,,,6ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T6,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&

第3次请求直接命中堆内缓存，响应耗时正常。

$grep -E 0be8245a162640690588427692543 *
    rpc-server-digest.log:2021-07-16 11:41:46.007,-,0be8245a162640690588427692543,0.2.7.51,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.233.58.137,icdpcore,,,8ms,1ms,SOFA-SEV-BOLT-BIZ-12200-6-T7,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&

第4次请求缓存命中失败，请求数据库查询，数据库执行耗时超长。

$grep -E 0b449955162640690509553972138 *
    rpc-profile.log:2021-07-16 11:41:47.003,-,0b449955162640690509553972138,0.2.7.5,,调用SOFA的TR服务[-.api.ContentManageFacade:1.0]:方法为[queryContentByIds]耗时[1,790]ms，发起请求的地址为：[11.36.91.190].
    rpc-server-digest.log:2021-07-16 11:41:47.004,-,0b449955162640690509553972138,0.2.7.5,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.36.91.190,icdpcore,,,1791ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T5,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    zdal-db-digest.log.2021-07-16_11:2021-07-16 11:41:46.971,-,0b449955162640690509553972138,0.2.7.5.2,-,-.-,,SELECT,select id%2C gmt_create%2C gmt_modified%2C tenant_id%2C bu_code%2C env%2C content_id%2C src_status%2C gmt_begin%2C gmt_end%2C content_type%2C content_source%2C content_channel%2C relation_id%2C biz_gmt_modify%2C title%2C title_desc%2C timezone %2C category%2C content_tags%2C src_ext_info%2C ext_info%2C artificial_tags from cc_content_lib WHERE ( env = ? and content_id in ( ? %2C ? ) and src_status in ( ? ) ),success,1751ms,SOFA-SEV-BOLT-BIZ-12200-6-T5,OB_CLOUD,,1710ms,10ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&

第5次请求缓存命中失败，请求数据库查询，数据库执行耗时超长。

$grep -E 0be82447162640690309714432565 *
    rpc-server-digest.log:2021-07-16 11:41:47.004,-,0be82447162640690309714432565,0.2.7.30,-.api.ContentManageFacade:1.0,queryContentByIds,,,33.155.229.40,icdpcore,,,3737ms,0ms,SOFA-SEV-BOLT-BIZ-12200-6-T1,02,,,2ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    zdal-db-digest.log.2021-07-16_11:2021-07-16 11:41:46.971,-,0be82447162640690309714432565,0.2.7.30.2,-,-.-,,SELECT,select id%2C gmt_create%2C gmt_modified%2C tenant_id%2C bu_code%2C env%2C content_id%2C src_status%2C gmt_begin%2C gmt_end%2C content_type%2C content_source%2C content_channel%2C relation_id%2C biz_gmt_modify%2C title%2C title_desc%2C timezone %2C category%2C content_tags%2C src_ext_info%2C ext_info%2C artificial_tags from cc_content_lib WHERE ( env = ? and content_id in ( ? ) and src_status in ( ? ) ),success,3197ms,SOFA-SEV-BOLT-BIZ-12200-6-T1,OB_CLOUD,,3132ms,10ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    zdal-tair-digest.log:2021-07-16 11:41:43.532,-,0be82447162640690309714432565,0.2.7.30.1,-,success,23ms,SOFA-SEV-BOLT-BIZ-12200-6-T1,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&

第6次请求缓存命中失败，请求数据库查询，数据库执行耗时超长。

$grep -E 0be93bcf162640690402076042573 *
    rpc-profile.log:2021-07-16 11:41:47.005,-,0be93bcf162640690402076042573,0.2.7.4,,调用SOFA的TR服务[-.api.ContentManageFacade:1.0]:方法为[queryContentByIds]耗时[2,898]ms，发起请求的地址为：[11.232.36.96].
    rpc-server-digest.log:2021-07-16 11:41:47.007,-,0be93bcf162640690402076042573,0.2.7.4,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.232.36.96,icdpcore,,,2900ms,1ms,SOFA-SEV-BOLT-BIZ-12200-6-T2,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    zdal-db-digest.log.2021-07-16_11:2021-07-16 11:41:46.971,-,0be93bcf162640690402076042573,0.2.7.4.2,-,-.-,,SELECT,select id%2C gmt_create%2C gmt_modified%2C tenant_id%2C bu_code%2C env%2C content_id%2C src_status%2C gmt_begin%2C gmt_end%2C content_type%2C content_source%2C content_channel%2C relation_id%2C biz_gmt_modify%2C title%2C title_desc%2C timezone %2C category%2C content_tags%2C src_ext_info%2C ext_info%2C artificial_tags from cc_content_lib WHERE ( env = ? and content_id in ( ? %2C ? %2C ? ) and src_status in ( ? ) ),success,2856ms,SOFA-SEV-BOLT-BIZ-12200-6-T2,OB_CLOUD,,2815ms,10ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&

第7次请求缓存命中失败，请求数据库查询，数据库执行耗时超长。

$grep -E 0b259e2b162640690475128552587 *
    rpc-profile.log:2021-07-16 11:41:47.005,-,0b259e2b162640690475128552587,0.2.7.29,,调用SOFA的TR服务[-.api.ContentManageFacade:1.0]:方法为[queryContentByIds]耗时[2,104]ms，发起请求的地址为：[11.233.58.139].
    rpc-server-digest.log:2021-07-16 11:41:47.007,-,0b259e2b162640690475128552587,0.2.7.29,-.api.ContentManageFacade:1.0,queryContentByIds,,,11.233.58.139,icdpcore,,,2106ms,1ms,SOFA-SEV-BOLT-BIZ-12200-6-T4,00,,,0ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&
    zdal-db-digest.log.2021-07-16_11:2021-07-16 11:41:46.971,-,0b259e2b162640690475128552587,0.2.7.29.2,-,-.-,,SELECT,select id%2C gmt_create%2C gmt_modified%2C tenant_id%2C bu_code%2C env%2C content_id%2C src_status%2C gmt_begin%2C gmt_end%2C content_type%2C content_source%2C content_channel%2C relation_id%2C biz_gmt_modify%2C title%2C title_desc%2C timezone %2C category%2C content_tags%2C src_ext_info%2C ext_info%2C artificial_tags from cc_content_lib WHERE ( env = ? and content_id in ( ? %2C ? %2C ? ) and src_status in ( ? ) ),success,2065ms,SOFA-SEV-BOLT-BIZ-12200-6-T4,OB_CLOUD,,2024ms,10ms,,mpaas=tenant:TSCPDICN%26workspace:default&tenantId=GNETW7CN&locale=en_US&FC_EVENT_CONTEXT={"tntInstId":"GNETW7CN"}&

很明显超时的原因是因为缓存命中失败后请求数据库查询而导致，但排查后续中的链路即使出现查询数据库也未出现服务响应耗时过长的情况，因此怀疑是数据库连接未初始化的问题：应用刚启动完成后，请求查询数据库前需要额外请求ZDAL初始化相关配置并且创建数据库连接，导致的耗时超长的情况。

咨询同事后得知应用在DDS上已经配置开启了数据库连接预热，于是去DDS上查看该配置说明：是否预热最小连接数。然后再查看连接池配置，发现当前的连接池配置的最小连接数为0。也就是说应用启动时预热了个寂寞，导致应用启动后数据库连接池数量为0，当请求到该应用后前几次请求均需要创建新数据库连接因而耗时较长，而后续请求直接复用连接池连接因此后续请求处理耗时恢复正常。

# 解决 #

DDS平台修改应用的连接池配置，最小连接数从0修改为5，保证应用在启动完成后数据库连接池已经初始化完成。等待下次应用迭代发布时监控新发布应用的请求耗时情况。

[35ad8ee9721147a6ac6f55ea07a736df.png]: /images/20220829/47290e6cb2634bfb95fd9fe128ebf9da.png
[c1c400a2c3fc4198962256029ef48a34.png]: /images/20220829/8dbdf0a505f64e689a861b49a18be5d7.png