9th July 2023, 44 min read

Profiling PHP Programs #2

After adding a number of smaller features to Simplified Saaze I wanted to make sure that not too much fat has been added. So I profiled Simplified Saaze with XHProf. I had written on PHP profiling in Profiling PHP Programs. I used XHProf version 2.3.9 and PHP version 8.2.8 on Arch Linux kernel 6.4.1. Simplified Saaze has below version:

$ php saaze -v
Version 1.29, 08-Jul-2023, written by Elmar Klausmeier

First a run without profiler.

$ time php saaze -mortb /tmp/build
Building static site in /tmp/build...
        execute(): filePath=/home/klm/php/sndsaaze/content/aux.yml, nentries=6, totalPages=1, entries_per_page=20
        execute(): filePath=/home/klm/php/sndsaaze/content/blog.yml, nentries=409, totalPages=21, entries_per_page=20
        execute(): filePath=/home/klm/php/sndsaaze/content/gallery.yml, nentries=6, totalPages=1, entries_per_page=20
        execute(): filePath=/home/klm/php/sndsaaze/content/music.yml, nentries=56, totalPages=3, entries_per_page=20
        execute(): filePath=/home/klm/php/sndsaaze/content/error.yml, nentries=1, totalPages=1, entries_per_page=20
Finished creating 5 collections, 4 with index, and 495 entries (0.15 secs / 10.83MB)
#collections=5, YamlParser=0.0074/501-5, md2html=0.0145, MathParser=0.0078/495, renderEntry=495, content=495/0, excerpt=0/0
        real 0.17s
        user 0.15s
        sys 0
        swapped 0
        total space 0

Now with profiler for the exact same input.

$ time php saaze -mortb /tmp/build
Building static site in /tmp/build...
        execute(): filePath=/home/klm/php/sndsaaze/content/aux.yml, nentries=6, totalPages=1, entries_per_page=20
        execute(): filePath=/home/klm/php/sndsaaze/content/blog.yml, nentries=409, totalPages=21, entries_per_page=20
        execute(): filePath=/home/klm/php/sndsaaze/content/gallery.yml, nentries=6, totalPages=1, entries_per_page=20
        execute(): filePath=/home/klm/php/sndsaaze/content/music.yml, nentries=56, totalPages=3, entries_per_page=20
        execute(): filePath=/home/klm/php/sndsaaze/content/error.yml, nentries=1, totalPages=1, entries_per_page=20
Finished creating 5 collections, 4 with index, and 495 entries (0.27 secs / 11.02MB)
#collections=5, YamlParser=0.0109/501-5, md2html=0.0205, MathParser=0.0253/495, renderEntry=495, content=495/0, excerpt=0/0
Warning: Must specify directory location for XHProf runs. Trying /tmp as default. You can either pass the directory location as an argument to the constructor for XHProfRuns_Default() or set xhprof.output_dir ini param, or set XHPROF_OUTPUT_DIR environment variable.
---------------
Assuming you have set up the http based UI for
XHProf at some address, you can view run at
http://<xhprof-ui-address>/index.php?run=64a9a7b7f24b2&source=saaze
---------------
        real 0.29s
        user 0.18s
        sys 0
        swapped 0
        total space 0

One can clearly see that XHProf makes the program almost two times slower. In our case this is no problem at all, as runtime is still way below half a second for all our roughly 500 blog posts.

Analyzing the output via GUI. We create a symlink to XHProf's PHP and JavaScript code:

cd /srv/http
ln -s /usr/share/webapps/xhprof/xhprof_html

Results are then viewed on http://localhost/xhprof_html/index.php. Below tables is the result of this data. Time unit is µs.

Details.

1. array_key_exists(). Looking at above number of calls for PHP function array_key_exists() one could assume that replacing this function call with something else, might be a good idea. Therefore I checked original and possible alternative.

$ time php -r '$v=Array(); $a=microtime(true); for($i=0;$i<900000;++$i) if (array_key_exists($i,$v)) echo $a; printf("%f\n",microtime(true)-$a);'
0.011149
        real 0.04s
        user 0.02s
        sys 0
        swapped 0
        total space 0

Avoiding the function call of array_key_exists() by using PHP null coalescing operator ?? is in no way faster:

$ time php -r '$v=Array(); $a=microtime(true); for($i=0;$i<900000;++$i) if ($v[$i] ?? false) echo $a; printf("%f\n",microtime(true)-$a);'
0.027347
        real 0.06s
        user 0.05s
        sys 0
        swapped 0
        total space 0

So in this case XHProf overestimates the impact of plain PHP function calls. This was also noted in Profiling Overhead and PHP 7.

Above table clearly shows that the computation of categories and tags is the culprit for the high number of calls to array_key_exists(). This makes sense, as every blog post must be checked for their cats and tags.

2. str_word_count(). This function is needed to compute the number of words and therefore the reading time. We don't need to worry about the additional runtime required to compute these two values.

3. youtube(). Initially the number of calls of this function looked quite high, above table shows 491 calls. Similarly, the number of calls of vimeo() is also astonishingly high. These numbers can be explained by the fact that both routines are called for each part of the Markdown-file separated by either single-backslash or triple backslash.

Counting the occurences of the [youtube] tag:

cd .../content
rg --count-matches '\[youtube' | perl -ane 'printf("%5d %s",$c+=$1,$_) if /:(\d+)$/'
    1 blog/2015/05-27-commuting-to-work-with-an-e-bike.md:1
    3 blog/2015/08-16-urban-planning.md:2
    5 blog/2022/04-26-various-quotes-from-kristian-koehntopp.md:2
    6 blog/2022/05-26-upgrading-oneplus-five-to-oppo-reno4.md:1
    . . .
  426 music/2021/05-18-music-from-joachim-raff.md:7
  429 music/2021/08-08-music-from-rodrigo-riera.md:3
  442 music/2021/01-23-music-from-max-bruch.md:13

So apparently we have 442 actual YouTube videos embedded into this blog. The rest of the calls is due to the separation according backquotes. Though, youtube() function is not called per YouTube video but per part of file separated by backquote!