线上发现有几个 supervisord 启动的 php 后台进程没有正常工作。上去 strace 了一下,发现卡在了写 stdout 上:
# strace -p 2509 Process 2509 attached - interrupt to quit write(1, "[2015-05-22 18:48:19] **************"..., 82
为啥写 stdout 会卡住呢?看了进程 2509 的 fd 1,原来是个管道,那就是管道对面的进程没有读取数据了。于是就写了个脚本遍历了所有进程的所有 fd 去找管道对面是哪个进程。结果却很神奇,管道对面居然也是进程 2509 自己!
# readlink /proc/2509/fd/1 pipe:[124628537] # readlink /proc/2509/fd/2 pipe:[124628537] # readlink /proc/2509/fd/1066 pipe:[124628537] # readlink /proc/2509/fd/1067 pipe:[124628537]
这就难怪了,显然 php 自己不会干自己读自己写的事,于是就卡住了。但是这又是怎么造成的呢?看到一个进程自己和自己管道,就想到了这应该是父子进程间用管道 ipc,然后没关干净造成的吧。php 是由 supervisord 启动的,又了解到写往 stdout 的是传给 supervisord 记日志用的,同时发现,这个 php 的父进程已经变成了 1,也就是说,supervisord 曾经挂过。那么这问题很可能就是 supervisord 造成的。那么究竟是怎么形成的,又如何避免呢?
于是就去翻了 supervisors 的代码,终于明白了原因。supervisors 启动子进程的流程是这样的。
这里的 minfds 是通过 supervisord 的启动参数设置的,默认为 1024。在 supervisord 的初始过程中,如果发现环境中的 rlimit 小于设置的值,会试图用 minfd 和 minproc 去设置相应的 rlimit 来满足需求,但是当环境中的 rlimit 大于设置时却没有处理,造成实际使用的 RLIMIT_NOFILE 大于 minfd。
出问题的 supervisord 并没有设置这个参数,而系统的 rlimit 的默认 max open files 是 10240。pipe 生成的 fd 是 1066,大于 1024,于是就没有被清理掉。原本正常的管道应该是
php:1 ----------- supervisord: 1066
结果成了
php:1 ----------- supervisord: 1066 php:1066 --/
最后在 supervisord 异常退出时,
原本应该是
php:1 ----------- XXX
结果成了
php:1 ----------- XXX php:1066 --/
正常情况下,supervisord 挂了,管道也就坏了。php 往坏了的管道写数据就会触发 Broken pipe,收到一个 SIGBUS 信号,默认就也会被干掉,不会造成现在的后果。但是由于有一头没清理掉,管道就还没坏,只是存活两头都是 php 自己,再往里写数据,就由于没人去读而卡死了。
要解决问题,就必须在启动 supervisord 时设置 `-a/–minfds` 不小于环境中 max open file 值。一个更好的习惯是,让系统的 soft RLIMIT_NOFILE 保持默认的 1024,调大 hard RLIMIT_NOFILE。然后通过 supervisord 的参数来设置需要的 rlimit。这个值也并部署越大越好,在所有进程退出时,和类似 supervisord 启动子进程时都需要遍历关闭 RLIMIT_NOFILE 的所有 fd。值太大会影响系统性能,同时每个进程的 fd 表也会增大,进程数量多的情况下,还是会多费些内存的。
最后还是去给 supervisord 提交了一个 issue:https://github.com/Supervisor/supervisor/issues/690