Varobj

2020-09-09

如何定位超时进程的问题



最近工作需要开发大量的定时脚本,脚本中需要处理,诸如调用第三方接口、 Redis 读写、 MySQLCURD 等耗时任务。但有的脚本总是无法在预期时间内结束,甚至永远不会结束。

例如这些:

[root@varobj ~]# ps aux|grep Jul|grep yii
root      7911  0.0  0.1 235764 27384 ?        S    Jul08   1:37 php /data/www/xx/yii material/gdt-creative
root      2440  0.0  0.1 227368 19252 ?        S    Jul30   1:01 php /data/www/xx/yii adver-info
root     11295  0.0  0.1 237424 29252 ?        S    Jul08   1:36 php /data/www/xx/yii gdt-budget/get-budget

images

1. 解决

当前时间九月份,但是很多七月的脚本还在运行。想要知道卡住的脚本的情况,可以使用 stracelsof 两个命令。

首选使用 strace 查看下进程的情况,strace 是查看进程的系统调用的调试工具,具体使用方法可以参考 strace 命令

[root@varobj ~]# strace -p 7911
Process 7911 attached
restart_syscall(<... resuming interrupted call ...>) = 0
poll([{fd=10, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {32056795, 478953645}) = 0
clock_gettime(CLOCK_MONOTONIC, {32056795, 478968611}) = 0
clock_gettime(CLOCK_MONOTONIC, {32056795, 478981480}) = 0
poll([{fd=10, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 1000) = 0 (Timeout)
poll([{fd=10, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {32056796, 480070547}) = 0
clock_gettime(CLOCK_MONOTONIC, {32056796, 480084038}) = 0
clock_gettime(CLOCK_MONOTONIC, {32056796, 480096520}) = 0

比较醒目的一行是:

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

poll() 函数是 IO 多路复用的一种方式,类似的还有 select, epoll。其中 poll 函数第一个参数是 pollfd 文件描述符,其结构体包含(fd, events, revents),fd 是文件编号,events 是传入的事件,revents 是返回的事件,事件中 POLLIN|POLLPRI 分别表示有数据需要读取;有紧急的数据需要读取,当 poll 函数返回结果大于 0 时,查看 revents 中的对应事件名称,进行对应的处理。详细关于 poll 的说明参考文档 poll 使用

以上是肯定有问题的,对比下没有问题的 poll 如下:

poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 2000) = 1 ([{fd=5, revents=POLLIN}])

这里可以看到 fd=10 的文件描述符相关的结果一直都是 timeout,所以需要看下 fd = 10 的文件包含了哪些资源。使用 lsof 命令查看进程中使用到的资源(即打开的文件列表,毕竟 Linux 中一切皆为文件,资源也即文件)lsof 命令

[root@varobj ~]# lsof -d 10|grep 7911
php        7911  root   10u  IPv4 1439182232      0t0        TCP 172.*.*.*:52424->183.3.226.36:https (ESTABLISHED)

或者使用 lsof -p 7911 在很长的列表中查找 FD 列值等于 10u 的那一行,也就是上面列出的一行。 能看到文件 10 且在进程号 7911 中的文件只有一个 tcp 连接,指向的 ip 地址是 183.3.226.36, 查阅代码,当前脚本调用了广点通的接口,域名对应的 ip 正好是这个。

问题出现在,封装的 curl 相关类缺少超时时间、最大时间等设置,就是下面这两行:

curl_setopt($curl, CURLOPT_CONNECTTIMEOUT, 10);
curl_setopt($curl, CURLOPT_TIMEOUT, 60);

2. 关于Curl的超时设置

其中 CURLOPT_CONNECTTIMEOUT 对应 curl 命令的 --connect-timeout 参数,表示连接超时时间,只在连接期间生效,一旦连接上这个参数将不再使用。所以如果只设置了 CURLOPT_CONNECTTIMEOUT, 但没有设置 CURLOPT_TIMEOUT 一样会遇到一直超时的现象。关于 --connect-timeout 的默认值,实测我的 CentOS 7 上是 2 分钟。curl 库中定义的默认时间是 5 分钟 DEFAULT_CONNECT_TIMEOUT, 为什么 CentOS 7 上是 2 分钟,我也不知道 😄。 curl 帮助中相关说明如下:

[root@varobj ~]# man curl|grep '\-\-connect-timeout' -A 3
       --connect-timeout <seconds>
              Maximum time in seconds that you allow the connection to the server to take.  This only limits the connection phase,  once
              curl has connected this option is of no more use. See also the -m, --max-time option.

CURLOPT_TIMEOUT 对应 curl 命令的 --max-time参数,表示建立连接后,最多能够执行的时间。假如没有设置当前参数,且后端接口不设置超时请求时间,那么进程会一直阻塞在这里,几个小时,甚至几个月都结束不了,进程会一直循环进行系统调用,如 strace所看到的那样。关于默认值,--max-time 并没有默认值,没有设置会一直等待。curl 帮助中相关说明如下:

[root@varobj ~]# man curl|grep '\-\-max-time <seconds>' -A 5 
       -m, --max-time <seconds>
              Maximum  time  in  seconds that you allow the whole operation to take.  This is useful for preventing your batch jobs from
              hanging for hours due to slow networks or links going down.  See also the --connect-timeout option.

              If this option is used several times, the last one will be used.

3. 关于后端接口的超时设置

最后,关于后端接口的超时如何设置的,在 nginx + php 的模式下,默认是 60s 超时时间,如果 php 处理超过 60s 没有返回,nginx 将返回 504 的状态给调用方,所以默认情况是不会出现这种情况的。那么只能说第三方接口服务没有设置超时时间。php 是通过 max_execution_time 来设置最长执行时间,如果是 0 表示不限制时间,还要看 default_socket_timeout 的设置。我的配置如下

[root@varobj ~]# php -i|grep max_execution_time
max_execution_time => 0 => 0
[root@varobj ~]# php -i|grep default_socket_timeout
default_socket_timeout => 60 => 60

如果 php 环境以上两个参数都是 0,还要看 Nginxfastcgi 的参数 fastcgi_read_timeout ,它可以决定读取后端的超时时间,默认是 60s。我认为正确的做法是,不能依赖环境的默认配置,调用第三方接口时,连接超时时间、请求超时时间都需要手动指定。一般设置 10 秒连接超时,60 秒请求超时就可以了。特殊情况,如下载超大文件,再特殊修改,所以选择第三方 curl 库,或者自己封装,都需要特别注意,既要保证请求不能缺少默认超时相关设置,也不能写死超时设置,导致调用方无法修改。下面是简单的封装示例部分代码

class XCURL {
    private $connect_timeout = 10;
    private $timeout = 60;

    public function __construct(array $params = [])
    {
        if (!empty($params['connect_timeout'])) {
            $this->connect_timeout = (int)$params['connect_timeout'];
        }
        if (!empty($params['timeout'])) {
            $this->timeout = (int)$params['timeout'];
        }
        // ...
    }

    protected function _doRequest(
        string $uri,
        array $query = [],
        array $post = [],
        bool $is_post = false
    ) {
        // ...
        curl_setopt($ch, CURLOPT_HTTPHEADER, $_headers);
        curl_setopt($ch, CURLOPT_HEADER, 0);
        curl_setopt($ch, CURLOPT_FOLLOWLOCATION, 1);
        curl_setopt($ch, CURLOPT_RETURNTRANSFER, true);
        curl_setopt($ch, CURLOPT_CONNECTTIMEOUT, $this->timeout);
        curl_setopt($ch, CURLOPT_TIMEOUT, $this->connect_timeout);
        curl_setopt($ch, CURLOPT_USERAGENT, 'XClient_Chrome_UA_V1.0');
        // ...
    }
}

Tips: 本文只是遇到了 curl 超时卡住的问题,一定还会有很多其它中原因的。