开发中遇到的gzuncompress,DomDocument等几个小问题以及一次Php上线碰到的502问题及php异常追踪

一、开发中遇到的gzuncompress,DomDocument等几个小问题记在此

        1，昨天在命令行模式行运行一个很复杂的程序，一开始执行php，刚刚连接数据库，都没怎么查几条记录，（publish:October 27, 2017 -Friday） 就报错：

Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 20480 bytes) in..。

        一开始看到这报错，还真是一头雾水，因为我这个程序正常运行出现内存溢出是完全可能的，因为会进行百万级的数据库查询，并且要生成几百M的数据文件出来，但目前我只是在调试程序，暂时还不应该出现这种报错啊。

        然后再一看不对啊，报错提示允许内存128M,我这才申请多大点内存，怎么报错呢。使用php --ini 查看所使用的ini文件位置，才发现php才刚安装，php.ini文件都还没有，然后将此文件配置好，再次执行，果然正常。看来如果没有php.ini文件，php命令行下执行命令的默认内存申请限制是20480 bytes（即2M）.

        2、在使用gzuncompress时碰到报错。Warning: gzuncompress(): insufficient memory这也真是个诱惑的问题，php的压缩内容方法第二个参数是表示压缩等级，从0-9，0表示不压缩，9为最高压缩，而gzuncompress第二个参数也是个整数，一不小心就把这两个方法的第二个参数整到一起去了，以为是以哪个等级压缩，就要以哪个等级解压缩。

        原来gzuncompress的第二个参数根本不是压缩等级，而是解压出来的字符串长度限制。

string gzcompress ( string $data [, int $level = -1 [, int $encoding = ZLIB_ENCODING_DEFLATE ]] )
string gzuncompress ( string $data [, int $length = 0 ] )

        3、今天考虑将一个较大的数据存储至redis, 最后一算这些字符内容整个大小400多M，于是看了一下redis单个key的最大值限制，发现其要求在512M以下，A String value can be at max 512 Megabytes in length.虽然目前我的数据没有超过这个数，但是因为数据还会增长，后期超过的可能性很大，另外即便不会超过，也不能一直打着擦边球运行啊。于是考虑使用压缩。这也就是上面遇到gzuncompress问题的原因了。

        php内容的压缩也考虑过其它的方法，比如之前一直用的msg_pack。但是这次使用msg_pack很意外，不知道为什么，压缩后的文件大小既然和压缩前一样，看了几遍代码觉得非常不可思议，但也没发出代码上的问题。我压缩的是个超长的XML内容，不知道是否与这有关。另外关于gzcompress的压缩率，我这压缩前的数据文件大小在480M，压缩后80来M。压缩率达到了6分之一。在我这个业务里完全满意这个效果。

        4、处理xml的php类DomDocument在操作添加添加元素时，元素名称不能是以数字开头，比如：

$Xmlmake = new DomDocument('1.0', 'utf-8');
$sphinxXml = $Xmlmake->createElement('3g'); #此项会报错

        另外xml元素创建节点值时，xml本身会对一些特殊字符作转义处理，比如<>符号，因为它会打乱xml的结构，所以如果你的值中有html元素，而又不想它转义，可以区分使用如下方法。

$text = $Xmlmake->createCDATASection($value); #如果值里面可能有特殊字符，使用createCDATASection，会自动将值处理成：<![CDATA[数据值]]>
$text = $Xmlmake->createTextNode($value);如果字段值都是一些明确没有特殊字符的值这样即可。

         最后的前一篇文章里有提到类DomDocument在输出xml字符串时，默认是不带有缩进的，可以设置类的属性formatOutput为true.从而使生成的xml文件自动缩进。方便查阅。

二、一次上线碰到的502问题及php异常追踪

    今天在上线时遇到了一些502报错，但并非大量，在上线后的几分钟里报了个几十条，程序中已经使用了register_shutdown_function方法捕获最终的异常并进行报错记录，但这次发生502时，PHP程序根本未记录任何错误。publish:December 26, 2017 -Tuesday 查看web里的nginx报错日志如下：

2017/12/26 17:03:00 [error] 11589#0: *202518654 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 192.168.168.164, server: 04007.cn, request: "GET /search/AF04A6B6C9B45D9624514 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "fangha.com"

    主要的报错日志：Connection reset by peer) while reading response header from upstream 表示php执行时间较长，并超出php-fpm.conf的request_terminate_timeout设置的秒数。但此处没有更详细的日志了。request_terminate_timeout用于设置当某个php脚本运行最长时间，若超出php-fpm进程管理器强行中止当前程序，并关闭fastcgi和nginx的网络连接，然后nginx中就会出现Connection reset by peer的错误了。

【建议】为了更详情地掌握nginx运行异常，建议在nginx的全局配置中将日志级别记入notice。这样可以记录nginx的详细异常信息。如下：

error_log   logs/error.log notice;

查看PHP.ini中配置的php日志：error_log = /opt/data/logs/php/php_errors.log

[26-Dec-2017 19:30:29 PRC] PHP Warning:  Invalid argument supplied for foreach() in /opt/fangha.com/revs/r20171226_1821/app/controller/aController.php on line 1428

发现一条warning日志，但从报错来看这条日志并非致命日志，可以忽略这条日志。

    查看php-fpm的日志：; Default Value: log/php-fpm.log;error_log = log/php-fpm.log 发现在这次上线后出现一些php进程出现重启，看来正是php进行执行时间过长超时，导致php重启，进而最终体现在proxy上记录的502错误。但诡异的是WEB上并没有记录任何错误日志。

[26-Dec-2017 16:54:44] WARNING: [pool www] child 25560 exited with code 1 after 100614.838080 seconds from start
[26-Dec-2017 16:54:44] NOTICE: [pool www] child 5894 started
[26-Dec-2017 16:54:47] WARNING: [pool www] child 25603 exited with code 1 after 100618.063972 seconds from start
[26-Dec-2017 16:54:47] NOTICE: [pool www] child 5895 started

 此时感觉没法查了，能查的日志都查了，只知道这次上线的东西导致了部分请求过慢，但出异常的量却很少。所以：

【建议】开启fpm的slowlog，及时发现性能问题：

request_slowlog_timeout = 2s    #执行时间超过2秒，则进行记录日志
slowlog = var/log/slow.log
request_terminate_timeout = 10s #执行时间不能超过这个值

      幸运的是，上线出异常后，我一直tail -f 错误日志目录里的所有日志文件，期间发现一个日志文件一直在出现提示(被改变)，即这个日志文件一直被其它的进程在修改，立即引起了我的注意，因为它很熟悉，我拿着这个文件名在程序里查找，发现我这次调用的日志生成方法是非追加写append，我便开始怀疑和此项有关。

      因为我上线的时候有一个数据缓存文件是不存在的，上线之后才会陆续生成一个缓存文件，文件不存在并不会导致文件异常，但是文件不存在我会记录一个日志，此处不小心用了一个debug(需要覆盖写)的日志写入方法，我想应该是这里的问题导致很多php进程在等待写入最终造成一些php进程执行超时。万幸的是缓存文件很快生成，所以报的错很少，否则一定是一个恶性循环导致更大的问题。

        除了查看日志外，linux也可以使用命令：strace -p 来追踪线程的执行过程，来排查php执行到了哪一步而出现了意外停止。如下为strace -p的执行日志：

[www@B4471 ~]$ ps -ef | grep php
root     10984     1  0 19:13 ?        00:00:00 php-fpm: master process (/opt/soft/php7/etc/php-fpm.conf)
www      10985 10984  0 19:13 ?        00:00:00 php-fpm: pool www              
www      10986 10984  0 19:13 ?        00:00:00 php-fpm: pool www
[www@B4471 ~]$ strace -p 10985
......
access("/oasher.php", F_OK) = 0
access("/oprface.php", F_OK) = 0
poll([{fd=7, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
setsockopt(7, SOL_TCP, TCP_NODELAY, [1], 4) = 0
poll([{fd=7, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
sendto(7, "*2\r\n$3\r\nGET\r\n$25\r\npages_android_"..., 45, MSG_DONTWAIT, NULL, 0) = 45
poll([{fd=7, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
poll([{fd=7, events=POLLIN|POLLERR|POLLHUP}], 1, 5000000) = 1 ([{fd=7, revents=POLLIN}])
recvfrom(7, "$7408\r\n\235\207\242id\2411\246pageid\2411\245title\246\347\262"..., 8192, MSG_DONTWAIT, NULL, NULL) = 1448
poll([{fd=7, events=POLLIN|POLLERR|POLLHUP}], 1, 5000000) = 1 ([{fd=7, revents=POLLIN}])
recvfrom(7, "\203\255\241c\201\246\346\234\200\346\226\260\241u\201\246\350\257\204\345\210\206\241s\243pay\223\201\246\345"..., 8192, MSG_DONTWAIT, NULL, NULL) = 5969
write(4, "\1\6\0\1\37\370\0\0X-Powered-By: PHP/7.0.10"..., 8192) = 8192
chdir("/o821/www") = 0
times({tms_utime=16, tms_stime=3, tms_cutime=0, tms_cstime=0}) = 3013606966
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
fcntl(3, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
write(4, "\1\6\0\1\24\10\0\0\\u6b27\\u7f8e\\u795e\\u5267"..., 5152) = 5152
shutdown(4, SHUT_WR)                    = 0
recvfrom(4, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
recvfrom(4, "", 8, 0, NULL, NULL)       = 0
close(4)                                = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
accept(0,