冯老师的困惑 —— PHP 挂了
认识冯老师五年以来,终于看到他露了一手,仅凭一战足以封神。此役过后,我愿尊称他为 master。
PHP5 挂了
本来今天晚上计划迁移服务器的,目标服务器已经通过阿里云共享镜像创建。按道理说,环境都是一模一样的,可是当我准备测试代码的时候,发现目标服务器上 PHP7 的项目运行正常,PHP5 的项目却一直转圈圈。这还真是奇了怪了。
于是,我便开始一步步定位。
跟踪定位
外部看到的情况是:请求半天以后,报了一个 504 错误 —— 「请求超时」。
遇到这种情况,首先想到的是分析 nginx 错误日志,可通过查看 nginx 错误日志后,并没有什么发现。于是,只能考虑别的方法。
会不会是项目里配置的地址有白名单之类的没有添加,导致的超时呢?
于是,我在项目入口处打了个断点,想看下请求有没有走到项目中来。可是当我打完以后,发现依然会请求超时,这说明请求并没有走到项目中。
请求没有走到项目中,但查看 nginx 访问日志,请求已经接收到了。那只能是在 php-fpm
处理请求这一块儿出问题了。于是,我想看看php-fpm
的错误日志或者慢日志。
我打算先使用php --ini
命令查看下配置相关的一些内容。可是当我在控制台输入命令以后,发现控制台也卡住了,等了大概 5 分钟以后,界面上提示了一个Segment fault
错误,翻译过来就是程序段错误
的意思。
我尝试运行其他 PHP 命令,发现php -m
也不能正常运行,php -v
,php -h
这些命令是可以的。
呃……看来,这就不只是php-fpm
的问题了,连cli
模式也有问题,说明是 PHP 程序出了问题。
那该怎么定位呢?
我首先想到了strace
命令。
strace 命令
strace
命令主要用来跟踪进程相关的系统调用信息,包括参数、返回值和调用时间等信息。
常用的方法如下:
strace -p 进程ID
我在一个窗口执行了php -m
命令,然后又开了一个窗口,使用ps
命令查看刚才命令的进程ID
,然后使用strace
命令进行跟踪,跟踪到的结果如下:
Process 19351 attached
restart_syscall(<... resuming interrupted call ...>) = 1
getsockopt(4, SOL_SOCKET, SO_ERROR, [110], [4]) = 0
fcntl(4, F_SETFL, O_RDWR) = 0
gettimeofday({1714132764, 671300}, NULL) = 0
close(4) = 0
gettimeofday({1714132764, 671620}, NULL) = 0
--- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0} ---
+++ killed by SIGSEGV +++
看到跟踪出来的结果,我并没有眼前一亮。因为还是没有看出具体是什么原因导致的。
正在我愁眉不展的时候,冯老师从我身边走过,问我是否需要帮助。
我本来想再挣扎一下的,但排查这个问题已经用去了几个小时的时间。如果还是没有进展的话,那定于晚上十点的迁移计划肯定要推迟。事不宜迟,于是,我向冯老师诚恳地发出了「求救信号」。
冯老师也没有吝啬,爽快地答应了我的请求,当然条件是一顿猪头肉。
strace 命令的新玩法
我本来只是抱着「试一试」的想法求教冯老师的,因为之前向他求教问题时,他总是东一榔头,西一棒槌地讲一堆大道理,然后画一个望不着边际的圈:「问题就是这么个问题,按我说的去查吧!」
最后我还是一脸懵逼,只能自己来。
这次冯老师并没有像往常一样,问题还没看完就有了结论。他很认真地排查着。
「你可以用 strace 命令跟踪一下。」
「用了,没看出问题来。」
我把跟踪的结果发给冯老师,冯老师仔细地看着。
五分钟过去了。
「你来看一下,这里有个 Redis 调用,卡住了。」
「Redis ?」
我一脸疑惑地来到冯老师电脑前,他指着屏幕上输出的日志给我看:
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
fcntl(4, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(4, {sa_family=AF_INET, sin_port=htons(6379), sin_addr=inet_addr("172.17.×××.×××")}, 16) = -1 EINPROGRESS (Operation now in progress)
poll([{fd=4, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 86400000) = 1 ([{fd=4, revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
......
我看冯老师的日志中确实有 Redis 连接的「痕迹」。端口是 6379 ,大概率是 Redis 的问题。
「php -m 怎么会触发连接 Redis 呢?我的 strace 命令怎么没有跟踪到呢,你是怎么跟踪到的?」
「用 strace php -m。你是不是用 strace 跟踪的进程号?」
「是的。」
「你用 strace 跟踪进程的时候,可能连接 redis 的操作已经执行了,所以在控制台界面没有打印出来。」
听到这里,我若有所思。
php -m
怎么会触发连接 redis 的操作呢?我怎么想也想不明白,但是strace
跟踪到的的确如此。
Session !!!
「你来看,找到在哪里用的了。」
冯老师像发现新大陆一样,摆手让我过去看。
我来到他屏幕前,看到了在php.ini
文件中有一行配置了 Redis 地址。配置的名称是session.save_path
。我恍然大悟,瞬间明白是怎么回事了。
session 可以设置存储机制为 redis
。当设置了 Redis 的时候,存储路径自然要设置 Redis 地址了。
原来如此。
我谢过冯老师,并在记账簿上记下:「欠冯老师猪头肉一顿」。冯老师嘴角微微上扬,洋溢着得意的笑容。
后续工作
虽然问题解决了,但是有些疑点仍然值得进一步探究。
- strace 命令的高级用法整理。
- PHP 脚本底层执行过程研究(比如
php -v
和php -m
执行过程的区别)。
关于这些疑点,我会单独整理成文章。感谢大家的持续关注~
本作品采用《CC 协议》,转载必须注明作者和本文链接
看到楼主的文章后,又去温习了CLI的生命周期,在模块初始化阶段:
加载


php.ini
在注册扩展之前,难怪php -m
会报错,感谢楼主分享。strace是神器,我遇到过接口卡慢的情况,怀疑是mysql,但是我们没有nginx日志、mysql日志,各种日志都没有,真是头皮发麻,只好用strace分析进程调用,最后分析下来,不是mysql慢,是redis有个key的值太大了,导致接口卡慢。当时用的脚本如下: