php5.3 curl超时,PHP中curl设置毫秒级超时的问题

TL;DR

PHP5/7加上7.19的libcurl，设置低于1s的超时时间时，curl_exec仍会执行超过1s以上。原因在于此版本的libcurl实现逻辑上以1000ms作为curl_exec中poll系统调用的超时值。

问题

某些HTTP接口响应时间可能因为种种原因会引起响应时间延长的问题，在这种情况下，从性能、体验角度考虑，设置调用方的超时时间成为必要。

从手册上得知：

选项

设置value为

备注

CURLOPT_TIMEOUT_MS

设置cURL允许执行的最长毫秒数。 如果 libcurl 编译时使用系统标准的名称解析器( standard system name resolver)，那部分的连接仍旧使用以秒计的超时解决方案，最小超时时间还是一秒钟。

在 cURL 7.16.2 中被加入。从 PHP 5.2.3 起可使用。

在符合版本条件的服务器上用PHP内置的HTTP服务器模拟一个时长超过1s的接口：

1

2

3

4

5

6[root@vm curl_test]# cat slow.php

$sleep = isset($_GET['sleep']) ? $_GET['sleep'] : 1;

sleep($sleep);

echo "SLOW RESPONSE\n";

[root@vm curl_test]# php -S 127.0.0.1:8000

通过如下代码访问这一接口：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19<?php

$timeout_ms = isset($argv[1]) ? $argv[1] : 200;

$sleep = isset($argv[2]) ? $argv[2] : 1;

$url = "http://127.0.0.1:8000/slow.php?sleep={$sleep}";

$ch = curl_init();

curl_setopt($ch, CURLOPT_URL, $url);

curl_setopt($ch, CURLOPT_NOSIGNAL, 1);

curl_setopt($ch, CURLOPT_TIMEOUT_MS, $timeout_ms);

$start = microtime(true);

curl_exec($ch);

$end = microtime(true);

$time = ($end - $start) * 1000;

curl_close($ch);

echo "sleep: {$sleep}s\n";

echo "timeout: {$timeout_ms}ms\n";

echo "start: {$start}\n";

echo "end: {$end}\n";

echo "used: " . ($end - $start) * 1000 . "ms\n";

通过如下命令，设定了200ms的超时时间，同时还有2s的接口延迟响应时间。

1[root@vm curl_test]# php curl_test.php 200 2

预料中，客户端应该会在200ms左右的时间结束程序，然而实际执行输出让人感到困惑：

1

2

3

4

5

6[root@vm curl_test]# php curl_test.php 200 2

sleep: 2s

timeout: 200ms

start: 1497665724.8918

end: 1497665725.8937

used: 1001.8589496613ms

客户端运行了1000ms+的时间。

分析

查询手册

从PHP手册中查询到的结果，字面意思并没有太多的歧义，使用方法上也并没有明显错误，下面可以从运行时的状态开始分析。

Strace跟踪运行过程

通过strace查看运行过程中的系统调用：

1strace -o curl_strace.log -ttt php curl_test.php 200 1

为了方便分析，将输出记录到curl_strace.log文件之中，并记录各个系统调用产生时的时间戳。

关键的网络请求部分系统调用记录如下：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

221 1497665724.892491 connect(3, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)

2 1497665724.892632 clock_gettime(CLOCK_MONOTONIC, {17533335, 287262686}) = 0

3 1497665724.892660 poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 200) = 1 ([{fd=3, revents=POLLOUT|POLLWRNORM}])

4 1497665724.892689 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0

5 1497665724.892714 clock_gettime(CLOCK_MONOTONIC, {17533335, 287343820}) = 0

6 1497665724.892737 clock_gettime(CLOCK_MONOTONIC, {17533335, 287371368}) = 0

7 1497665724.892767 clock_gettime(CLOCK_MONOTONIC, {17533335, 287395792}) = 0

8 1497665724.892789 clock_gettime(CLOCK_MONOTONIC, {17533335, 287418504}) = 0

9 1497665724.892811 clock_gettime(CLOCK_MONOTONIC, {17533335, 287439788}) = 0

10 1497665724.892849 sendto(3, "GET /slow.php?sleep=2 HTTP/1.1\r\n"..., 69, MSG_NOSIGNAL, NULL, 0) = 69

11 1497665724.893017 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)

12 1497665724.893046 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)

13 1497665724.893070 clock_gettime(CLOCK_MONOTONIC, {17533335, 287699255}) = 0

14 1497665724.893093 clock_gettime(CLOCK_MONOTONIC, {17533335, 287722637}) = 0

15 1497665724.893117 clock_gettime(CLOCK_MONOTONIC, {17533335, 287746751}) = 0

16 1497665724.893139 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 1000) = 0 (Timeout)

17 1497665725.893450 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)

18 1497665725.893480 clock_gettime(CLOCK_MONOTONIC, {17533336, 288109801}) = 0

19 1497665725.893505 clock_gettime(CLOCK_MONOTONIC, {17533336, 288133751}) = 0

20 1497665725.893545 clock_gettime(CLOCK_MONOTONIC, {17533336, 288174671}) = 0

21 1497665725.893576 gettimeofday({1497665725, 893582}, NULL) = 0

22 1497665725.893602 close(3) = 0

fd=3的文件描述符即用于处理网络请求。在上述步骤的第10行发出请求之后，调用了poll系统调用来检验fd是否可以读写。查阅手册得知，poll系统调用的声明为：

1int poll(struct pollfd *fds, nfds_t nfds, int timeout);

第三个参数即以毫秒为单位的等待超时时间。

请注意16行的系统poll调用，超时时间足足设定了1000ms，之后程序执行结束退出，那么这个1000ms的超时设定，应该就是程序没有在200ms左右的时间退出的主要原因。

PHP curl扩展

PHP中的curl函数在curl的扩展中定义，如果怀疑对运行的方式产生了怀疑，可以查看扩展源码。

在PHP源码的ext/curl目录下的interface.c文件中，可以看到curl_exec方法的定义：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19/*{{{ proto bool curl_exec(resource ch)

Perform a cURL session */

PHP_FUNCTION(curl_exec)

{

CURLcode error;

zval *zid;

php_curl *ch;

if (zend_parse_parameters(ZEND_NUM_ARGS() TSRMLS_CC, "r", &zid) == FAILURE) {

return;

}

ZEND_FETCH_RESOURCE(ch, php_curl *, &zid, -1, le_curl_name, le_curl);

_php_curl_verify_handlers(ch, 1 TSRMLS_CC);

_php_curl_cleanup_handle(ch);

error = curl_easy_perform(ch->cp);

可以看到，实际上PHP中的curl_exec调用的是libcurl中的curl_easy_perform这一函数执行的网络请求。

对于超时的问题，需要深入到libcurl之中了。

libcurl 7.19

通过curl --version命令可以获取cUrl的版本，之后在GitHub是哪个clone源码repo，checkout对应版本(7.19.x)即可。

可以看到curl_easy_perform在libcurl源码目录中lib/easy.c中被定义了。主要执行步骤如下：

1.执行Curl_perform函数

2.在Curl_perform中完成连接(connect_host函数)与传输数据操作(Transfer函数)

3.在Transfer中对第一次poll操作设定0ms的超时，之后均设定为1000ms的超时，参见代码：

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

26if(first &&

((fd_read != CURL_SOCKET_BAD) || (fd_write != CURL_SOCKET_BAD)))

/* if this is the first lap and one of the file descriptors is fine

to work with, skip the timeout */

timeout_ms = 0;

else

timeout_ms = 1000;

switch (Curl_socket_ready(fd_read, fd_write, timeout_ms)) {

case -1: /* select() error, stop reading */

#ifdef EINTR

/* The EINTR is not serious, and it seems you might get this more

often when using the lib in a multi-threaded environment! */

if(SOCKERRNO == EINTR)

continue;

#endif

return CURLE_RECV_ERROR; /* indicate a network problem */

case 0: /* timeout */

default: /* readable descriptors */

result = Curl_readwrite(conn, &done);

/* "done" signals to us if the transfer(s) are ready */

break;

}

...

4.Curl_socket_ready方法中会根据传入的超时时间即变量timeout_ms的值设定poll系统调用的超时值，结合strace日志，即11与16行的poll操作。

5.第一次超时为0ms时，poll会立刻返回，显然没有socket可以读写，会走入switch语句的case 0的分支，调用Curl_readwrite函数；在第二次以及之后的执行中，超时会恒定在1000ms，在可读写之后，会走入switch语句的default的分支，也会调用Curl_readwrite函数。

6.在Curl_readwrite函数中会再次调用Curl_socket_ready方法，但是这次传入的超时时间则固定为0ms了：

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

29

30

31

32

33

34

35

36

37/*

* Curl_readwrite() is the low-level function to be called when data is to

* be read and written to/from the connection.

*/

CURLcode Curl_readwrite(struct connectdata *conn,

bool *done)

{

struct SessionHandle *data = conn->data;

struct SingleRequest *k = &data->req;

CURLcode result;

int didwhat=0;

curl_socket_t fd_read;

curl_socket_t fd_write;

int select_res = conn->cselect_bits;

conn->cselect_bits = 0;

/* only use the proper socket if the *_HOLD bit is not set simultaneously as

then we are in rate limiting state in that transfer direction */

if((k->keepon & KEEP_RECVBITS) == KEEP_RECV) {

fd_read = conn->sockfd;

} else

fd_read = CURL_SOCKET_BAD;

if((k->keepon & KEEP_SENDBITS) == KEEP_SEND)

fd_write = conn->writesockfd;

else

fd_write = CURL_SOCKET_BAD;

if(!select_res) { /* Call for select()/poll() only, if read/write/error

status is not known. */

select_res = Curl_socket_ready(fd_read, fd_write, 0);

}

...

这里的Curl_socket_ready就是strace日志中12与17行两次poll操作记录的来源。

7.在Curl_readwrite中会判断当前已执行时间是否已经超过了设定的超时时间：

1

2

3

4

5

6

7

8

9

10

11

12

13if(data->set.timeout &&

(Curl_tvdiff(k->now, k->start) >= data->set.timeout)) {

if(k->size != -1) {

failf(data, "Operation timed out after %ld milliseconds with %"

FORMAT_OFF_T " out of %" FORMAT_OFF_T " bytes received",

data->set.timeout, k->bytecount, k->size);

} else {

failf(data, "Operation timed out after %ld milliseconds with %"

FORMAT_OFF_T " bytes received",

data->set.timeout, k->bytecount);

}

return CURLE_OPERATION_TIMEDOUT;

}

如果已超过则，返回已超时。

小结

综上，老版本curl设定了ms级别超时但是仍然会执行s级别的问题在于curl的poll超时设定被固定在1000ms之上，造成了这一问题。

解决

可以考虑升级libcurl，或者在编译的PHP中使用高版本的libcurl。

1

2

3

4

5

6

7

8

9

10[root@vm curl_test]# curl --version

curl 7.55.0-DEV (x86_64-unknown-linux-gnu) libcurl/7.55.0-DEV OpenSSL/1.0.1e zlib/1.2.3

Release-Date: [unreleased]

Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp

[root@vm curl_test]# /opt/softwares/php/7.1.6_newlibcurl/bin/php curl_test.php 200 1

sleep: 1s

timeout: 200ms

start: 1497667324.1965

end: 1497667324.3967

used: 200.21796226501ms

以上。