Bug #70984 [Ana]: Script extreme slow compared to 5.6, MAP_HUGETLB problem?

Edit report at https://bugs.php.net/bug.php?id=70984&edit=1 ID: 70984 Updated by: yohgaki@php.net Reported by: arjen at react dot com Summary: Script extreme slow compared to 5.6, MAP_HUGETLB problem? Status: Analyzed Type: Bug Package: Scripting Engine problem Operating System: Linux PHP Version: 7.0.0RC8 Block user comment: N Private report: N New Comment: Huge page setting affects more for 7.0. I observed extremely slow execution (60 secs or more) on occasion when HugePages_Total is 1. The reporter's system uses no huge page and experiences slow execution. My Fedora 22 seems performing better without huge page. It seems we are better to document huge page setting some where in the manual. Previous Comments: ------------------------------------------------------------------------ [2015-12-08 09:20:44] sjon at hortensius dot net Adding vm.nr_hugepages will claim a few pages as huge; making the allocation work. @yohgaki: it will probably be the reboot that 'fixes' this for you, like I already posted. However, PHP should fail better when no hugepages can be allocated. Imo the allocator should store a HUGETLB failure for x number of runs / time instead of keep trying (which seems to have a significant impact on performance). Increasing nr_hugepages is a workaround; and potentially claims memory that can not be used by applications not using HUGETLB allocations. ------------------------------------------------------------------------ [2015-12-08 09:15:26] yohgaki@php.net It appears vm.nr_hugepages=0 helped also. PHP 7.0 debug build [yohgaki@dev PHP-7.0]$ time ./php-bin t.php real 0m0.839s user 0m0.812s sys 0m0.026s [yohgaki@dev PHP-7.0]$ time ./php-bin t.php real 0m0.847s user 0m0.819s sys 0m0.027s PHP 5.6 Fedora 22 rpm package [yohgaki@dev PHP-7.0]$ time php t.php real 0m1.166s user 0m0.805s sys 0m0.195s [yohgaki@dev PHP-7.0]$ time php t.php real 0m1.012s user 0m0.816s sys 0m0.205s ------------------------------------------------------------------------ [2015-12-08 09:03:10] yohgaki@php.net My system is Fedora 22 with 32GB memory. 'sysctl -a | grep huge' showed only 1 huge page. PHP 7 was about 100% or more slower than PHP 5.6 with the test script. I set vm.nr_hugepages=512 in /etc/sysctl.conf and rebooted the system as it seemed rebooting is required. PHP 7.0 (debug build) $ time ./php-bin t.php real 0m0.938s user 0m0.910s sys 0m0.027s PHP 5.6 (Fedora22) $ time php t.php real 0m1.099s user 0m0.882s sys 0m0.226s It appears vm.nr_hugepages=512 helped a lot. Thanks for the tip, Rasmus. vm.nr_hugepages=0 may help, but I didn't test this. (yet) ------------------------------------------------------------------------ [2015-11-29 17:01:25] sjon at hortensius dot net Not sure if it'll help; but here are the first few lines from perf-report: 33.41% php-7.0.0RC8 [kernel.vmlinux] [k] pageblock_pfn_to_page 31.77% php-7.0.0RC8 [kernel.vmlinux] [k] isolate_freepages_block 3.78% php-7.0.0RC8 [kernel.vmlinux] [k] get_pfnblock_flags_mask 2.96% php-7.0.0RC8 libc-2.22.so [.] __memcpy_avx_unaligned 2.51% php-7.0.0RC8 [kernel.vmlinux] [k] memcmp 2.23% php-7.0.0RC8 [kernel.vmlinux] [k] compaction_alloc valgrind-cachegrind tells me most instruction cost (56%) goes towards __memcpy_avx_unaligned, then 34% into unknown and the rest is < 4% each. Strace shows the same as reported. If you are unable to reproduce or need anything else, I'm happy to help! ------------------------------------------------------------------------ [2015-11-29 10:08:06] sjon at hortensius dot net I tried testing this, this specific (bare-metal/archlinux-4.2.5) machine refused to increase hugepages until I dropped caches to free some memory. After I did this, the speed immediately increased even without increasing the actual hugepages setting. On this machine, I have the following stats before dropping caches: Performance counter stats for '/srv/http/3v4l.org/bin/php-7.0.0RC8 ./hugepages.php': 39181.707776 task-clock (msec) # 0.997 CPUs utilized 132 context-switches # 0.003 K/sec 1 cpu-migrations # 0.000 K/sec 23,446 page-faults # 0.598 K/sec 133,246,942,916 cycles # 3.401 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 131,441,748,754 instructions # 0.99 insns per cycle 35,752,523,403 branches # 912.480 M/sec 273,889,941 branch-misses # 0.77% of all branches 39.303890805 seconds time elapsed ---------------------------------------------------------------------------- Performance counter stats for '/srv/http/3v4l.org/bin/php-5.6.16 ./hugepages.php': 1511.186576 task-clock (msec) # 0.931 CPUs utilized 165 context-switches # 0.109 K/sec 13 cpu-migrations # 0.009 K/sec 8,528 page-faults # 0.006 M/sec 4,878,265,167 cycles # 3.228 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 4,934,451,314 instructions # 1.01 insns per cycle 1,079,838,152 branches # 714.563 M/sec 22,318,535 branch-misses # 2.07% of all branches 1.623016972 seconds time elapsed **************************** After drop_caches: **************************** Performance counter stats for '/srv/http/3v4l.org/bin/php-7.0.0RC8 ./hugepages.php': 698.424928 task-clock (msec) # 0.711 CPUs utilized 124 context-switches # 0.178 K/sec 21 cpu-migrations # 0.030 K/sec 2,303 page-faults # 0.003 M/sec 2,221,973,568 cycles # 3.181 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 1,864,390,002 instructions # 0.84 insns per cycle 447,618,521 branches # 640.897 M/sec 9,212,550 branch-misses # 2.06% of all branches 0.982939191 seconds time elapsed ---------------------------------------------------------------------------- Performance counter stats for '/srv/http/3v4l.org/bin/php-5.6.16 ./hugepages.php': 1004.733041 task-clock (msec) # 0.579 CPUs utilized 117 context-switches # 0.116 K/sec 6 cpu-migrations # 0.006 K/sec 5,651 page-faults # 0.006 M/sec 3,191,485,063 cycles # 3.176 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 3,684,100,051 instructions # 1.15 insns per cycle 762,235,655 branches # 758.645 M/sec 17,702,881 branch-misses # 2.32% of all branches 1.736382087 seconds time elapsed ------------------------------------------------------------------------ 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=70984 -- Edit this bug report at https://bugs.php.net/bug.php?id=70984&edit=1