Bug #79713 [Com]: Random extreme execution times on CPU intensive loads
Edit report at https://bugs.php.net/bug.php?id=79713&edit=1
ID: 79713
Comment by: alex dot farcas at race dot com
Reported by: alex dot farcas at race dot com
Summary: Random extreme execution times on CPU intensive
loads
Status: Open
Type: Bug
Package: Performance problem
Operating System: Ubuntu 18.04.1 LTS
PHP Version: 7.4.7
Block user comment: N
Private report: N
New Comment:
We downgraded to PHP 7.4.3 (by upgrading the OS to Ubuntu 20) and the problem has disappeared.
Previous Comments:
------------------------------------------------------------------------
[2020-06-18 20:00:39] alex dot farcas at race dot com
Description:
------------
The issue manifested itself immediately after we upgraded from PHP-FPM 7.4.1 to 7.4.7. We're
using the Ondrej PPA packages.
We have code which looks like this (please ignore it's quality):
foreach ($scratchrows as $ss) {
if ($ss['region']!=$region) continue;
if ($ss['clli_search']!=$clli_search) continue;
if ($ss['city_search']!=$city_search) continue;
if ($ss['propertyname_search']!=$propertyname_search) continue;
if ($ss['address_search']!=$address_search) continue;
$flag=false;
if ($data->search) {
if ($ss['locationid']==$search) $flag=true;
if ($ss['aliaslocationid']==$search) $flag=true;
// if ($ss['nonexistent']==$search) $flag=true;
if (!$flag) continue;
}
$srows[$ss['locationid']]=$ss;
}
Basically, a loop with a lot of comparisons. $scratchrows contains about 30k entries. All the data
is made of plain arrays of strings or strings. On a server with zero traffic, this type of code
randomly takes from sub second to 10 minutes to execute. It's very difficult to reproduce
reliably, but we noticed that it has to do with comparisons with non existent array keys. For
example if we uncomment the one commented line above, the load time increases with about 30 seconds.
Adding one more adds another 30 seconds. Yet sometimes adding these lines has no effect at all and
the whole thing runs in sub second time.
We introduced timings all over the code to make sure we isolate the problem as narrowly as possible.
We basically had a microtime printed before the loop and one after the loop.
Running strace on such a process had the following output:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
78.46 6.252417 34 181733 munmap
21.54 1.716797 9 181380 mmap
0.00 0.000013 4 3 2 write
0.00 0.000012 12 1 futex
0.00 0.000011 2 5 close
0.00 0.000000 0 1 read
0.00 0.000000 0 1 fstat
0.00 0.000000 0 1 poll
0.00 0.000000 0 1 lseek
0.00 0.000000 0 1 setitimer
0.00 0.000000 0 3 sendto
0.00 0.000000 0 3 recvfrom
0.00 0.000000 0 1 shutdown
0.00 0.000000 0 1 fcntl
0.00 0.000000 0 1 chdir
0.00 0.000000 0 1 times
0.00 0.000000 0 1 openat
------ ----------- ----------- --------- --------- ----------------
100.00 7.969250 363138 2 total
------------------------------------------------------------------------
--
Edit this bug report at https://bugs.php.net/bug.php?id=79713&edit=1
Thread (3 messages)