Bug #79794 [Asn->Csd]: Speed degradation with many NOTICEs and set_error_handler

Edit report at https://bugs.php.net/bug.php?id=79794&edit=1 ID: 79794 Updated by: nikic@php.net Reported by: oleg at salionov dot ru Summary: Speed degradation with many NOTICEs and set_error_handler -Status: Assigned +Status: Closed Type: Bug Package: Performance problem Operating System: Debian GNU/Linux 9 PHP Version: 7.4.7 Assigned To: laruence Block user comment: N Private report: N New Comment: 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). Previous Comments: ------------------------------------------------------------------------ [2020-07-08 14:09:30] nikic@php.net Related To: Bug #79713 ------------------------------------------------------------------------ [2020-07-08 07:55:48] 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 07:36:32] 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-06 08:47:58] 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-05 00:24:32] 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 ------------------------------------------------------------------------ The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at https://bugs.php.net/bug.php?id=79794 -- Edit this bug report at https://bugs.php.net/bug.php?id=79794&edit=1