工作杂记(1) 一次HTTP请求超时

发表于 | 更新于

有两台服务器，一台上运行着PHP服务，另一台运行Java服务。两台服务器之间通过HTTP进行接口调用。查看Java服务端的日志发现，有很多往PHP服务的HTTP请求都超时。
于是在PHP服务器端用 netstat 命令查看了一下网络套接字连接情况。

命令 netstat -atp

运行结果:

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
...
tcp        0      0 172.19.126.49:53334     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:53556     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:52912     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:50760     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:53534     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:50570     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:50080     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:50660     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:50708     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:50156     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:51220     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:53924     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:49602     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:51988     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:38694     172.19.126.48:9981      TIME_WAIT   -
tcp        0      0 172.19.126.49:54832     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:50184     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:49270     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:53124     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:54068     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:52530     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:50504     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:54822     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:52070     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:53562     172.19.126.50:mysql     TIME_WAIT   -
tcp        0      0 172.19.126.49:54286     172.19.126.50:mysql     TIME_WAIT   -
...

发现大量的端口处于TIME_WAIT状态,而且都是与mysql连接相关.

运行命令 netstat -at | grep 'mysql' | awk '{print $6}' | sort | uniq -c。发现有差不多3000个端口处于TIME_WAIT。看来PHP服务打开的MySQL连接还真多。鉴于自己对PHP开发不了解，只是直觉上感觉打开这么多MySQL连接会影响服务性能。接下来主要想看一下HTTP调用的端口情况。用netstat检查发现端口连接不多，于是打算抓一下http端口的数据包看看。用tcpdump抓包，wireshark分析没有发现问题。然后又在Java服务端抓取双方通信的数据包，分析也没看出问题。It’s so strange!!!

既然日志是Java服务报出来的，看来应该在Java服务上去找原因。查看了Java服务的代码，发现Java服务中使用了Vertx框架中的HttpClient来进行Http请求。HttpClient配置如下:

1
2
3
4
5
6
7
{
    "keepAlive": true,
    "idleTimeout": 10,
    "maxPoolSize": 50,
    "maxWaitQueueSize": 3000,
    "connectTimeout": 10000
}

当keepAlive设置为true的时候，HttpClient会重用建立的连接进行HTTP请求。idleTimeout参数控制连接空闲时间，当空闲时间达到idleTimout，该连接会被关闭。maxPoolSize指定了最大的连接数，当连接数没有达到maxPoolSize时，HttpClient会为新的请求新建连接，当达到maxPoolSize，HttpClient不再新建连接，而是把请求放进等待队列，等待队列的大小由maxWaitQueueSize来指定。connectTimeOut指定了连接超时时间。从日志看到的超时并不是连接超时。而是请求超时，请求超时是在HttpClientRequest里设置的。当一个请求达到设置的timeout且没有返回任何数据，就会一个java.util.concurrent.TimeoutException传递给异常处理方法。

通过运行命令netstat -at | grep -E '172.19.126.49' -c发现当前连接已经达到了50，也就是达到了maxPoolSize的设置。

统计Java服务发起的请求，1秒钟有差不多接近三千个请求。

综合上述信息，问题还是出现在PHP服务，PHP服务提供的HTTP接口处理速度不够快，导致Java服务端产生大量的HTTP请求堆积超时。而且从PHP服务端一开始发现的大量MySQL连接也证实了PHP服务提供的接口实现会去直接访问数据库，没有采用缓存之类的操作，导致接口更慢。看来还得找PHP研发打架去。。。