php cgi对单个流量最大执行时间和作用域

2020-04-10 本文已影响0人舒小贱

一，总结

php.ini的max_execution_time设置的超时时间是指：cgi worker进程处理一次请求的周期中，占用cpu时间分片的最大总时间，不包括系统调用，比如本地磁盘io等待时间，比如网络io等待时间。
如果一次请求执行时间超过max_execution_time，php只是认为是一次php fatal，跟普通的fatal，比如syntax error无异。cgi会结束此次请求并跳转到执行注册在register_shutdown_function里面的函数，完成之后就可以开始下一个请求处理周期。比如我们现在的日志就会在这种情况下正常记录，但是日志中会缺少fatal之后的数据，这一点在trouble shotting的时候尤要注意
php-fpm.conf的request_terminate_timeout设置的超时时间是指：cgi worker进程处理一次请求的最大时间，包括系统调用(磁盘io，网卡io等)。
如果一次请求执行时间超过request_terminate_timeout，php-fpm会直接kill cgi worker进程并立即重启一个新的worker进程。进程都被kill了，所以超时以后的代码都不会执行，包括register_shutdown_function里的注册函数。
request_terminate_timeout 计时范围，开始于请求到来，结束于请求结束，不包括register_shutdown_function里的注册函数执行时间。有个风险在于，注册函数如果有死循环，会一直执行下去，永远不会被kill掉

二，背景资料

1）现象

发现用某个固定的流量，往ui模块sandbox实例发请求，nginx有日志，但是php打印的sialog，ral-worker.log等业务日志都没有打印。而且下游的us打印了日志，在us耗时大约15s。php发生了什么？？

2）sialog业务日志打印机制

首先，在框架入口，将日志内容写入磁盘的函数notice::points注册在register_shutdown_function。
其次，，在日志内容是一个全局变量point，在请求入口对point初始化，业务流程中往point里面填充打点数据。
最后，cgi处理完请求后，会先将业务响应返回给客户端，然后执行注册的notice::points函数写日志。这样可以减小对客户端的响应时间。

register_shutdown_function(function(){
    if(function_exists("fastcgi_finish_request")){
        NPLogger::gblTimeStart("finish_fastcgi_request_t"); 
        fastcgi_finish_request();
        NPLogger::gblTimeEnd("finish_fastcgi_request_t");
    }
    NPLogger::notice();
    PBLogger::notice();
});

3）nginx和cgi读写超时设置：

nginx和php的socket读、写、连接时间都为8s:

    location ~* ^.*$ {
        fastcgi_pass   unix:/home/work/minping/php7/php/var/php-cgi.sock;
        fastcgi_pass_header SaiyaLogID;
        fastcgi_index  index.php;
        fastcgi_param  SCRIPT_FILENAME  /home/work/minping/temp3/du-ui/du-uiapp/webroot/route.php;
        include        fastcgi_params;
        fastcgi_connect_timeout 8;
        fastcgi_read_timeout    8;
        fastcgi_send_timeout    8;
    }
}

nginx 日志内容：

10.207.184.34 - - [10/Apr/2020:17:44:01 +0800] "POST /saiya/dcs/v1/events HTTP/1.1" 200 719 "-" "version/38" "" "-" "8.016" "0.006"  "8.008" "unix:/home/work/minping/php7/php/var/php-cgi.sock" "ca4a6974-7b0f-11ea-a09c-6c92bf04afcf_DCS-10-207-184-34-8280-0410174353-18042_2"

可以发现cgi很快就往ngx返回了一部分数据(0.006s)，但是ngx等最终的数据超时(8.016s),状态码200。(对于都超时了，为什么状态码是200的同学，移步这里)

但是日志没有打印，初步分析，应该是cgi处理这次请求超时被kill掉了。从us打印完整日志可以推断应该是在ui模块处理respose部分的时候或者尝试将data通过socket文件回传给nginx的时候，被kill掉了。

查看php-error.log无异常(php-error.log不会记录此信息，只会记录cgi进程在处理请求过程中遇到的fatal，warn等解析器解析不了的语法问题)
查看php-fpm.log发现异常：看起来确实是cgi被kill了，重新启动了一个cgi进程：

[10-Apr-2020 17:44:06] WARNING: [pool www] child 22476, script '/home/work/minping/history_second/du-ui/du-uiapp/webroot/route.php' (request: "POST /saiya/dcs/v1/events") execution timed out (12.162005 sec), terminating
[10-Apr-2020 17:44:06] WARNING: [pool www] child 22476 exited on signal 15 (SIGTERM) after 393.411066 seconds from start
[10-Apr-2020 17:44:06] NOTICE: [pool www] child 15303 started

证实确实是有cgi被kill掉了。

4）php cgi进程处理单次请求耗时上限设置

从上面可以看到，肯定是sandbox环境对cgi处理单次请求的耗时做了限制。php配置文件做这个限制的有两个地方：

php.ini文件里面的max_execution_time
php.fpm文件里面的request_terminate_timeout

a）max_execution_time

这个设置很坑，测试的时候你就会发现这个很坑。max_execution_time设置的超时时间是指：cgi进程处理这次请求占用cpu时间分片的最大总时间，不包括系统调用，比如本地磁盘io等待时间，比如网络io等待时间(请求下游时等待返回结果时间。
比如sandbox环境中设置：

max_execution_time = 30     ; Maximum execution time of each script, in seconds
max_input_time = 60 ; Maximum amount of time each script may spend parsing request data
;max_input_nesting_level = 64 ; Maximum input variable nesting level
memory_limit = 128M      ; Maximum amount of memory a script may consume (128MB)

这个30s设置不包括请求下游us的耗时。在代码中sleep测试一下：

sleep(60);

可以发现sleep 60s后cgi依然继续执行，客户端收到响应，日志正常落盘。
只有你的程序实打实的占用cpu时间超过max_execution_time，这个配置项才会work。写一个for循环测试验：

function getMillisecond(){
    list($s1,$s2)=explode(' ',microtime());
    return (float)sprintf('%.0f',(floatval($s1)+floatval($s2))*1000);
}
$teststr = "赵钱孙李，周吴郑王。冯陈褚卫，蒋沈韩杨。朱秦尤许，何吕施张。孔曹严华，金魏陶姜。戚谢邹喻，柏水窦章。云苏潘葛，奚范彭郎。鲁韦昌马，苗凤花方。俞任袁柳，酆鲍史唐。费廉岑薛，雷贺倪汤。滕殷罗毕，郝邬安常。乐于时傅，皮卞齐康。伍余元卜，顾孟平黄。和穆萧尹，姚邵湛汪。祁毛禹狄，米贝明臧。计伏成戴，谈宋茅庞。熊纪舒屈，项祝董梁。杜阮蓝闵，席季麻强。贾路娄危，江童颜郭。梅盛林刁，钟徐邱骆。高夏蔡田，樊胡凌霍。虞万支柯，昝管卢莫。经房裘缪，干解应宗。丁宣贲邓，郁单杭洪。包诸左石，崔吉钮龚。程嵇邢滑，裴陆荣翁。荀羊於惠，甄曲家封。芮羿储靳，汲邴糜松。井段富巫，乌焦巴弓。牧隗山谷，车侯宓蓬。全郗班仰，秋仲伊宫。宁仇栾暴，甘钭厉戎。祖武符刘，景詹束龙。叶幸司韶，郜黎蓟薄。印宿白怀，蒲邰从鄂。索咸籍赖，卓蔺屠蒙。池乔阴鬱，胥能苍双。闻莘党翟，谭贡劳逄。姬申扶堵，冉宰郦雍。卻璩桑桂，濮牛寿通。边扈燕冀，郏浦尚农。温别庄晏，柴瞿阎充。慕连茹习，宦艾鱼容。向古易慎，戈廖庾终。暨居衡步，都耿满弘。匡国文寇，广禄阙东。欧殳沃利，蔚越夔隆。师巩厍聂，晁勾敖融。冷訾辛阚，那简饶空。曾毋沙乜，养鞠须丰。巢关蒯相，查后荆红。游竺权逯，盖益桓公。万俟司马，上官欧阳。夏侯诸葛，闻人东方。赫连皇甫，尉迟公羊。澹台公冶，宗政濮阳。淳于单于，太叔申屠。公孙仲孙，轩辕令狐。钟离宇文，长孙慕容。鲜于闾丘，司徒司空。丌官司寇，仉督子车。颛孙端木，巫马公西。漆雕乐正，壤驷公良。拓跋夹谷，宰父谷梁。晋楚闫法，汝鄢涂钦。段干百里，东郭南门。呼延归海，羊舌微生。岳帅缑亢，况郈有琴。梁丘左丘，东门西门。商牟佘佴，伯赏南宫。墨哈谯笪，年爱阳佟。第五言福，百家姓终。";

$stime = getMillisecond();
for($i=0;$i<2000;$i++){
  for($j=0;$j<1000;$j++){
     $md5 = md5($teststr);
  }
}
$etime = getMillisecond();
$cost = ($etime - $stime)/1000.0;
\NPLogger::get('sialog')->point("max_execution_test", $cost);

然后把max_execution_time设置成3s:

max_execution_time = 3;

运行，发现nginx日志：

172.24.191.20 - - [10/Apr/2020:18:58:37 +0800] "POST /saiya/dcs/v1/events HTTP/1.1" 200 171 "-" "PostmanRuntime/7.6.0" "-" "BDUSS=gyd09-fkltekprdk9tNzhKeUFnYUstUHNqLU1JZFdDUUVTSDhKM1hRdkdscmxjQUFBQUFBJCQAAAAAAAAAAAEAAAAVAr3M48nGvTEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAMYJklzGCZJcU0; BAIDUID=5773F1745A58ED9E3721FC82A8A793BC:FG=1" "3.454" "3.301"  "3.301" "unix:/home/work/minping/php7/php/var/php-cgi.sock" "-"

从nginx日志看，耗时3.3s左右，未超过8s限制。当display_errors=On，往客户端输出错误时，nginx状态码如上，为200；当当display_errors=Off，对客户端隐藏错误，只落php-error.log日志时，nginx状态码为500.

sialog日志:

[NOTICE] [2020-04-10 18:58:37:787355] [sialog] [15865163141605] all_t:- us_t:- appid:dmC983500B0350C3AC self_t:- mod:0 err_source_type:- query_type:0 source_type:- predict_status:- ais_switch:1 sug_presearch:- cuid:6194d52a-0b45-11ea-aebc-6c92bf047345 query:今天天气 version:3 is_filter_passed:- pv_lost:0 request:null response:null logid:15865163141605 access_time:18:58:34.337 finish_fastcgi_request_t:450

从sialog日志看，代码中设置的max_execution_test并未在sialog日志中打印，而且all_t:- us_t:-这些在后面设置的值都没打印(-是最开始)。说明此cgi在超时max_execution_time的地方结束了对该请求的处理，但是会执行注册在register_shutdown_function函数里的notice::put()函数打印日志，结束前的全局变量还都保存着，并在日志中顺利打印出来。

php-error.log日志：(测试的时候，发现竟然没落php-error.log日志，检查了好几遍才发现，原来是php.ini里面php-error.log路径写错，恰好写错的路径存在。。。囧)

[10-Apr-2020 19:57:27 Asia/Shanghai] PHP Fatal error:  Maximum execution time of 3 seconds exceeded in /home/work/minping/history_second/du-ui/du-uiapp/app/ServiceUtils.class.php on line 54

从php-error.log日志来看，记录了一个fatal，php把cgi执行超过max_execution_time时间，记录为fatal，有点奇怪。

php-fpm.log日志：
无输出。看来php确实是把执行超过max_execution_time时间计为php fatal，不会kill cgi进程。cgi进程只是结束此次请求，并可以接着处理下一个请求。

客户端输出(当display_errors=On时)：

<br />
<b>Fatal error</b>:  Maximum execution time of 3 seconds exceeded in
<b>/home/work/minping/history_second/du-ui/du-uiapp/app/ServiceUtils.class.php</b> on line
<b>54</b>
<br />

b）request_terminate_timeout

这个设置符合我们的认知，会把系统调用(包括io等待时间)包含进来。sandbox环境的设置为：

request_terminate_timeout = 10s

当us_t 超过10s时，cgi会被强制kill掉。或者在程序中sleep 12s:

sleep(12);

可以看到nginx日志：

10.207.184.34 - - [10/Apr/2020:17:44:01 +0800] "POST /saiya/dcs/v1/events HTTP/1.1" 200 719 "-" "version/38" "" "-" "8.016" "0.006"  "8.008" "unix:/home/work/minping/php7/php/var/php-cgi.sock" "ca4a6974-7b0f-11ea-a09c-6c92bf04afcf_DCS-10-207-184-34-8280-0410174353-18042_2"

uilog日志没打印。
php-fpm.log日志：

[10-Apr-2020 17:44:06] WARNING: [pool www] child 22476, script '/home/work/minping/history_second/du-ui/du-uiapp/webroot/route.php' (request: "POST /saiya/dcs/v1/events") execution timed out (12.162005 sec), terminating
[10-Apr-2020 17:44:06] WARNING: [pool www] child 22476 exited on signal 15 (SIGTERM) after 393.411066 seconds from start
[10-Apr-2020 17:44:06] NOTICE: [pool www] child 15303 started

至此，完整复现sandbox环境的问题，uilog日志没打印就是因为：cgi执行时间超过了request_terminate_timeout设置的10s，导致cgi被kill掉。

但是还有一点需要注意的是，request_terminate_timeout超时设置对注册在register_shutdown_function里面的钩子函数无效。
恰好我们的日志打印函数notice::notice()是注册在register_shutdown_function里面的。可以在notice函数里面sleep超过request_terminate_timeout时间验证下：

register_shutdown_function(function(){
    if(function_exists("fastcgi_finish_request")){
        NPLogger::gblTimeStart("finish_fastcgi_request_t"); 
        fastcgi_finish_request();
        NPLogger::gblTimeEnd("finish_fastcgi_request_t");
    }
    NPLogger::notice();
    PBLogger::notice();
});


//NPLogger类中notice函数
public static function notice(){
   sleep(12);
   if (is_array(self::$loggers)){
      foreach(self::$loggers as $module_name => $module){
         if (empty($module->_file_prefix)){
            continue;
         }
         $module->put("notice");
      }
   }
}

然后请求一次,首先看nginx日志：

172.24.191.20 - - [10/Apr/2020:20:37:16 +0800] "POST /saiya/dcs/v1 HTTP/1.1" 200 4596 "-" "PostmanRuntime/7.6.0" "-" "BAIDUID=5773F1745A58ED9E3721FC82A8A793BC:FG=1" "0.545" "0.466"  "0.466" "unix:/home/work/minping/php7/php/var/php-cgi.sock" "-"

看到cgi非常快的把响应返回给nginx。

再看sialog日志，过了12s左右正常落盘：

[NOTICE] [2020-04-10 20:41:13:334826] [sialog] [15865224604832] all_t:505 us_t:493 appid:dmC983500B0350C3AC self_t:12 mod:0 err_source_type:- query_type:0 source_type:duer_weather predict_status:- ais_switch:1 sug_presearch:- cuid:4c446b3edbc9722ee13616f4fe5f608c query:今天天气 version:3 is_filter_passed:- pv_lost:0 request:null response:null logid:15865224604832 access_time:20:41:00.827 cgi2ngx_t:0 finish_fastcgi_request_t:0

sialog日志的正常记录，验证了request_terminate_timeout设置对注册在register_shutdown_function里面的函数无效。

再看php-fpm.log和php-error.log，都无异常记录，说明cgi完好。

番外篇：当注册在register_shutdown_function里面的函数有syntax error时，会正常返回响应给客户端吗？

因为返回响应给客户端，然后落日志，都注册在register_shutdown_function中:

register_shutdown_function(function(){
    if(function_exists("fastcgi_finish_request")){
        NPLogger::gblTimeStart("finish_fastcgi_request_t"); 
        fastcgi_finish_request();
        NPLogger::gblTimeEnd("finish_fastcgi_request_t");
    }
    NPLogger::notice();
    PBLogger::notice();
});

我们在notice里面写一个syntax error:

//NPLogger类中notice函数
public static function notice(){
   vvv //syntax error
   if (is_array(self::$loggers)){
      foreach(self::$loggers as $module_name => $module){
         if (empty($module->_file_prefix)){
            continue;
         }
         $module->put("notice");
      }
   }
}

然后试着请求一次，发现php-error.log确实是有错误记录：

[10-Apr-2020 21:22:57 Asia/Shanghai] PHP Parse error:  syntax error, unexpected 'if' (T_IF) in /home/work/minping/history_second/du-ui/du-uiapp/lib/NPLogger.class.php on line 442

但是发现客户端收到的是syntax error:

<br />
<b>Parse error</b>:  syntax error, unexpected 'if' (T_IF) in
<b>/home/work/minping/history_second/du-ui/du-uiapp/lib/NPLogger.class.php</b> on line
<b>442</b>
<br />

而不是我们预想的客户端能收到正常响应，然后php error。这是为什么？？php解释器不是逐行解释逐行执行，下一行的syntax error不影响上一行的正常执行输出吗？？