php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login

go to bug id or search bugs for

Bug #79794 Speed degradation with many NOTICEs and set_error_handler
Submitted: 2020-07-05 00:18 UTC Modified: 2020-07-09 09:20 UTC
Votes:2
Avg. Score:4.0 ± 0.0
Reproduced:2 of 2 (100.0%)
Same Version:2 (100.0%)
Same OS:1 (50.0%)
From: oleg at salionov dot ru Assigned: laruence (profile)
Status: Closed Package: Performance problem
PHP Version: 7.4.7 OS: Debian GNU/Linux 9
Private report: No CVE-ID: None
View Developer Edit
 [2020-07-05 00:18 UTC] oleg at salionov dot ru 
Description:
------------
I have speed degradation when code have error_handler

On 7.4.6 I have results <= 1s in output
On 7.4.7 I have results >= 20s


here is results of strace -c on 2 versions of PHP

PHP 7.4.6
strace -c php test.php
double(28.002721071243)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.43    4.600459          46    100009           gettimeofday
  0.11    0.004931         105        47           munmap
  0.09    0.004235          21       202           mmap
  0.06    0.003006          21       144           mprotect
  0.06    0.002844          26       111        19 open
  0.06    0.002577          32        80           rt_sigaction
  0.05    0.002182          20       111           fstat
  0.04    0.001781          19        96           close
  0.04    0.001768          19        93           read
  0.02    0.001028          19        55        54 access
  0.01    0.000420          19        22           brk
  0.01    0.000378          24        16         4 stat
  0.01    0.000337          26        13         1 lstat
  0.01    0.000236          11        22           futex
  0.00    0.000176          15        12        12 ioctl
  0.00    0.000144          48         3           getcwd
  0.00    0.000080          80         1           write
  0.00    0.000070          35         2           getrlimit
  0.00    0.000061          61         1           execve
  0.00    0.000049          49         1           clock_gettime
  0.00    0.000048          24         2           rt_sigprocmask
  0.00    0.000046          23         2           getdents
  0.00    0.000035          35         1           lseek
  0.00    0.000033          33         1           socket
  0.00    0.000028          28         1           sysinfo
  0.00    0.000023          23         1           clock_getres
  0.00    0.000007           7         1           readlink
  0.00    0.000005           5         1           arch_prctl
  0.00    0.000005           5         1           set_tid_address
  0.00    0.000005           5         1           getrandom
  0.00    0.000004           4         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    4.627001                101054        90 total



PHP 7.4.7

strace -c php test.php
double(67.658080101013)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 43.95 1637.994611       16378    100009           gettimeofday
 36.99 1378.316977       19977     68996           munmap
 18.46  688.027506       19834     34689           mmap
  0.11    4.025349       27954       144           mprotect
  0.08    3.104728       27971       111        19 open
  0.08    3.102637       27952       111           fstat
  0.07    2.683311       27951        96           close
  0.07    2.599923       27956        93           read
  0.06    2.236857       27961        80           rt_sigaction
  0.04    1.537768       27959        55        54 access
  0.02    0.615141       27961        22           brk
  0.02    0.614762       27944        22           futex
  0.01    0.447294       27956        16         4 stat
  0.01    0.363522       27963        13         1 lstat
  0.01    0.335352       27946        12        12 ioctl
  0.00    0.083917       27972         3           getcwd
  0.00    0.055945       27973         2           rt_sigprocmask
  0.00    0.055918       27959         2           getdents
  0.00    0.055898       27949         2           getrlimit
  0.00    0.027985       27985         1           clock_gettime
  0.00    0.027973       27973         1           lseek
  0.00    0.027967       27967         1           socket
  0.00    0.027964       27964         1           sysinfo
  0.00    0.027962       27962         1           write
  0.00    0.027960       27960         1           clock_getres
  0.00    0.027948       27948         1           execve
  0.00    0.027945       27945         1           readlink
  0.00    0.027943       27943         1           getrandom
  0.00    0.027942       27942         1           arch_prctl
  0.00    0.027937       27937         1           set_tid_address
  0.00    0.027937       27937         1           set_robust_list
  0.00    0.021011       10506         2           mremap
------ ----------- ----------- --------- --------- ----------------
100.00 3726.613890                204492        90 total



OPCodes are identical in both versions

I think problem in that commit https://github.com/php/php-src/commit/ccd41e083359cf6dd264f88806dce4cc49d9358e

Test script:
---------------
<?php

error_reporting(E_NOTICE);

function my_error_handler($code, $msg, $file, $line)
{
}

$old_error_handler = set_error_handler('my_error_handler');


$time = microtime(true);

$a = [];
$i = 50000;
while ($i-- > 0) {
    if (
        !is_array($a[$i])
        ||
        !in_array($i, $a[$i], true)
    ) {
        $a[$i][] = $i;
    }
}
var_dump(microtime(true) - $time);

Patches

Pull Requests

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2020-07-05 00:24 UTC] oleg at salionov dot ru 
On 7.4.6 I have results on test script <= 1s in output
On 7.4.7 I have results on test script >= 20s
 [2020-07-06 08:47 UTC] oleg at salionov dot ru 
PHP 7.4.6 without modules (e.g. xdebug)

strace -c php -n  test.php
float(0.11966705322266)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 16.32    0.002045          89        23           munmap
 15.43    0.001934          12       157           mmap
 14.64    0.001834          21        87           rt_sigaction
 13.34    0.001671          15       110           mprotect
 11.70    0.001466          20        75        16 open
  9.10    0.001140          17        67           fstat
  5.00    0.000626          10        65           read
  4.25    0.000533           9        61           close
  4.13    0.000517          11        47        46 access
  2.19    0.000274          21        13         1 lstat
  1.04    0.000130          43         3           getcwd
  0.50    0.000063          63         1         1 ioctl
  0.49    0.000062           3        22           futex
  0.46    0.000058          19         3           gettimeofday
  0.35    0.000044          22         2           rt_sigprocmask
  0.34    0.000042          42         1           lseek
  0.29    0.000036           2        17           brk
  0.16    0.000020           3         6         4 stat
  0.06    0.000008           8         1           readlink
  0.05    0.000006           3         2           getrlimit
  0.04    0.000005           5         1           arch_prctl
  0.04    0.000005           5         1           getrandom
  0.03    0.000004           4         1           set_tid_address
  0.03    0.000004           4         1           clock_getres
  0.02    0.000003           3         1           set_robust_list
  0.00    0.000000           0         1           write
  0.00    0.000000           0         1           socket
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           sysinfo
------ ----------- ----------- --------- --------- ----------------
100.00    0.012530                   772        68 total


PHP 7.4.7 without modules (e.g. xdebug)


strace -c php -n test.php
float(56.749221086502)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 77.47    3.992071          58     68971           munmap
 22.15    1.141526          33     34643           mmap
  0.07    0.003792          34       110           mprotect
  0.07    0.003789          51        75        16 open
  0.06    0.002870          36        80           rt_sigaction
  0.04    0.001922          41        47        46 access
  0.04    0.001897          30        63           close
  0.04    0.001872          29        65           read
  0.03    0.001585          24        67           fstat
  0.01    0.000446          34        13         1 lstat
  0.01    0.000364          17        22           futex
  0.00    0.000198          12        17           brk
  0.00    0.000089          30         3           gettimeofday
  0.00    0.000086          86         1           socket
  0.00    0.000072          24         3           getcwd
  0.00    0.000053          53         1           lseek
  0.00    0.000046          46         1         1 ioctl
  0.00    0.000037          37         1           sysinfo
  0.00    0.000033          17         2           rt_sigprocmask
  0.00    0.000031          31         1           write
  0.00    0.000031          31         1           readlink
  0.00    0.000029          15         2           getrlimit
  0.00    0.000026           4         6         4 stat
  0.00    0.000025          25         1           arch_prctl
  0.00    0.000019          19         1           set_tid_address
  0.00    0.000019          19         1           set_robust_list
  0.00    0.000000           0         2           mremap
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           clock_getres
  0.00    0.000000           0         1           getrandom
------ ----------- ----------- --------- --------- ----------------
100.00    5.152928                104203        68 total
 [2020-07-08 07:36 UTC] dskim at ridi dot com 
To all,

We've stumbled upon the very same problem after updating to 7.4.7. The effect becomes painfully apparent once an error tracking solution like Sentry is implemented. Some cron tasks that took only several minutes on 7.3.x don't even END after several hours(!) on 7.4.7.

Here is a little bit simpler test case we used and the comparison between versions.

Test Script
```php
<?php

function foo() {}
set_error_handler('foo');

$past = microtime(true);
for ($i = 0; $i < 1000000; ++$i) {
    $X[0]; // E_NOTICE
}
$future = microtime(true);

echo ($future - $past) . PHP_EOL;
```

Result
```
$ uname -a
Darwin ____.local 19.5.0 Darwin Kernel Version 19.5.0: Tue May 26 20:41:44 PDT 2020; root:xnu-6153.121.2~2/RELEASE_X86_64 x86_64

$ php73 -v
PHP 7.3.19 (cli) (built: Jul  4 2020 20:25:10) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.3.19, Copyright (c) 1998-2018 Zend Technologies
    with Xdebug v2.9.2, Copyright (c) 2002-2020, by Derick Rethans
    with Zend OPcache v7.3.19, Copyright (c) 1999-2018, by Zend Technologies

$ php73 test.php 
0.8933482170105

$ php74 -v
PHP 7.4.7 (cli) (built: Jun 12 2020 00:04:10) ( NTS )
Copyright (c) The PHP Group
Zend Engine v3.4.0, Copyright (c) Zend Technologies
    with Xdebug v2.9.6, Copyright (c) 2002-2020, by Derick Rethans
    with Zend OPcache v7.4.7, Copyright (c), by Zend Technologies

$ php74 test.php
2.5607399940491
```

Thanks,
Don
 [2020-07-08 07:55 UTC] nikic@php.net
-Assigned To: +Assigned To: laruence
 [2020-07-08 07:55 UTC] nikic@php.net 
I don't think there is a good solution here. I'm inclined to revert @laruence's change in PHP 7.4 and just wait for PHP 8.0, where this issue has been solved by removing the $context argument to the error handler completely.
 [2020-07-08 14:09 UTC] nikic@php.net 
Related To: Bug #79713
 [2020-07-09 09:20 UTC] nikic@php.net
-Status: Assigned +Status: Closed
 [2020-07-09 09:20 UTC] nikic@php.net 
I have now:
 * Reverted https://github.com/php/php-src/commit/ccd41e083359cf6dd264f88806dce4cc49d9358e.
 * Apply a different fix for the original problem in https://github.com/php/php-src/commit/5795dfda93d1f60cce4731e2089ad5975a6c062f. It has a small behavior change in the emission order of notices.
 * Reverted that change while merging into master, as the original issue doesn't apply there (and I don't want to implement a new notice order in jit).
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved. 		Last updated: Sat Dec 21 13:01:31 2024 UTC