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:
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)
Previous Comments:
------------------------------------------------------------------------
[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
------------------------------------------------------------------------
[2015-11-27 21:40:01] rasmus@php.net
Just to verify that it is due to the lack of huge pages, can you configure some and re-run your
test. Something like:
sysctl -w vm.nr_hugepages=256
------------------------------------------------------------------------
[2015-11-27 12:54:26] arjen at react dot com
Description:
------------
Testcase runs in 6.7 sec.
1.7 sec in PHP 5.6.
strace reports lots of ENOMEM (Cannot allocate memory) warnings:
munmap(0x7fd131400000, 2097152) = 0
mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_HUGETLB, -1, 0) = -1 ENOMEM
(Cannot allocate memory)
mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd131400000
madvise(0x7fd131400000, 2097152, MADV_HUGEPAGE) = 0
munmap(0x7fd131400000, 2097152) = 0
mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_HUGETLB, -1, 0) = -1 ENOMEM
(Cannot allocate memory)
mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd131400000
madvise(0x7fd131400000, 2097152, MADV_HUGEPAGE) = 0
[....]
Ultimately the memory allocation succeeds. With bigger javascript inputs (it's a javascript
minifier), running time can be in 10-60 minutes, compared to 1-5 minutes under 5.6.
The PHP binary is compiled on a host with HUGETLB support, however the target host
(systemd-container) has not Hugepages (configured). 5.6 testing was done with same memory amount.
There is enough (normal) free memory.
cat /proc/meminfo
[..]
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
Test script:
---------------
https://gist.github.com/arjenschol/49a847c07154b51130b2
Expected result:
----------------
Execution at least as fast as 5.6.
Actual result:
--------------
3-4x slower compared to 5.6.
------------------------------------------------------------------------
--
Edit this bug report at https://bugs.php.net/bug.php?id=70984&edit=1