1. 问题
登录服务器,发现5号开始运行的脚本一直到今天(7号)还在执行(使用ps -ef 查看该进程),由于是非常驻进程,所以绝对是有问题的。2. 排查步骤
使用ps命令找到进程id# ps -aux | grep PHP得到进程ID为11621使用strace查看进程底层调用# 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的操作系统上一切皆文件,网络连接也抽象成一个文件。
查看进程打开的文件句柄信息# 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调试# 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 @R_444_4045@ion.
0x00002ae8d8ba44e9 in Curl_poll () from /lib64/libcurl.so.4
(gdb) n
Single stepping until exit from function Curl_poll,
which has no line number @R_444_4045@ion.
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 @R_444_4045@ion.
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 @R_444_4045@ion.
...发现阻塞到了curl_easy_perform这里,跟curl相关函数有关。
查看代码发现curl忘记设置超时时间。
主要是 curl 没设置超时时间导致
https://www.PHP.net/manual/zh/function.curl-setopt.PHP
添加超时时间设置
curl_setopt($ch, CURLOPT_TIMEOUT, 30);发布代码重新上线之后经过验证,发现不会再出现进程僵死问题了。
总结
对于线上僵死进程问题的排查,一般需要如下命令工具:ps -aux // 得到僵死进程pidstrace -p pid // 查看僵死进程底层的调用信息,获取到 fdlsof -d FD // 查看fd对应文件信息gdb --pid=PID // 通过gdb查看代码调用信息tcpdump // 抓网络包不同的编程语言,还有其他很多可以使用的调试工具,但是调试排查思路大致相同。