Clever Geek Handbook

Php set_time_limit () generates timeout on php-fpm

I have a weird problem with php-fpm and set_time_limit (). After I updated php in general to 5.6.30, the previously running script dies with a timeout.

<?php
set_time_limit( 300 );
echo "ok";

Result:

( ! ) Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/hutml/asd.php on line 2
Call Stack
#   Time    Memory  Function    Location
1   0.0002  238976  {main}( )   .../asd.php:0
2   0.0004  239616  set_time_limit ( )  .../asd.php:2

Interesting part: if I restart php-fpm it works for multiple requests (3-8) and stops working forever (until next restart).

Here's the trace that doesn't work :

Process 12972 attached
0.000000 accept(0, {sa_family=AF_INET, sin_port=htons(49070), sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
0.738389 clock_gettime(CLOCK_MONOTONIC, {668002, 562282734}) = 0
0.000045 gettimeofday({1494920122, 398537}, NULL) = 0
0.000033 times({tms_utime=5129, tms_stime=553, tms_cutime=0, tms_cstime=0}) = 496191553
0.000057 poll([{fd=4, events=POLLIN}], 1, 5000) = 1 ([{fd=4, revents=POLLIN}])
0.000054 read(4, "\1\1\0\1\0\10\0\0", 8) = 8
0.000042 read(4, "\0\1\0\0\0\0\0\0", 8) = 8
0.000035 read(4, "\1\4\0\1\5b\6\0", 8) = 8
0.000030 read(4, "\f\0QUERY_STRING\16\3REQUEST_METHODGE"..., 1384) = 1384
0.000065 read(4, "\1\4\0\1\0\0\0\0", 8) = 8
0.000041 gettimeofday({1494920122, 398893}, NULL) = 0
0.000031 lstat("/var/www/hutml/asd.php", {st_mode=S_IFREG|0644, st_size=40, ...}) = 0
0.000097 clock_gettime(CLOCK_MONOTONIC, {668002, 562819467}) = 0
0.000059 gettimeofday({1494920122, 399081}, NULL) = 0
0.000040 gettimeofday({1494920122, 399120}, NULL) = 0
0.000033 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
0.000037 rt_sigaction(SIGPROF, {0x5d4980, [PROF], SA_RESTORER|SA_RESTART, 0x7efdf5602510}, {0x5d4980, [PROF], SA_RESTORER|SA_RESTART, 0x7efdf5602510}, 8) = 0
0.000102 rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
0.000633 gettimeofday({1494920122, 399930}, NULL) = 0
0.000101 clock_gettime(CLOCK_MONOTONIC, {668002, 563838495}) = 0
0.000079 getcwd("/", 4095) = 2
0.000039 chdir("/var/www/hutml") = 0
0.000043 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0
0.000035 fcntl(3, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1, len=1}) = 0
0.000081 stat("/var/www/hutml/asd.php", {st_mode=S_IFREG|0644, st_size=40, ...}) = 0
0.000060 gettimeofday({1494920122, 400364}, NULL) = 0
0.000047 gettimeofday({1494920122, 400409}, NULL) = 0
30.079993 --- SIGPROF {si_signo=SIGPROF, si_code=SI_KERNEL, si_value={int=0, ptr=0x100000000}} ---
0.000198 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0
0.000060 rt_sigaction(SIGPROF, {0x5d4980, [PROF], SA_RESTORER|SA_RESTART, 0x7efdf5602510}, {0x5d4980, [PROF], SA_RESTORER|SA_RESTART, 0x7efdf5602510}, 8) = 0
0.000065 rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
0.000546 open("/var/log/php-fpm/www-error.log", O_WRONLY|O_CREAT|O_APPEND, 0644) = 5
0.000275 gettimeofday({1494920152, 481549}, NULL) = 0
0.000216 stat("/usr/share/zoneinfo/UTC", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
0.001098 open("/usr/share/zoneinfo/UTC", O_RDONLY) = 6
0.000030 fstat(6, {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
0.000024 mmap(NULL, 118, PROT_READ, MAP_SHARED, 6, 0) = 0x7efdf7bcc000
0.007856 close(6) = 0
0.007871 munmap(0x7efdf7bcc000, 118) = 0
0.000199 write(5, "[16-May-2017 07:35:52 UTC] PHP F"..., 127) = 127
0.000090 close(5) = 0
0.000056 open("/var/log/php-fpm/www-error.log", O_WRONLY|O_CREAT|O_APPEND, 0644) = 5
0.000133 gettimeofday({1494920152, 499120}, NULL) = 0
0.000039 write(5, "[16-May-2017 07:35:52 UTC] PHP S"..., 44) = 44
0.000033 close(5) = 0
0.000090 open("/var/log/php-fpm/www-error.log", O_WRONLY|O_CREAT|O_APPEND, 0644) = 5
0.000031 gettimeofday({1494920152, 499310}, NULL) = 0
0.000028 write(5, "[16-May-2017 07:35:52 UTC] PHP "..., 70) = 70
0.000026 close(5) = 0
0.000038 open("/var/log/php-fpm/www-error.log", O_WRONLY|O_CREAT|O_APPEND, 0644) = 5
0.000026 gettimeofday({1494920152, 499428}, NULL) = 0
0.000027 write(5, "[16-May-2017 07:35:52 UTC] PHP "..., 78) = 78
0.000023 close(5) = 0
0.000085 chdir("/") = 0
0.000072 clock_gettime(CLOCK_MONOTONIC, {668032, 663420619}) = 0
0.000029 times({tms_utime=8131, tms_stime=553, tms_cutime=0, tms_cstime=0}) = 496194562
0.000092 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
0.000280 umask(022) = 022
0.000237 fcntl(3, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
0.001047 write(4, "\1\6\0\1\0g\1\0Status: 500 Internal Ser"..., 128) = 128
0.000869 shutdown(4, SHUT_WR) = 0
0.000451 recvfrom(4, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
0.000043 recvfrom(4, "", 8, 0, NULL, NULL) = 0
0.000020 close(4) = 0
0.000037 clock_gettime(CLOCK_MONOTONIC, {668032, 666524271}) = 0
0.000052 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
0.000040 clock_gettime(CLOCK_MONOTONIC, {668032, 666616844}) = 0
0.000023 accept(0, Process 12972 detached

And another one where it works:

Process 13888 attached
0.000000 accept(0, {sa_family=AF_INET, sin_port=htons(49118), sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
2.933113 clock_gettime(CLOCK_MONOTONIC, {668265, 781254874}) = 0
0.000116 gettimeofday({1494920385, 617536}, NULL) = 0
0.000157 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 496217871
0.000140 poll([{fd=4, events=POLLIN}], 1, 5000) = 1 ([{fd=4, revents=POLLIN}])
0.000517 read(4, "\1\1\0\1\0\10\0\0", 8) = 8
0.000301 read(4, "\0\1\0\0\0\0\0\0", 8) = 8
0.000135 read(4, "\1\4\0\1\5b\6\0", 8) = 8
0.000104 read(4, "\f\0QUERY_STRING\16\3REQUEST_METHODGE"..., 1384) = 1384
0.000253 read(4, "\1\4\0\1\0\0\0\0", 8) = 8
0.000233 gettimeofday({1494920385, 619407}, NULL) = 0
0.000081 lstat("/var/www/hutml/asd.php", {st_mode=S_IFREG|0644, st_size=40, ...}) = 0
0.000280 lstat("/var/www/hutml", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
0.000083 lstat("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
0.000140 lstat("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
0.000154 clock_gettime(CLOCK_MONOTONIC, {668265, 783895254}) = 0
0.000287 gettimeofday({1494920385, 620465}, NULL) = 0
0.000384 gettimeofday({1494920385, 620818}, NULL) = 0
0.000161 stat("/var/www/hutml/.user.ini", 0x7ffd7f6695a0) = -1 ENOENT (No such file or directory)
0.000245 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
0.000147 rt_sigaction(SIGPROF, {0x5d4980, [PROF], SA_RESTORER|SA_RESTART, 0x7fe68069d510}, {SIG_DFL, [], 0}, 8) = 0
0.000218 rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
0.001945 brk(0x17b0000) = 0x17b0000
0.001032 gettimeofday({1494920385, 624573}, NULL) = 0
0.000481 gettimeofday({1494920385, 625048}, NULL) = 0
0.000219 gettimeofday({1494920385, 625286}, NULL) = 0
0.000154 open("/var/www/hutml/asd.php", O_RDONLY) = 5
0.000168 fstat(5, {st_mode=S_IFREG|0644, st_size=40, ...}) = 0
0.000264 fstat(5, {st_mode=S_IFREG|0644, st_size=40, ...}) = 0
0.000262 fstat(5, {st_mode=S_IFREG|0644, st_size=40, ...}) = 0
0.000215 mmap(NULL, 40, PROT_READ, MAP_SHARED, 5, 0) = 0x7fe682c67000
0.000130 clock_gettime(CLOCK_MONOTONIC, {668265, 790237375}) = 0
0.000117 getcwd("/", 4095) = 2
0.000160 chdir("/var/www/hutml") = 0
0.000266 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0
0.000058 fcntl(3, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1, len=1}) = 0
0.000044 stat("/var/www/hutml/asd.php", {st_mode=S_IFREG|0644, st_size=40, ...}) = 0
0.001159 fcntl(3, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=1}) = 0
0.000133 fcntl(3, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=1}) = 0
0.000049 munmap(0x7fe682c67000, 40) = 0
0.000046 close(5) = 0
0.000054 gettimeofday({1494920385, 628504}, NULL) = 0
0.000092 gettimeofday({1494920385, 628597}, NULL) = 0
0.000061 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
0.000033 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={300, 0}}, NULL) = 0
0.000080 chdir("/") = 0
0.000061 clock_gettime(CLOCK_MONOTONIC, {668265, 792621333}) = 0
0.000053 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 496217872
0.000076 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
0.000152 fcntl(3, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
0.000068 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
0.000068 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0
0.000236 write(4, "\1\6\0\1\0F\2\0X-Powered-By: PHP/5.6.30"..., 96) = 96
0.000208 shutdown(4, SHUT_WR) = 0
0.000435 recvfrom(4, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
0.000059 recvfrom(4, "", 8, 0, NULL, NULL) = 0
0.000064 close(4) = 0
0.000041 clock_gettime(CLOCK_MONOTONIC, {668265, 794075045}) = 0
0.000078 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
0.000039 clock_gettime(CLOCK_MONOTONIC, {668265, 794190802}) = 0
0.000030 accept(0, Process 13888 detached

If you have any ideon / experience / whatever, please feel free to share with me.

Thank.

+3


source to share


2 answers


I expanded /etc/nginx/nginx.conf http section as follows:



client_header_timeout 3000;
client_body_timeout 3000;
fastcgi_read_timeout 3000;
client_max_body_size 32m;
fastcgi_buffers 8 128k;
fastcgi_buffer_size 128k;
0


source


This is due to the large amount of memory on your system.

You need to change your php.ini file with max execution time to 1200ms



Remember to restart the apache server after changing php.ini

0


source






More articles:


All Articles