PHP僵死进程的一次排查过程

1. 问题

登录服务器，发现5号开始运行的脚本一直到今天(7号)还在执行（使用ps -ef 查看该进程），由于是非常驻进程，所以绝对是有问题的。

2. 排查步骤

使用ps命令找到进程id

1
$ ps -aux | grep php

得到进程ID为11621

使用strace查看进程底层调用

1
2
3
4
5
6
7
8
9
10
$ strace -p 11621
strace: Process 11621 attached
restart_syscall(<... resuming interrupted poll ...>) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=4, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=4, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 1000) = 0 (Timeout)
...

发现fd=4的文件描述符超时，需要知道 fd 4 对应的是什么?

Unix Like的操作系统上一切皆文件，网络连接也抽象成一个文件。
每个被打开的文件，在进程中都会有唯一的文件句柄FD。

查看进程打开的文件句柄信息

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
$ ls -l /proc/11621/fd/4
lrwx------ 1 root root 64 Jul 27 17:34 /proc/11621/fd/4 -> socket:[80836276]

$ lsof -d 4 |grep 11621
php 11621 root 4u IPv4 80836276 0t0 TCP bje-xxx-xxx-cron-01:33930->17.154.66.154:https (ESTABLISHED)

$ lsof -n -p 11621
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
php 11621 root cwd DIR 253,1 4096 131073 /root
php 11621 root rtd DIR 253,1 4096 2 /
php 11621 root txt REG 253,1 42570928 546171 /opt/apps/php/bin/php
php 11621 root mem REG 253,1 164240 1049977 /usr/lib64/ld-2.17.so
php 11621 root mem REG 253,1 26254 1050290 /usr/lib64/gconv/gconv-modules.cache
php 11621 root mem REG 253,1 217032 262232 /var/db/nscd/hosts
...
php 11621 root mem REG 253,1 1630976 546169 /opt/apps/php/lib/php/extensions/no-debug-non-zts-20160303/opcache.so
php 11621 root mem REG 253,1 1425312 546824 /opt/apps/php/lib/php/extensions/no-debug-non-zts-20160303/yaf.so
php 11621 root mem REG 253,1 1733920 546768 /opt/apps/php/lib/php/extensions/no-debug-non-zts-20160303/redis.so
...
php 11621 root 1w REG 253,17 926360 1374641 /data/logs/crontablog/ios_vip_20190727.log
php 11621 root 2w REG 253,17 926360 1374641 /data/logs/crontablog/ios_vip_20190727.log
php 11621 root 3u IPv4 80619185 0t0 TCP 172.16.56.44:40762->172.29.1.162:mysql (CLOSE_WAIT)
php 11621 root 4u IPv4 80836276 0t0 TCP 172.16.56.44:33930->17.154.66.154:https (ESTABLISHED)    // 重点关注
...

发现一个可疑的IP地址17.154.66.154，经查询之后得知是美国的服务器。由于业务中包含有苹果IAP支付，所以能确定是跟苹果的支付接口有关。

使用GDB调试

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
$ gdb --pid=11621
Program received signal SIGINT, Interrupt.
0x00002ae8da719f0d in poll () from /lib64/libc.so.6
(gdb) n
Single stepping until exit from function poll,
which has no line number information.
0x00002ae8d8ba44e9 in Curl_poll () from /lib64/libcurl.so.4
(gdb) n
Single stepping until exit from function Curl_poll,
which has no line number information.
0x00002ae8d8b9d40d in curl_multi_wait () from /lib64/libcurl.so.4
(gdb) n
Single stepping until exit from function curl_multi_wait,
which has no line number information.
0x00002ae8d8b964ef in curl_easy_perform () from /lib64/libcurl.so.4
(gdb) n
Single stepping until exit from function curl_easy_perform,
which has no line number information.
...

发现阻塞到了curl_easy_perform这里，跟curl相关函数有关。
查看代码发现curl忘记设置超时时间。

主要是 curl 没设置超时时间导致
https://www.php.net/manual/zh/function.curl-setopt.php

添加超时时间设置。

1
curl_setopt($ch, CURLOPT_TIMEOUT, 30);

发布代码重新上线之后经过验证，发现不会再出现进程僵死问题了。

总结

对于线上僵死进程问题的排查，一般需要如下命令工具：

1
2
3
4
5
ps -aux     // 得到僵死进程pid
strace -p  pid  // 查看僵死进程底层的调用信息，获取到 fd
lsof -d  FD  // 查看fd对应文件信息
gdb  --pid=PID  // 通过gdb查看代码调用信息
tcpdump      // 抓网络包

不同的编程语言，还有其他很多可以使用的调试工具，但是调试排查思路大致相同。