Bug #79794 [Opn]: Speed degradation with many NOTICEs and set_error_handler

Edit report at https://bugs.php.net/bug.php?id=79794&edit=1 ID: 79794 User updated by: oleg at salionov dot ru Reported by: oleg at salionov dot ru Summary: Speed degradation with many NOTICEs and set_error_handler Status: Open Type: Bug Package: Performance problem Operating System: Debian GNU/Linux 9 PHP Version: 7.4.7 Block user comment: N Private report: N New Comment: 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 Previous Comments: ------------------------------------------------------------------------ [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 ------------------------------------------------------------------------ [2020-07-05 00:18:49] 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); ------------------------------------------------------------------------ -- Edit this bug report at https://bugs.php.net/bug.php?id=79794&edit=1