php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #79713 Random extreme execution times on CPU intensive loads
Submitted: 2020-06-18 20:00 UTC Modified: 2020-07-08 14:09 UTC
Votes:2
Avg. Score:4.0 ± 1.0
Reproduced:0 of 0 (0.0%)
From: alex dot farcas at race dot com Assigned:
Status: Duplicate Package: Performance problem
PHP Version: 7.4.7 OS: Ubuntu 18.04.1 LTS
Private report: No CVE-ID: None
 [2020-06-18 20:00 UTC] 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





Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2020-07-08 14:06 UTC] alex dot farcas at race dot com
We downgraded to PHP 7.4.3 (by upgrading the OS to Ubuntu 20) and the problem has disappeared.
 [2020-07-08 14:09 UTC] nikic@php.net
-Status: Open +Status: Duplicate
 [2020-07-08 14:09 UTC] nikic@php.net
This looks like a duplicate of bug #79794, which has a bit more information.
 
PHP Copyright © 2001-2020 The PHP Group
All rights reserved.
Last updated: Fri Sep 25 16:01:24 2020 UTC