记一次进程异常退出的问题排查

机器搬家之后,之前一直稳定的PHP多进程程序子进程突然异常退出,但是退出的不是很频繁,查看进程日志并也没有发现有什么导致退出的,问题比较诡异。于是开启了一段问题排查之路。

首先查看内核日志,使用dmesg,拉到最后发现有一些这样的错误,看来确实是崩溃了。

[4791991.998535] php[16776]: segfault at 7f6443ee18c8 ip 00007f6443ee18c8 sp 00007fff4d4ba818 error 15 in libc-2.17.so[7f6443ee1000+2000]
[4792165.192628] php[609]: segfault at 0 ip 000000000075919d sp 00007fff0c6e0578 error 4 in php[400000+94b000]
[4792423.164949] traps: php[2337] general protection ip:75919d sp:7fff0c6e0578 error:0 in php[400000+94b000]
[4793914.900298] traps: php[589] general protection ip:7576b6 sp:7fff0c6e0460 error:0 in php[400000+94b000]
[4794155.124685] php[25418]: segfault at 35007265746c ip 000000000075919d sp 00007fff0c6e0578 error 4 in php[400000+94b000]
[4794677.119847] traps: php[2314] general protection ip:75959b sp:7fff4d4ba840 error:0 in php[400000+94b000]
[4795121.747090] php[4642]: segfault at 0 ip 000000000075919d sp 00007fff0c6e0578 error 4 in php[400000+94b000]
[4795666.787427] php[2372]: segfault at 40 ip 000000000075958c sp 00007fff0c6e0500 error 4 in php[400000+94b000]
[4796212.001686] php[6224]: segfault at 10 ip 000000000075919d sp 00007fff0c6e0578 error 4 in php[400000+94b000]
[4796224.510583] traps: php[6156] general protection ip:75919d sp:7fff0c6e0578 error:0 in php[400000+94b000]
[4796337.623455] php[562]: segfault at 247ec40 ip 000000000247ec40 sp 00007fff0c6e04d8 error 15
[4796427.436886] php[1711]: segfault at ffffffffffffffff ip 00000000007576b6 sp 00007fff0c6e0460 error 5 in php[400000+94b000]
[4796554.025960] php[6662]: segfault at 6b6f01000040 ip 000000000075958c sp 00007fff0c6e0500 error 4 in php[400000+94b000]
[4797141.552356] php[6658]: segfault at 18 ip 0000000000758daf sp 00007fff0c6e04d0 error 4 in php[400000+94b000]
[4797495.302089] php[7239]: segfault at 110 ip 00000000007576d2 sp 00007fff0c6e0460 error 4 in php[400000+94b000]
[4797867.446166] php[8265]: segfault at 247e730 ip 000000000247e730 sp 00007fff0c6e04d8 error 15
[4798245.596106] php[8223]: segfault at 247ef40 ip 000000000247ef40 sp 00007fff0c6e04d8 error 15
[4798514.326132] traps: php[8152] general protection ip:75919d sp:7fff0c6e0578 error:0 in php[400000+94b000]
[4798769.904337] traps: php[7255] general protection ip:7576d2 sp:7fff0c6e0460 error:0 in php[400000+94b000]
[4799427.934198] php[2297]: segfault at 17b57d0 ip 00000000017b57d0 sp 00007fff4d4ba838 error 15
[4800091.548467] php[9826]: segfault at 247ed10 ip 000000000247ed10 sp 00007fff0c6e04d8 error 15
[4800607.342570] php[11239]: segfault at 100000007 ip 000000000075919d sp 00007fff0c6e0578 error 4 in php[400000+94b000]
[4800806.439680] php[9796]: segfault at 247ec90 ip 000000000247ec90 sp 00007fff0c6e04d8 error 15
[4801110.909591] php[8317]: segfault at 247ed20 ip 000000000247ed20 sp 00007fff0c6e04d8 error 15
[4801417.477197] php[9326]: segfault at 0 ip 00000000007576d2 sp 00007fff0c6e0460 error 4 in php[400000+94b000]

运气不错,现在居然就有眉目了。上面的信息一般是内存访问越界导致的。现在找一条看看

php[9326]: segfault at 0 ip 00000000007576d2 sp 00007fff0c6e0460 error 4 in php[400000+94b000]

根据网上的资料,error 后面的数字是比较有用的,上面的是4,转换成二进制是100。

bit2: 值为1表示是用户态程序内存访问越界,值为0表示是内核态程序内存访问越界
bit1: 值为1表示是写操作导致内存访问越界,值为0表示是读操作导致内存访问越界
bit0: 值为1表示没有足够的权限访问非法地址的内容,值为0表示访问的非法地址根本没有对应的页面,也就是无效地址

所以含义就是用户态读取得内存地址无效。但是这个信息太笼统。于是还需要进一步调试,这个时候就要用到core dump了。

开启core dump(核心转储)

Core Dump通常是当程序崩溃的时候,操作系统记录下来当前时间程序的内存状态信息。其中还包括处理器寄存器,程序计数器和堆栈指针,存储器管理信息以及其他处理器和操作系统标志和信息。核心转储通常用于帮助诊断和调试计算机程序中的错误。

更多的信息可以去查阅维基百科 https://en.wikipedia.org/wiki/Core_dump

使用ulimit -c unlimited开启core dump。由于php的核心转储文件比较大,因此建议不要限制core文件的大小,当调试完毕之后关闭coredump之后就好了。

经过一段时间的运行之后,core文件终于生成了。

可以使用下面的命令调试之前生成的core。假设我们已经进入了core文件的目录下面,php安装在/usr/local/php/下面,core文件问core.30983

gdb /usr/local/php/bin/php -c core.30983

之后我们可以看到这么一些信息(关于gdb的使用,可以自行google)

Program terminated with signal 11, Segmentation fault.
#0 0x000000000075958c in _php_stream_set_option ()
Missing separate debuginfos, use: debuginfo-install php55-5.5.6-2.el7.centos.x86_64
(gdb) bt
#0 0x000000000075958c in _php_stream_set_option ()
#1 0x0000000000759648 in _php_stream_eof ()
#2 0x00007fd73cc1f014 in redis_check_eof (redis_sock=redis_sock@entry=0x2847918, no_throw=no_throw@entry=0) at /tmp/pear/temp/redis/library.c:167
#3 0x00007fd73cc1ef8f in redis_sock_write (redis_sock=redis_sock@entry=0x2847918, 
 cmd=0x281b038 "*4\r\n$5\r\nSETEX\r\n$48\r\nlock::createid::b476a966712ffc251747356512675590\r\n$2\r\n10\r\n$1\r\n1\r\n", sz=85)
 at /tmp/pear/temp/redis/library.c:1926
#4 0x00007fd73cbf6113 in zim_Redis_setex (ht=3, return_value=0x28af538, return_value_ptr=0x0, this_ptr=0x2820640, return_value_used=1)
 at /tmp/pear/temp/redis/redis.c:875
#5 0x000000000084e9c8 in zend_do_fcall_common_helper_SPEC ()
#6 0x00000000007c88d8 in execute_ex ()
#7 0x00000000007a1130 in zend_execute_scripts ()
#8 0x0000000000742bfb in php_execute_script ()
#9 0x0000000000850751 in do_cli ()
#10 0x0000000000432c7f in main ()

可以看到引起segfault的原因是phpredis的扩展的问题。目前还没有深入php的源代码,不清楚到底是什么导致读取了非法的内存地址,因此只能去搜索这个错误了。在phpredis的github中的issue中看到有很多人遇到了和我一样的问题,原因是pconnect导致的。在常驻内存的脚本中,使用pconnect可能会引起上面的问题。

最终把pconnect改成connect就没问题了。

赞赏

微信赞赏支付宝赞赏

发表评论

电子邮件地址不会被公开。 必填项已用*标注