ES客户端请求超时问题排查

一、现象

生产的3台ES用Nginx做代理，客户端->Nginx->ES都是长连接。ES客户端每天会有30条左右的超时日志，这是客户端设置了60s请求超时主动报错引起的，错误信息如下（搜索、按ID获取、建立索引都会出现超时）：

java.net.SocketTimeoutException: 60,000 milliseconds timeout on connection http-outgoing-922 [ACTIVE]
	at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:808)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:248)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:235)
	at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:1514)
	at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:1484)
	at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:1454)
	at org.elasticsearch.client.RestHighLevelClient.update(RestHighLevelClient.java:921)

客户端设置了socketTimeout为60秒，所以可以肯定的是请求长时间无数据返回导致报错。Nginx里的错误日志如下：

2021/05/20 13:26:58 [warn] 491406#491406: *94078113 an upstream response is buffered to a temporary file /data/openresty/nginx/proxy_temp/1/65/0000049651 while reading upstream, client: 10.81.127.209, server: 10.30.223.84, request: "POST /spprjm_customer/_search HTTP/1.1", upstream: "http://10.29.56.90:39200/spprjm_customer/_search", host: "10.30.223.84:86"
2021/05/20 13:26:59 [info] 491406#491406: *94076470 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while connecting to upstream, client: 10.45.179.90, server: 10.30.223.84, request: "POST /enterprise_v1/_search HTTP/1.1", upstream: "http://10.30.222.121:39200/enterprise_v1/_search", host: "10.30.223.84:86"

10.45.182.231 - - [21/Jun/2021:16:41:01 +0800] "POST /person_search_user_v1/_search HTTP/1.1" "/person_search_user_v1/_search" "60.052" "-" 499 0 "-" "Apache-HttpAsyncClient/4.1.4 (Java/1.8.0_144)"

这里的epoll_wait()错误与业务里的超时异常是一一对应的，就是说客户端等待60s后提前断开了长连接，于是Nginx也断开了与上游代理的长连接，最后响应499错误码。

二、排查问题

看到这些错误，于是在网络上寻找答案，下边列举几个感觉有价值的信息：

通过排查服务器配置net.ipv4.tcp_keepalive_time = 1200可以排除是防火墙连接超时过早导致网络不通，一般防火墙连接超时是1小时（我没有找到任何教程对于这个时间的配置，但在 Iptables Default connections 里看到默认是600s超时，由于能力有限没办法得知服务器里的真实数值），TCP连接在1200s后会有多次探测，所以应该不是防火墙把连接过早断开的问题。

我把问题指向了ES服务，经过kibana里的监控得知，近期的请求延迟并不高，但是与客户端超时有一致的延迟突起，说明与ES还是有一定关系的，我找到一篇文章介绍了监控参数，可以认为这里的监控值取的是平均值。那就把ES的慢请求日志打开，看看到底有多大的延迟，配置如下：

curl -XPUT "http://ip:port/_all/_settings?preserve_existing=true" -H 'Content-Type: application/json' -d'
{
  "index.indexing.slowlog.level" : "info",
  "index.indexing.slowlog.source" : "1000",
  "index.indexing.slowlog.threshold.index.info" : "100ms",
  "index.search.slowlog.threshold.fetch.info" : "100ms",
  "index.search.slowlog.threshold.query.info" : "100ms"
}
'

经过几个小时的等待，生产最终有业务报超时了，然后排查ES慢日志，得到的最大延迟却只有1s左右（也有可能这个请求根本没打日志，这里还需要认真排查确认），看起来并不是ES响应慢的问题，到这里我没有了思路。

三、在测试环境复现问题

我本机开启多个线程对ES发起查询（客户端连接数配置充足，不然会停顿在获取连接的地方，反而复现不出请求超时），在线程数为50的时候下行带宽达到了100%，线程开到200时就开始频繁出现10s超时。使用jvisualvm查看线程状态发现，有大量线程长时间被挂起（带宽不够导致IO等待），线程唤醒后出现超时异常，但是Nginx的错误日志与生产的并不一样，因为生产只有epoll_wait()一种错误，测试环境却出现了如下几种错误，只有我强制关闭程序时才会出现与生产一致的错误：

2021/06/21 15:07:52 [info] 14749#0: *58644745 recv() failed (104: Connection reset by peer) while sending to client, client: 172.16.9.119, server: 172.16.1.78, request: "POST /prep_statistics_service_process_detail/_search HTTP/1.1", upstream: "http://172.16.1.78:9203/prep_statistics_service_process_detail/_search", host: "172.16.1.78:86"
2021/06/21 20:01:13 [info] 14749#0: *61424251 writev() failed (104: Connection reset by peer) while sending to client, client: 172.16.20.14, server: 172.16.1.78, request: "POST /prep_srms_service_record_group/_search HTTP/1.1", upstream: "http://172.16.1.78:9201/prep_srms_service_record_group/_search", host: "172.16.1.78:86"
2021/06/21 15:07:52 [info] 14749#0: *58658403 client 172.16.9.119 closed keepalive connection (104: Connection reset by peer)

经过思考，我认为可能是由于客户端线程挂起，而这时请求在Nginx这里是不停的读写的，客户端超时后，Nginx这里即有可能在读数据也有可能在写数据，最终出现这些网络错误。

于是我把测试程序放在网络更好的虚拟器上运行，但是CPU却在200线程时就占满了，最终500个线程只使用了50%的带宽，这时出现了我期待的5s超时。通过jvisualvm分析发现也是由于线程挂起导致，这次是CPU竞争导致的长时间等待。

于是我开始定位业务服务器的负载情况，通过观察历史监控数据得知GC停顿并不大，CPU负载也不高，出入带宽也才使用10%。分析到这里我没有了思路。不过今天测试组在做生产的搜索压测，导致近4个小时有100左右的业务60s请求超时日志，这又让我开始怀疑是ES负载高的问题。

初步结论：

  • Nginx的 proxy_next_upstream 默认配置是：error timeout
  • 生产配置的 proxy_connect_timeout 为3600秒是不合理的（客户端60s就会主动报错），这样就没法利用Nginx的重试机制
  • 合理的配置应该设置: proxy_connect_timeout 10 快速触发超时并重连下一台机器，这样ES客户端很大几率不用等待60s就可正常通信

四、有了解决经验后的总结

1. 响应502错误码

Nginx代理3台机器，如果一台上游实例挂掉，且 proxy_next_upstream_tries 为2，proxy_next_upstream 没有配置（使用默认值：error timeout），当另外2台上游实例的网络稍微有不稳定，很容易触发重试2次都失败的情景，导致nginx报no live upstreams while connecting to upstream的错误，最终nginx认为上游服务器不可用，响应给客户端502状态码。由于官方 server 默认配置 max_fails=1 fail_timeout=10s，所以就可以解释为啥每次502问题都只持续了10s。

2. TCP半连接数不稳定

Linux服务器的TCP半连接数不稳定与NG的连接保持数有很大关系。先看官方文档对 keepalive 的描述：

设置每个工作进程的缓存中保留的到上游服务器的空闲keepalive连接的最大数量。如果超过此数字，则关闭最近使用最少的连接。应该特别注意的是，keepalive指令并没有限制nginx工作进程可以打开的上游服务器的连接总数。此参数应设置为足够小的数字，以便上游服务器也可以处理新的传入连接。当使用默认循环方法以外的负载平衡方法时，必须在keepalive指令之前激活它们。

此配置默认值为空，即对空闲的连接会立即关闭并回收。这就能解释之前linux为啥有大量创建中的TCP连接了，在高并发请求下几乎每次都要重建连接，用完又被关闭，所以稳定TCP连接数几乎没有波动。

这里必须要说明 keepalive_timeout 这个参数，官方描述：设置一个超时，在此期间，到上游服务器的空闲keepalive连接将保持打开状态，即空闲时长超过此数字才会把连接关闭并回收。

经过之前的测试发现，keepalive_timeout 是在有 keepalive 配置时才会起作用，在没有配置keepalive时，即使有配置keepalive_timeout也会立即回收空闲连接。所以，针对这样一个有巨大收益的NG配置，建议在NG里都配置上，以解决长连接不起效（重用率不高也与 keepalive_requests 的值有关）的问题。

注意：keepalive配置值不是越大越好，必须根据上游连接能力和业务实际并发量进行配置。一般取最大并发量的30%左右，由于空闲连接会在配置的超时时长后被回收，我认为只要配置值不超过上游连接能力尽量大些。

参考资料：

posted @ 2021-11-22 10:04  爱定小闹钟  阅读(11787)  评论(0)  编辑  收藏  举报