调用机构在线接口超时问题根因排查

一、问题概述

   2023年07月某日，线上服务A请求机构在线接口超时且连接未断开，导致对应服务线程资源被占用；从而影响外部机构和内部系统对本系统的访问，最终导致在线业务成功率跌0。

    线上服务A请求浦发超时表现现象：

           1）请求浦发接口耗时突增，最大达到：455秒，但是可以同步获取到机构的响应数据。

            2）服务现场打满，导致服务暂时不能对外提供服务，导致在线业务成功率跌0。

            3）OP侧排查机构流量请求到Nginx转发层，接入层504错误码突增。

图一：线程数突增：

图二：接入层504错误码突增：

二：根因分析

结论：系统A因http 连接池配置问题导致在机构超时情况下无法从http连接池中实时获取到连接，请求下游排队导致服务线程长时间占用，服务线程逐步被打满。

1. 问题分析：网络链路方向排查

1.1  系统A请求机构接口交互链路：

 1.2 排查链路：

 1. 2022年4月份 线上出现过故障【北京联通网络异常导致网络耗时突增问题】。

       本次出现故障首先排查：是否由于网络问题，导致一直有数据包回传，导致超时时间不生效。PS:目前设置httpClient组件中超时时间（socketTimeOut）参数含义是：数据传输过程中数据包之间最大间隔时间，超过后才会断开连接。

      1）验证：一直有数据包回传，是否超时时间确实无法生效？

            验证步骤：测试环境，设置接口超时时间25秒，服务端在每20秒内返回一次数据。

            发现：有数据包回传，连接确实无法断开。

2. 但是正常情况下，浦发侧不会在每个超时时间内，一直不间断返回数据包。故怀疑网络层面是否有数据包回传现象，导致连接无法断开。

         1）验证：网络层面是否有回包现象？

              验证步骤：

                       <1> 模拟生产环境的网络链路请求：设置接口超时时间25秒；使用生产环境专属云代理请求测试环境的外网域名；外网域名对应后端服务夯住100秒不返回数据。结果：未出现连接无法断开的现象。

                        <2>找OP在生产环境针对调用机构超时的请求进行抓包分析，未发现网络层面有回包现象。

2. 问题分析：是否无法从http连接池中获取连接，导致请求线程一直等待从连接池获取连接？ PS: 调用机构虽然耗时较大，但是能够从机构接口获取到同步响应数据。

    2.1 排查链路：测试环境不间断模拟上游请求系统A调用机构流程的接口。

        2.1.1 验证设置：

               1） 设置接口超时时间25秒；

                2）使用专属云代理请求测试环境的外网域名；

                3）外网域名对应后端服务夯住100秒不返回数据；

                4）不间断发送5笔请求。

               结论：

                  1）5笔请求耗时统计：前两笔请求耗时25秒，第3、4笔请求耗时46秒，第5笔请求耗时67秒。PS：耗时统计详见：【2.5 验证http连接池】

                   2）根据验证得出结论，请求的并发为2。第3、4笔请求需等待1、2笔请求结束后才能获取到http连接池连接请求机构。

      2.2 尝试复现：并发请求机构网关，浦发线上接口耗时不断增加，但可以获取到同步响应数据。

                    1）设置接口超时时间25秒；

                     2）使用专属云代理请求测试环境的外网域名；

                     3）外网域名对应后端服务20秒后同步返回数据；

                     4）并发请求30个；

                   结论：

                       1）并发请求30个，前两个请求耗时20秒，后续请求耗时不断增加，最高耗时达到300秒。PS：耗时统计详见：【2.6 复现机构线上接口耗时不断增加】

        2.3 排查代码中使用的http 请求工具类：sys-common.jar 包封装的httpClient工具类。

        因为代码中不存在配置文件 /META-INF/config/http_client.cfg。导致未手动设置http连接池最大连接以及每个路由的最大并发连接数。

          PS：http 连接池默认的连接数配置：最大连接20，每个路由最大并发连接数：2

         图一：不存在配置文件，未设置连接池最大连接。

图二： httpClient 连接池默认最大连接 & 每个路由最大并发连接数。

           

2.4 排查代码发现：代码中未设置从连接池获取连接的超时时间。

    PS：在httpClient中，如果没有配置从连接池获取连接的超时时间，默认情况下是不限制超时时间。这意味着当连接池中没有可用连接时，HttpClient将一直等待直到有可用连接为止。        

         

2.5 验证http 连接池只有2个连接，其他请求会一直等待，直到获取到新的连接。（可复现）

前提：http请求超时时间设置25秒，服务端超时时间设置为：1000秒。

请求	耗时统计
1. 发送5笔请求，每笔请求间隔了2秒； 2. 根据结果分析：系统A收到请求后，调用机构需要从http连接池获取连接，如果获取不到，一直等待直到获取到新的连接。
第一笔请求：总体耗时：25074	1. 客户端接收到时间：【2023-07-25 12:02:09.361】 2. 客户端请求服务端时间：【2023-07-25 12:02:09.379】 3. 服务端接收到请求的时间：【2023-07-25 12:02:09.445】 4. 客户端整体耗时：【2023-07-25 12:02:34.456】excuteTime：25074
第二笔请求：总体耗时：25040	1. 客户端接收到时间：【2023-07-25 12:02:11.366】 2. 客户端请求服务端时间：【2023-07-25 12:02:11.372】 3. 服务端接收到请求的时间：【2023-07-25 12:02:11.393】 4. 客户端整体耗时：【2023-07-25 12:02:36.413】excuteTime：25040
第三笔请求：总体耗时：46220	1. 客户端接收到时间：【2023-07-25 12:02:13.265】 2. 客户端请求服务端时间：【2023-07-25 12:02:13.272】 3. 服务端接收到请求的时间：【2023-07-25 12:02:34.475】 4. 客户端整体耗时：【2023-07-25 12:02:59.493】excuteTime：46220
第四笔请求：总体耗时：45978	1. 客户端接收到时间：【2023-07-25 12:02:15.445】 2. 客户端请求服务端时间：【2023-07-25 12:02:15.451】 3. 服务端接收到请求的时间：【2023-07-25 12:02:36.430】 4. 客户端整体耗时：【2023-07-25 12:03:01，430】excuteTime：45978
第五笔请求：总体耗时：67098	1. 客户端接收到时间：【2023-07-25 12:02:17.476】 2. 客户端请求服务端时间：【2023-07-25 12:02:17.484】 3. 服务端接收到请求的时间：【2023-07-25 12:02:59.563】 4. 客户端整体耗时：【2023-07-25 12:03:24.583】excuteTime：67098

2.6 复现调用机构接口耗时不断增加，但可以获取到同步响应数据。

（PS:并发请求时，后续请求无法及时获取到http连接池连接，会一直等待，直到获取到连接并请求机构）

前提：http请求机构超时时间设置为25秒，服务端超时时间设置为：20秒，并发请求30个。

达到效果：http连接池只有2个连接，其他请求会一直等待，耗时不断增加，但是最终可以收到服务器响应。

   

2.7 根据07.05 日线上机构耗时比较长单子，找机构侧排查机构接收到请求的时间以及同步响应的时间。

 

三、解决方案

         1. 设置合理的http连接池连接数。

              根据系统A与机构交互请求QPS，设置连接池最大连接数、每个路由（目标主机）的最大连接数。待补充。

         2. 设置从连接池获取连接的超时时间：待补充。

         3. 增加http连接池监控：

                使用组件，监控httpClient 连接池实时使用情况。

四、经验沉淀

        1. 使用httpClient 组件时， 需要根据实际请求的qps以及资源，设置合理的连接池最大连接数、每个路由的最大连接数，禁止使用httpClient默认值。

        2. 使用httpClient 组件请求时，必须设置：从连接池获取连接的超时时间、连接超时时间、读取数据的超时时间。

        3. 使用该组件，监控httpClient 连接池实时使用情况。

【资料参考】

https://www.cnblogs.com/nuccch/p/10611877.html https://mp.weixin.qq.com/s/bB1EaVwJhHPCY9gNVtb-9w https://www.cnblogs.com/nuccch/p/10611877.html: https://www.cnblogs.com/nuccch/p/10611877.html https://mp.weixin.qq.com/s/bB1EaVwJhHPCY9gNVtb-9w: https://mp.weixin.qq.com/s/bB1EaVwJhHPCY9gNVtb-9w