, 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 have to create a symlink to XHProf's PHP and JavaScript code as so:

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.

Overall Summary
Total Incl. Wall Time (microsec):268,275 microsecs
Total Incl. CPU (microsecs):266,828 microsecs
Total Incl. MemUse (bytes):9,671,352 bytes
Total Incl. PeakMemUse (bytes):9,792,824 bytes
Number of Function Calls:192,936

Details.

Function Name Calls Calls% Incl. Wall Time
(microsec)
IWall% Excl. Wall Time
(microsec)
EWall% Incl. CPU
(microsecs)
ICpu% Excl. CPU
(microsec)
ECPU% Incl.
MemUse
(bytes)
IMemUse% Excl.
MemUse
(bytes)
EMemUse% Incl.
PeakMemUse
(bytes)
IPeakMemUse% Excl.
PeakMemUse
(bytes)
EPeakMemUse%
main() 1 0.0% 268,275 100.0% 30 0.0% 266,828 100.0% 25 0.0% 9,671,352 100.0% -18,488 -0.2% 9,792,824 100.0% 0 0.0%
Saaze\BuildCommand::buildAllStatic 1 0.0% 267,921 99.9% 990 0.4% 266,474 99.9% 834 0.3% 9,516,976 98.4% -486,936 -5.0% 9,792,824 100.0% 0 0.0%
Saaze\BuildCommand::buildEntry 495 0.3% 165,125 61.6% 3,418 1.3% 164,740 61.7% 2,721 1.0% 1,783,216 18.4% -18,936,600 -195.8% 3,901,352 39.8% 0 0.0%
Saaze\TemplateManager::renderEntry 495 0.3% 145,793 54.3% 40,623 15.1% 145,444 54.5% 32,168 12.1% 20,529,904 212.3% -23,448,896 -242.5% 3,901,352 39.8% 466,512 4.8%
Saaze\Collection::getEntries 5 0.0% 77,137 28.8% 8 0.0% 76,211 28.6% 8 0.0% 6,791,912 70.2% 376 0.0% 5,462,264 55.8% 0 0.0%
Saaze\Collection::loadEntries 5 0.0% 74,368 27.7% 11 0.0% 73,440 27.5% 12 0.0% 6,788,976 70.2% 856 0.0% 5,447,368 55.6% 0 0.0%
Saaze\Collection::loadMkdwnRecursive 5 0.0% 74,348 27.7% 58 0.0% 73,419 27.5% 41 0.0% 6,787,744 70.2% -10,400 -0.1% 5,447,368 55.6% 0 0.0%
Saaze\Collection::loadMkdwnRecursive@1 21 0.0% 72,785 27.1% 897 0.3% 71,863 26.9% 627 0.2% 6,569,344 67.9% -10,376 -0.1% 5,440,880 55.6% 0 0.0%
Saaze\Collection::loadEntry 496 0.3% 71,986 26.8% 1,556 0.6% 71,164 26.7% 1,427 0.5% 6,732,744 69.6% -5,808 -0.1% 5,447,368 55.6% 0 0.0%
Saaze\Entry::getContentAndExcerpt 495 0.3% 52,920 19.7% 1,428 0.5% 52,056 19.5% 1,205 0.5% 3,330,256 34.4% -1,640,096 -17.0% 3,561,672 36.4% 0 0.0%
Saaze\MarkdownContentParser::toHtml 495 0.3% 46,252 17.2% 6,944 2.6% 45,396 17.0% 5,127 1.9% 4,968,160 51.4% -2,228,808 -23.0% 3,561,672 36.4% 19,840 0.2%
load::blog/entry.php 423 0.2% 18,957 7.1% 18,957 7.1% 19,027 7.1% 19,027 7.1% 7,078,088 73.2% 7,078,088 73.2% 89,408 0.9% 89,408 0.9%
load::templates/top-layout.php 525 0.3% 15,161 5.7% 15,161 5.7% 15,286 5.7% 15,286 5.7% 10,750,256 111.2% 10,750,256 111.2% 363,184 3.7% 363,184 3.7%
load::templates/read_cattag_json.php 495 0.3% 14,344 5.3% 14,344 5.3% 14,449 5.4% 14,449 5.4% 4,175,336 43.2% 4,175,336 43.2% 0 0.0% 0 0.0%
Saaze\Entry::__construct 496 0.3% 12,221 4.6% 534 0.2% 12,250 4.6% 476 0.2% 3,194,120 33.0% -2,497,920 -25.8% 1,885,696 19.3% 0 0.0%
load::templates/bottom-layout.php 525 0.3% 12,178 4.5% 12,178 4.5% 12,263 4.6% 12,263 4.6% 6,169,952 63.8% 6,169,952 63.8% 560,952 5.7% 560,952 5.7%
Saaze\Entry::parseEntry 496 0.3% 11,370 4.2% 3,225 1.2% 11,456 4.3% 2,519 0.9% 5,530,320 57.2% 4,256 0.0% 1,885,696 19.3% 1,168 0.0%
md4c_toHtml 495 0.3% 9,714 3.6% 9,714 3.6% 9,078 3.4% 9,078 3.4% 48,072 0.5% 48,072 0.5% 672 0.0% 672 0.0%
file_put_contents 529 0.3% 9,601 3.6% 9,601 3.6% 9,715 3.6% 9,715 3.6% 2,240 0.0% 2,240 0.0% 568 0.0% 568 0.0%
Saaze\BuildCommand::clearBuildDirectory 1 0.0% 8,852 3.3% 2 0.0% 8,832 3.3% 3 0.0% 20,232 0.2% 664 0.0% 0 0.0% 0 0.0%
Saaze\BuildCommand::delTree 1 0.0% 8,843 3.3% 14 0.0% 8,822 3.3% 14 0.0% 19,016 0.2% -240 -0.0% 0 0.0% 0 0.0%
Saaze\BuildCommand::delTree@1 4 0.0% 8,741 3.3% 62 0.0% 8,717 3.3% 33 0.0% 14,160 0.1% -5,392 -0.1% 0 0.0% 0 0.0%
Saaze\BuildCommand::delTree@2 31 0.0% 8,592 3.2% 797 0.3% 8,578 3.2% 569 0.2% 11,560 0.1% -124,424 -1.3% 0 0.0% 0 0.0%
printf 30,111 15.6% 8,301 3.1% 8,301 3.1% 10,966 4.1% 10,966 4.1% 2,857,640 29.5% 2,857,640 29.5% 15,656 0.2% 15,656 0.2%
substr 38,306 19.9% 7,588 2.8% 7,588 2.8% 10,921 4.1% 10,921 4.1% 9,411,528 97.3% 9,411,528 97.3% 733,920 7.5% 733,920 7.5%
strpos 14,121 7.3% 6,972 2.6% 6,972 2.6% 8,288 3.1% 8,288 3.1% 6,040 0.1% 6,040 0.1% 552 0.0% 552 0.0%
Saaze\BuildCommand::delTree@3 498 0.3% 6,778 2.5% 1,445 0.5% 6,849 2.6% 1,119 0.4% 57,720 0.6% -213,720 -2.2% 0 0.0% 0 0.0%
Saaze\BuildCommand::buildCollectionIndex 32 0.0% 6,475 2.4% 184 0.1% 6,453 2.4% 171 0.1% 57,832 0.6% -971,448 -10.0% 62,592 0.6% 0 0.0%
Saaze\Entry::slug 1,484 0.8% 5,493 2.0% 3,647 1.4% 5,661 2.1% 3,028 1.1% 234,320 2.4% -295,248 -3.1% 0 0.0% 0 0.0%
Saaze\TemplateManager::renderCollection 30 0.0% 5,446 2.0% 1,253 0.5% 5,440 2.0% 1,058 0.4% 1,019,592 10.5% -1,355,408 -14.0% 62,592 0.6% 0 0.0%
prtCatOrTag 2 0.0% 5,415 2.0% 3,192 1.2% 5,374 2.0% 2,523 0.9% 552,960 5.7% -172,840 -1.8% 0 0.0% 0 0.0%
ob_get_contents 528 0.3% 5,169 1.9% 5,169 1.9% 5,251 2.0% 5,251 2.0% 19,498,632 201.6% 19,498,632 201.6% 838,960 8.6% 838,960 8.6%
str_contains 24,694 12.8% 5,006 1.9% 5,006 1.9% 7,223 2.7% 7,223 2.7% 552 0.0% 552 0.0% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::myTag 2,026 1.1% 4,962 1.8% 3,341 1.2% 5,202 1.9% 2,879 1.1% 297,136 3.1% -766,728 -7.9% 39,400 0.4% 352 0.0%
str_word_count 495 0.3% 4,880 1.8% 4,880 1.8% 4,950 1.9% 4,950 1.9% 552 0.0% 552 0.0% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::getExcerpt 495 0.3% 4,794 1.8% 1,125 0.4% 4,818 1.8% 936 0.4% 438,712 4.5% -2,630,104 -27.2% 2,714,336 27.7% 0 0.0%
Saaze\BuildCommand::build_cat_and_tag 495 0.3% 4,133 1.5% 3,010 1.1% 4,207 1.6% 2,637 1.0% 849,496 8.8% 831,256 8.6% 0 0.0% 0 0.0%
array_map 909 0.5% 4,126 1.5% 1,715 0.6% 4,205 1.6% 1,515 0.6% 401,184 4.1% 215,496 2.2% 680 0.0% 680 0.0%
load::jscss/blogklm.css 525 0.3% 4,025 1.5% 4,025 1.5% 4,141 1.6% 4,141 1.6% 2,684,832 27.8% 2,684,832 27.8% 0 0.0% 0 0.0%
file_get_contents 502 0.3% 3,966 1.5% 3,966 1.5% 4,066 1.5% 4,066 1.5% 2,956,024 30.6% 2,956,024 30.6% 1,635,184 16.7% 1,635,184 16.7%
Saaze\MarkdownContentParser::hackLNHighlight 157 0.1% 3,904 1.5% 1,411 0.5% 3,916 1.5% 1,096 0.4% 1,750,440 18.1% -11,205,304 -115.9% 99,200 1.0% 45,528 0.5%
Saaze\Entry::getUrl 495 0.3% 3,348 1.2% 1,211 0.5% 3,405 1.3% 1,028 0.4% 89,760 0.9% -48,792 -0.5% 0 0.0% 0 0.0%
strip_tags 495 0.3% 3,321 1.2% 3,321 1.2% 3,355 1.3% 3,355 1.3% 2,779,096 28.7% 2,779,096 28.7% 2,714,336 27.7% 2,714,336 27.7%
load::templates/head.php 526 0.3% 3,276 1.2% 3,276 1.2% 3,414 1.3% 3,414 1.3% 1,589,648 16.4% 1,589,648 16.4% 0 0.0% 0 0.0%
load::templates/entry.php 70 0.0% 3,185 1.2% 3,185 1.2% 3,208 1.2% 3,208 1.2% 1,131,120 11.7% 1,131,120 11.7% 0 0.0% 0 0.0%
yaml_parse 501 0.3% 3,150 1.2% 3,150 1.2% 3,253 1.2% 3,253 1.2% 646,448 6.7% 646,448 6.7% 51,496 0.5% 51,496 0.5%
Saaze\MarkdownContentParser::inlineMath 143 0.1% 3,066 1.1% 2,013 0.8% 3,084 1.2% 1,545 0.6% 127,704 1.3% -3,570,144 -36.9% 102,712 1.0% 78,648 0.8%
str_replace 8,197 4.2% 3,038 1.1% 3,038 1.1% 4,031 1.5% 4,031 1.5% 1,545,328 16.0% 1,545,328 16.0% 0 0.0% 0 0.0%
Saaze\TemplateManager::renderGeneral 3 0.0% 2,820 1.1% 1,255 0.5% 2,801 1.0% 949 0.4% 456,216 4.7% -649,976 -6.7% 191,696 2.0% 64 0.0%
Saaze\Collection::sortEntries 5 0.0% 2,761 1.0% 18 0.0% 2,763 1.0% 16 0.0% 2,560 0.0% 856 0.0% 14,896 0.2% 0 0.0%
usort 5 0.0% 2,742 1.0% 1,680 0.6% 2,743 1.0% 1,347 0.5% 1,152 0.0% 600 0.0% 14,896 0.2% 14,896 0.2%
scandir 574 0.3% 2,739 1.0% 2,739 1.0% 2,842 1.1% 2,842 1.1% 394,936 4.1% 394,936 4.1% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::youtube 491 0.3% 2,409 0.9% 315 0.1% 2,501 0.9% 340 0.1% 240,472 2.5% -2,712 -0.0% 21,152 0.2% 256 0.0%
unlink 528 0.3% 2,334 0.9% 2,334 0.9% 2,416 0.9% 2,416 0.9% 2,904 0.0% 2,904 0.0% 0 0.0% 0 0.0%
Saaze\TemplateManager::{closure} 2,238 1.2% 2,308 0.9% 1,799 0.7% 2,532 0.9% 1,718 0.6% 185,136 1.9% 176,728 1.8% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::gallery 274 0.1% 2,298 0.9% 940 0.4% 2,337 0.9% 774 0.3% 223,264 2.3% -20,208 -0.2% 0 0.0% 0 0.0%
Saaze\BuildCommand::compRbase 525 0.3% 2,287 0.9% 1,560 0.6% 2,364 0.9% 1,273 0.5% 25,536 0.3% -72,008 -0.7% 0 0.0% 0 0.0%
is_dir 2,218 1.1% 2,173 0.8% 2,173 0.8% 2,485 0.9% 2,485 0.9% 6,128 0.1% 6,128 0.1% 0 0.0% 0 0.0%
Saaze\BuildCommand::save_cat_and_tag 1 0.0% 1,939 0.7% 459 0.2% 1,937 0.7% 365 0.1% 4,072 0.0% -773,864 -8.0% 174,920 1.8% 128 0.0%
strlen 9,506 4.9% 1,810 0.7% 1,810 0.7% 2,727 1.0% 2,727 1.0% 7,088 0.1% 7,088 0.1% 232 0.0% 232 0.0%
substr_replace 1,204 0.6% 1,804 0.7% 1,804 0.7% 1,921 0.7% 1,921 0.7% 13,529,136 139.9% 13,529,136 139.9% 90,080 0.9% 90,080 0.9%
mkdir 508 0.3% 1,746 0.7% 1,746 0.7% 1,826 0.7% 1,826 0.7% 1,088 0.0% 1,088 0.0% 0 0.0% 0 0.0%
strtotime 1,022 0.5% 1,341 0.5% 1,341 0.5% 1,482 0.6% 1,482 0.6% 1,864 0.0% 1,864 0.0% 0 0.0% 0 0.0%
date 1,549 0.8% 1,152 0.4% 1,152 0.4% 1,313 0.5% 1,313 0.5% 397,648 4.1% 397,648 4.1% 504 0.0% 504 0.0%
array_key_exists 4,747 2.5% 1,120 0.4% 1,120 0.4% 1,539 0.6% 1,539 0.6% 2,776 0.0% 2,776 0.0% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::mermaid 424 0.2% 1,118 0.4% 300 0.1% 1,180 0.4% 304 0.1% 36,752 0.4% -3,832 -0.0% 18,960 0.2% 712 0.0%
Saaze\TemplateManager::templateExists 528 0.3% 1,107 0.4% 520 0.2% 1,176 0.4% 529 0.2% 2,368 0.0% 1,816 0.0% 0 0.0% 0 0.0%
Saaze\Collection::Saaze\{closure} 4,096 2.1% 1,062 0.4% 1,062 0.4% 1,396 0.5% 1,396 0.5% 552 0.0% 552 0.0% 0 0.0% 0 0.0%
is_link 1,061 0.5% 1,008 0.4% 1,008 0.4% 1,140 0.4% 1,140 0.4% 2,144 0.0% 2,144 0.0% 0 0.0% 0 0.0%
rmdir 534 0.3% 997 0.4% 997 0.4% 1,076 0.4% 1,076 0.4% 2,144 0.0% 2,144 0.0% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::moreTag 495 0.3% 966 0.4% 334 0.1% 1,039 0.4% 340 0.1% 569,008 5.9% 648 0.0% 0 0.0% 0 0.0%
json_decode 1 0.0% 958 0.4% 958 0.4% 959 0.4% 959 0.4% 1,353,568 14.0% 1,353,568 14.0% 1,345,496 13.7% 1,345,496 13.7%
urlencode 3,340 1.7% 867 0.3% 867 0.3% 1,194 0.4% 1,194 0.4% 150,352 1.6% 150,352 1.6% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::displayMath 143 0.1% 821 0.3% 515 0.2% 846 0.3% 417 0.2% 107,592 1.1% -943,480 -9.8% 89,832 0.9% 29,872 0.3%
Saaze\MarkdownContentParser::vimeo 324 0.2% 808 0.3% 235 0.1% 861 0.3% 245 0.1% 2,368 0.0% 568 0.0% 64 0.0% 64 0.0%
Saaze\MarkdownContentParser::codepen 261 0.1% 712 0.3% 214 0.1% 745 0.3% 207 0.1% 7,288 0.1% 216 0.0% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::twitter 270 0.1% 678 0.3% 189 0.1% 727 0.3% 209 0.1% 3,280 0.0% 472 0.0% 256 0.0% 0 0.0%
Saaze\MarkdownContentParser::markmap 256 0.1% 642 0.2% 152 0.1% 685 0.3% 192 0.1% 2,256 0.0% 568 0.0% 0 0.0% 0 0.0%
FFI::string 495 0.3% 621 0.2% 621 0.2% 713 0.3% 713 0.3% 2,779,096 28.7% 2,779,096 28.7% 327,336 3.3% 327,336 3.3%
file_exists 528 0.3% 587 0.2% 587 0.2% 647 0.2% 647 0.2% 552 0.0% 552 0.0% 0 0.0% 0 0.0%
sort 1,187 0.6% 586 0.2% 586 0.2% 683 0.3% 683 0.3% 224,904 2.3% 224,904 2.3% 0 0.0% 0 0.0%
microtime 2,479 1.3% 568 0.2% 568 0.2% 875 0.3% 875 0.3% 1,640 0.0% 1,640 0.0% 0 0.0% 0 0.0%
preg_match 1,430 0.7% 549 0.2% 549 0.2% 671 0.3% 671 0.3% 1,288 0.0% 1,288 0.0% 0 0.0% 0 0.0%
getenv 1,543 0.8% 537 0.2% 537 0.2% 730 0.3% 730 0.3% 1,104 0.0% 1,104 0.0% 0 0.0% 0 0.0%
json_encode 1 0.0% 518 0.2% 518 0.2% 515 0.2% 515 0.2% 504,360 5.2% 504,360 5.2% 174,224 1.8% 174,224 1.8%
Saaze\MarkdownContentParser::tiktok 269 0.1% 504 0.2% 328 0.1% 534 0.2% 263 0.1% 4,368 0.0% 808 0.0% 2,288 0.0% 576 0.0%
load::blog/index.php 22 0.0% 443 0.2% 443 0.2% 450 0.2% 450 0.2% 113,032 1.2% 113,032 1.2% 24,896 0.3% 24,896 0.3%
strrpos 1,874 1.0% 423 0.2% 423 0.2% 609 0.2% 609 0.2% 1,632 0.0% 1,632 0.0% 0 0.0% 0 0.0%
ltrim 2,025 1.0% 418 0.2% 418 0.2% 645 0.2% 645 0.2% 136,912 1.4% 136,912 1.4% 0 0.0% 0 0.0%
implode 1,487 0.8% 384 0.1% 384 0.1% 518 0.2% 518 0.2% 453,936 4.7% 453,936 4.7% 66,352 0.7% 66,352 0.7%
rtrim 1,543 0.8% 366 0.1% 366 0.1% 458 0.2% 458 0.2% 23,672 0.2% 23,672 0.2% 0 0.0% 0 0.0%
load::saaze/MarkdownContentParser.php 1 0.0% 317 0.1% 317 0.1% 318 0.1% 318 0.1% 161,720 1.7% 161,720 1.7% 0 0.0% 0 0.0%
Saaze\CollectionArray::getCollections 1 0.0% 288 0.1% 2 0.0% 288 0.1% 3 0.0% 33,472 0.3% 712 0.0% 0 0.0% 0 0.0%
Saaze\MarkdownContentParser::wpvideo 271 0.1% 286 0.1% 149 0.1% 311 0.1% 141 0.1% 3,472 0.0% 648 0.0% 0 0.0% 0 0.0%
ob_start 528 0.3% 270 0.1% 270 0.1% 347 0.1% 347 0.1% 8,720,120 90.2% 8,720,120 90.2% 0 0.0% 0 0.0%
Saaze\CollectionArray::loadCollections 1 0.0% 259 0.1% 27 0.0% 259 0.1% 23 0.0% 29,680 0.3% -7,056 -0.1% 0 0.0% 0 0.0%
array_push 1,061 0.5% 236 0.1% 236 0.1% 360 0.1% 360 0.1% 17,672 0.2% 17,672 0.2% 0 0.0% 0 0.0%
ksort 4 0.0% 233 0.1% 233 0.1% 234 0.1% 234 0.1% 85,664 0.9% 85,664 0.9% 0 0.0% 0 0.0%
load::templates/index.php 8 0.0% 212 0.1% 212 0.1% 215 0.1% 215 0.1% 42,296 0.4% 42,296 0.4% 0 0.0% 0 0.0%
ctype_space 992 0.5% 202 0.1% 202 0.1% 298 0.1% 298 0.1% 536 0.0% 536 0.0% 0 0.0% 0 0.0%

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.

Function Name Calls Calls% Incl. Wall Time
(microsec)
IWall% Incl. CPU
(microsecs)
ICpu% Incl.
MemUse
(bytes)
IMemUse% Incl.
PeakMemUse
(bytes)
IPeakMemUse%
Current Function
array_key_exists4,747 99.7% 1,120 0.4% 1,539 0.6% 2,776 0.0% 0 0.0%
Exclusive Metrics for Current Function1,120 100.0% 1,539 100.0% 2,776 100.0% 0 N/A%
Parent functions
Saaze\BuildCommand::build_cat_and_tag3,723 78.4% 887 79.2% 1,210 78.6% 568 20.5% 0 N/A%
Saaze\Entry::getContentAndExcerpt495 10.4% 123 11.0% 167 10.9% 552 19.9% 0 N/A%
Saaze\Entry::getUrl495 10.4% 96 8.6% 151 9.8% 536 19.3% 0 N/A%
Saaze\BuildCommand::buildCollectionIndex32 0.7% 14 1.2% 11 0.7% 568 20.5% 0 N/A%
Saaze\BuildCommand::save_cat_and_tag2 0.0% 0 0.0% 0 0.0% 552 19.9% 0 N/A%

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!