http request 访问超时

问题：

Caused by: java.net.SocketTimeoutException: Read timed out
        at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.7.0_71]
        at java.net.SocketInputStream.read(SocketInputStream.java:152) ~[na:1.7.0_71]
        at java.net.SocketInputStream.read(SocketInputStream.java:122) ~[na:1.7.0_71]
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:442) ~[na:1.7.0_71]
        at sun.security.ssl.InputRecord.read(InputRecord.java:480) ~[na:1.7.0_71]
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:927) ~[na:1.7.0_71]
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:884) ~[na:1.7.0_71]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:102) ~[na:1.7.0_71]
        at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137) ~[httpcore-4.4.10.jar:4.4.10]
        at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153) ~[httpcore-4.4.10.jar:4.4.10]
        at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282) ~[httpcore-4.4.10.jar:4.4.10]
        at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) ~[httpcore-4.4.10.jar:4.4.10]
        at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) ~[httpcore-4.4.10.jar:4.4.10]
        at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) ~[httpcore-4.4.10.jar:4.4.10]
        at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) ~[httpcore-4.4.10.jar:4.4.10]
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) ~[httpclient-4.5.6.jar:4.5.6]
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108) ~[httpclient-4.5.6.jar:4.5.6]

分析：

1、循环10次访问API，输出每次请求的总耗时

curl -10 -o /dev/null -s -w "Total: %{time_total}s\n" https://xxx.xxx.com/gateway.do

发现间歇性访问超时，10s左右

2、循环10次访问API，输出每次请求的网络耗时

for i in {1..10}; do echo "=== 第 $i 次请求 ==="; curl -o /dev/null -s -w "DNS: %{time_namelookup}s | TCP: %{time_connect}s | TLS: %{time_appconnect}s | TTFB: %{time_starttransfer}s | Total: %{time_total}s\n" https://xxx.xxx.com/gateway.do; done

发现间歇性解析超时，10s左右

3、接着在分析本地DNS解析情况

# DNS配置202.106.0.20、114.114.114.114
dig @202.106.0.20 xxx.xxx.com A +time=5 +tries=1
dig @202.106.0.20 xxx.xxx.com AAAA +time=5 +tries=1

dig @114.114.114.114 xxx.xxx.com A +time=5 +tries=1
dig @114.114.114.114 xxx.xxx.com AAAA +time=5 +tries=1

发现202.106.0.20DNS 解析间歇超时，DNS解析超时为5s，整好A+AAAA两次解析总时间与上面超时10s符合

4、接着使用strace验证问题，发现符合：/etc/resolv.conf 里的第一个 DNS：202.106.0.20 不响应，glibc 每次等满 5 秒后才切到第二个 DNS：114.114.114.114

strace -tt -T -f \
-e trace=connect,sendto,recvfrom,poll,ppoll,select,openat,read \
getent hosts xxx.xxx.com

[sysoper@Wletdmz3 ~]$ strace -tt -T -f   -e trace=connect,sendto,recvfrom,poll,ppoll,select,openat,read   getent hosts openapi-gy.getui.com
18:47:40.673727 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\356\241x1\0\0\0"..., 832) = 832 <0.000039>
18:47:40.675944 read(3, "# Generated by NetworkManager\nna"..., 4096) = 81 <0.000030>
18:47:40.676056 read(3, "", 4096)       = 0 <0.000023>
18:47:40.676400 connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000034>
18:47:40.676638 connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000027>
18:47:40.677029 read(3, "#\n# /etc/nsswitch.conf\n#\n# An ex"..., 4096) = 1688 <0.000043>
18:47:40.677149 read(3, "", 4096)       = 0 <0.000046>
18:47:40.677661 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360!\0\0\0\0\0\0"..., 832) = 832 <0.000025>
18:47:40.678462 read(3, "multi on\n", 4096) = 9 <0.000029>
18:47:40.678549 read(3, "", 4096)       = 0 <0.000035>
18:47:40.679057 read(3, "127.0.0.1   Wletdmz3 localhost l"..., 4096) = 440 <0.000029>
18:47:40.679161 read(3, "", 4096)       = 0 <0.000032>
18:47:40.679641 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\20\0\0\0\0\0\0"..., 832) = 832 <0.000025>
18:47:40.680240 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\00009z1\0\0\0"..., 832) = 832 <0.000025>
18:47:40.681025 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("202.106.0.20")}, 16) = 0 <0.000031>
18:47:40.681137 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}]) <0.000040>
18:47:40.681296 sendto(3, "\313\21\1\0\0\1\0\0\0\0\0\0\nopenapi-gy\5getui\3co"..., 38, MSG_NOSIGNAL, NULL, 0) = 38 <0.000046>
18:47:40.681442 poll([{fd=3, events=POLLIN}], 1, 5000) = 0 (Timeout) <5.002645>
18:47:45.684212 connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("114.114.114.114")}, 16) = 0 <0.000017>
18:47:45.684300 poll([{fd=4, events=POLLOUT}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}]) <0.000010>
18:47:45.684352 sendto(4, "\313\21\1\0\0\1\0\0\0\0\0\0\nopenapi-gy\5getui\3co"..., 38, MSG_NOSIGNAL, NULL, 0) = 38 <0.000040>
18:47:45.684436 poll([{fd=4, events=POLLIN}], 1, 5000) = 1 ([{fd=4, revents=POLLIN}]) <0.023791>
18:47:45.708408 recvfrom(4, "\313\21\201\200\0\1\0\1\0\0\0\0\nopenapi-gy\5getui\3co"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("114.114.114.114")}, [16]) = 62 <0.000033>
18:47:45.709074 read(3, "127.0.0.1   Wletdmz3 localhost l"..., 4096) = 440 <0.000046>
18:47:45.709202 read(3, "", 4096)       = 0 <0.000037>
18:47:45.709473 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("202.106.0.20")}, 16) = 0 <0.000038>
18:47:45.709574 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}]) <0.000025>
18:47:45.709652 sendto(3, "k\34\1\0\0\1\0\0\0\0\0\0\nopenapi-gy\5getui\3co"..., 38, MSG_NOSIGNAL, NULL, 0) = 38 <0.000037>
18:47:45.709746 poll([{fd=3, events=POLLIN}], 1, 5000) = 0 (Timeout) <5.005100>
18:47:50.714953 connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("114.114.114.114")}, 16) = 0 <0.000044>
18:47:50.715082 poll([{fd=4, events=POLLOUT}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}]) <0.000011>
18:47:50.715150 sendto(4, "k\34\1\0\0\1\0\0\0\0\0\0\nopenapi-gy\5getui\3co"..., 38, MSG_NOSIGNAL, NULL, 0) = 38 <0.000018>
18:47:50.715235 poll([{fd=4, events=POLLIN}], 1, 5000) = 1 ([{fd=4, revents=POLLIN}]) <0.023176>
18:47:50.738571 recvfrom(4, "k\34\201\200\0\1\0\2\0\0\0\0\nopenapi-gy\5getui\3co"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("114.114.114.114")}, [16]) = 78 <0.000031>
183.136.220.39  gd.cname2.getui.com openapi-gy.getui.com

4、至此以为问题解决了，但是调整DNS（删除202.106.0.20或者把移到后面）后，发现仍然存在偶尔超时，频次降低了，说明还存在其它问题

通过分析代码，发先是PoolingHttpClientConnectionManager没有配置回收机制，导致链接池链接失效了也一直存在，知道下次使用报错才会移除，至此问题彻底解决

posted @ 2026-07-14 15:02 zbjice 阅读(7) 评论(0) 收藏举报

刷新页面返回顶部

Jice's Blog

http request 访问超时

公告