php加载公司so,导致打开文件句柄不释放问题

今天跟大家分享我近期一个TroubleShoot的一个例子，由于受公司的规定限制，文中有大量删减相关明显住处，请大家谅解。但干货是不会少的。

一个业务在PHP升级 LVS改造后，通过xxxxx.xxxx.com访问论坛页面出现”服务器暂时无法响应，请稍后再试”。

查询httpd的error.log日志，有如下的错误记录

[Wed Mar 07 13:34:28 2012] [error] [client xxx.xxx.xxx.xxx] (24)Too many open files: file permissions deny server access: /usr/local/xxxxxxxx

一台nginx php-fpm运行环境也出现类似的问题

2012/03/07 10:50:20 [error] 23163#0: *248762 connect() failed (111: Connection refused) while connecting to upstream, client: x.x.x.x, server: xxxxxx, request: "GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "xxxxxxxx"

再次重启的，查看了ulimit –a选项，发现默认情况只有1024打开文件数，调整到ulimit –SHn 65535之后再次重启相关服务。

运行一段时间后又出现类似无法打开页面的问题。通过下面命令查询到当前系统已经打开的文件句柄数，可用的句柄数，最大句柄数。

#cat  /proc/sys/fs/file-nr

系统当前状态打开文件也达到10多万了。虽然没有这到最大的可用数了，但有可能是会出现无法打开页面的问题。这种问题的重现概率非常高。

查看系统sock数量,sock数量也特别的多，但总体机器负载并不高，各方面响应都很正常。

# more /proc/net/sockstat

sockets: used 168096

TCP: inuse 791 orphan 31 tw 213 alloc 791 mem 104

UDP: inuse 0

RAW: inuse 0

FRAG: inuse 0 memory 0

 

根据以前经验判断，打开文件过多问题，一般是打开文件没有close靠成的。代码问题可能是居多，但这些都只是猜测，还没有拿得出手的任何证据。近期同时操作了PHP升级和LVS改造，所以这3方面入手进行思考：

一方面，代码没有更新的背景上，还是怀疑PHP升级造成的可能性要大一些，但还觉是不是特别认可这个怀疑，但无法从PHP.net获得更多信息。

另一方面，LVS是非常成熟的技术，只涉及数据包的转发，只是为了验证RS是否存活，会周期性探测80端口是否有响应，会增加一定的访问量，但也只是一次简单GET访问，不会造成WEB无响应的问题。同时监控LVS并未有异常的连接数的增加。

还有就是php加载了过多的公司自已独有的so文件，使整个事件事情的关键点过多，而且需要跨部门协调开发人员，增加了问题分析的复杂度。

通过lsof命令将httpd进程的打开文件都列出来

# ls -l /proc/26455/fd

total 66

lr-x------ 1 root root 64 Mar  8 09:02 0 -> /dev/null

l-wx------ 1 root root 64 Mar  8 09:02 1 -> /dev/null

lr-x------ 1 root root 64 Mar  8 09:02 11 -> eventpoll:[747760290]

lrwx------ 1 root root 64 Mar  8 09:02 12 -> socket:[747876322]

lrwx------ 1 root root 64 Mar  8 09:02 14 -> socket:[747761854]

lrwx------ 1 root root 64 Mar  8 09:02 15 -> socket:[747761855]

lrwx------ 1 root root 64 Mar  8 09:04 16 -> socket:[747765423]

lrwx------ 1 root root 64 Mar  8 09:02 17 -> socket:[747761863]

lrwx------ 1 root root 64 Mar  8 09:02 18 -> socket:[747761873]

lrwx------ 1 root root 64 Mar  8 09:04 19 -> socket:[747765424]

lrwx------ 1 root root 64 Mar  8 09:08 20 -> socket:[747780588]

lrwx------ 1 root root 64 Mar  8 09:05 21 -> socket:[74777028

# lsof -p 26455

COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME

httpd   26455 nobody   14u  sock       0,5           747761854 can't identify protocol

httpd   26455 nobody   15u  sock       0,5           747761855 can't identify protocol

httpd   26455 nobody   16u  sock       0,5           747765423 can't identify protocol

httpd   26455 nobody   19u  sock       0,5           747765424 can't identify protocol

httpd   26455 nobody   20u  sock       0,5           747780588 can't identify protocol

httpd   26455 nobody   22u  sock       0,5           747780589 can't identify protocol

httpd   26455 nobody   23u  sock       0,5           747783801 can't identify protocol

httpd   26455 nobody   24u  sock       0,5           747783802 can't identify protoco

通过strace进行跟踪

# strace -p 9570 –T

accept(0, {sa_family=AF_INET, sin_port=htons(42612), sin_addr=inet_addr("127.0.0.1")}, [16]) = 3 <21.584688> clock_gettime(CLOCK_MONOTONIC, {21313285, 376542000}) = 0 <0.000062>

times({tms_utime=18, tms_stime=18, tms_cutime=0, tms_cstime=0}) = 3849553032 <0.000061>

 poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1 <0.000061>

 read(3, "\1\1\0\1\0\10\0\0", 8) = 8 <0.000061>

 read(3, "\0\1\0\0\0\0\0\0", 8) = 8 <0.000121>

 read(3, "\1\4\0\1\nX\0\0", 8) = 8 <0.000056>

 read(3, "\21\7GATEWAY_INTERFACECGI/1.1\17\5SERV"..., 2648) = 2648 <0.000038>

 read(3, "\1\4\0\1\0\0\0\0", 8) = 8 <0.000063>

 clock_gettime(CLOCK_MONOTONIC, {21313285, 377799000}) = 0 <0.000062>

mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2aea0e294000 <0.000091> setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0 <0.000064>

 rt_sigaction(SIGPROF, {0x6704d0, [PROF], SA_RESTORER|SA_RESTART, 0x2aea06f9cfc0}, {0x6704d0, [PROF], SA_RESTORER|SA_RESTART, 0x2aea06f9cfc0}, 8) = 0 <0.000065> 

对strace的输出内容一时也没有理清头绪，但随着查询文档的增多，也随步加深了对strace输出信息的理解

以nginx php-cgi场景开始重复测试工具，抓取有用信息

lsof 查到的结果

php-fpm 13229 nobody   16u  sock       0,5          154072250 can't identify protocol

php-fpm 13229 nobody   17u  sock       0,5          154072296 can't identify protocol

php-fpm 13229 nobody   18u  sock       0,5          154072297 can't identify protocol

php-fpm 13229 nobody   19u  IPv4 154072299                TCP xxxxx:54089->xxxx:ssql (ESTABLISHED)

php-fpm 13229 nobody   20u  IPv4 154072301                TCP xxxxx:47763->xxxx:ssql (ESTABLISHED)

php-fpm 13229 nobody   21u  IPv4 154072263                TCP xxxxx:38810->xxxx:11507 (ESTABLISHED)

php-fpm 13229 nobody   22u  IPv4 154072303                TCP xxxxx:54091->xxxx:ssql(ESTABLISHED)

php-fpm 13229 nobody   23u  IPv4 154072305                TCP xxxx:54092->xxxx:ssql (ESTABLISHED)

过了几秒钟，再查lsof,发现19,20有变化。

php-fpm 13229 nobody   17u  sock       0,5          154072296 can't identify protocol

php-fpm 13229 nobody   18u  sock       0,5          154072297 can't identify protocol

php-fpm 13229 nobody   19u  sock       0,5          154072384 can't identify protocol

php-fpm 13229 nobody   20u  sock       0,5          154072385 can't identify protocol

php-fpm 13229 nobody   21u  IPv4 154072263                TCP xxxxxx:38810->xxxxx:11507

 (ESTABLISHED)

上面抓取的信息，在一定程度上影响了我的判断，因为19u,20u是因为连接完数据库后，状态才生成的can‘t identify protocol，所以我的关注点转向了数据库连接上面。

继续查询，同时通过另一个终端上面查strace ，根据FD进行从下往上查询，查询FD19,20连接完数据库后，已经进行 正常close()操作了。

但查询到下面4个系统调用是最后使用19，20句柄，就没有下文了。而且没有正常close();

socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 19

ioctl(19, SIOCGIFADDR, {ifr_name="eth1", ifr_addr={AF_INET, inet_addr("xxxxx")}}) = 0

socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 20

ioctl(20, SIOCGIFADDR, {ifr_name="eth1", ifr_addr={AF_INET, inet_addr("xxxxx")}}) = 0

下面没有19和20的任何输出了,当然也没有包括close()的操作。

下面是一个标准的open,close操作记录，便于对比参考。

open("xxxxxx.php", O_RDONLY) = 15 <0.000037>

fstat(15, {st_mode=S_IFREG|0644, st_size=2624, ...}) = 0 <0.000025>

fstat(15, {st_mode=S_IFREG|0644, st_size=2624, ...}) = 0 <0.000026>

fstat(15, {st_mode=S_IFREG|0644, st_size=2624, ...}) = 0 <0.000026>

mmap(NULL, 2624, PROT_READ, MAP_SHARED, 15, 0) = 0x2aea0e315000 <0.000028>

munmap(0x2aea0e315000, 2624)            = 0 <0.000031>

close(15)                               = 0 <0.000028>

通过多次测试，监控系统调用，已经可以定位FD问题是由于socket和ioctl两个系统调产生的，并且处理正确处理造成socket没有释放。

socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 23 <0.000030>

ioctl(23, SIOCGIFADDR, {ifr_name="eth1", ifr_addr={AF_INET, inet_addr("xxxxxx")}}) = 0 <0.000024>

一直在处纠结了很长时间，很长时间…………………………

通过strace 命令可以查到ifcnofig eth1的系统调用有类似输出

# strace -e socket,ioctl ifconfig eth1

到这时候就基本明白了。先要查出PHP是如何调用，查询eth1网关，调和这个IP做什么

传统方法：grep –R eth1 ./   结果很给力，多个.php文件都有调一个get_eth1_ip_str函数（实属运气，如果函数没写eth1类似的名称，还可能查不到哪. ^_^）

2)通过php源代码查到此函数，是公司xxxx.so里面定义实现。手头正好有这个源码，查到get_eth1_ip_str这个函数，很简单就是返回一个eth1的IP地址。

通过简单分析，以及咨询同事，觉是应该是申请了sock,没有进行close造成的。于此问题原因已经找到了。

更新扩展so后，线上测试均正常。没有再出现因为调用这个函数不释放socket句柄的问题