Original post is here: eklausmeier.goip.de
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:
1$ php saaze -v
2Version 1.29, 08-Jul-2023, written by Elmar Klausmeier
First a run without profiler.
1$ time php saaze -mortb /tmp/build
2Building static site in /tmp/build...
3 execute(): filePath=/home/klm/php/sndsaaze/content/aux.yml, nentries=6, totalPages=1, entries_per_page=20
4 execute(): filePath=/home/klm/php/sndsaaze/content/blog.yml, nentries=409, totalPages=21, entries_per_page=20
5 execute(): filePath=/home/klm/php/sndsaaze/content/gallery.yml, nentries=6, totalPages=1, entries_per_page=20
6 execute(): filePath=/home/klm/php/sndsaaze/content/music.yml, nentries=56, totalPages=3, entries_per_page=20
7 execute(): filePath=/home/klm/php/sndsaaze/content/error.yml, nentries=1, totalPages=1, entries_per_page=20
8Finished creating 5 collections, 4 with index, and 495 entries (0.15 secs / 10.83MB)
9#collections=5, YamlParser=0.0074/501-5, md2html=0.0145, MathParser=0.0078/495, renderEntry=495, content=495/0, excerpt=0/0
10 real 0.17s
11 user 0.15s
12 sys 0
13 swapped 0
14 total space 0
Now with profiler for the exact same input.
1$ time php saaze -mortb /tmp/build
2Building static site in /tmp/build...
3 execute(): filePath=/home/klm/php/sndsaaze/content/aux.yml, nentries=6, totalPages=1, entries_per_page=20
4 execute(): filePath=/home/klm/php/sndsaaze/content/blog.yml, nentries=409, totalPages=21, entries_per_page=20
5 execute(): filePath=/home/klm/php/sndsaaze/content/gallery.yml, nentries=6, totalPages=1, entries_per_page=20
6 execute(): filePath=/home/klm/php/sndsaaze/content/music.yml, nentries=56, totalPages=3, entries_per_page=20
7 execute(): filePath=/home/klm/php/sndsaaze/content/error.yml, nentries=1, totalPages=1, entries_per_page=20
8Finished creating 5 collections, 4 with index, and 495 entries (0.27 secs / 11.02MB)
9#collections=5, YamlParser=0.0109/501-5, md2html=0.0205, MathParser=0.0253/495, renderEntry=495, content=495/0, excerpt=0/0
10Warning: 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.
11---------------
12Assuming you have set up the http based UI for
13XHProf at some address, you can view run at
14http://<xhprof-ui-address>/index.php?run=64a9a7b7f24b2&source=saaze
15---------------
16 real 0.29s
17 user 0.18s
18 sys 0
19 swapped 0
20 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:
1cd /srv/http
2ln -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.
1$ 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);'
20.011149
3 real 0.04s
4 user 0.02s
5 sys 0
6 swapped 0
7 total space 0
Avoiding the function call of array_key_exists() by using PHP null coalescing operator ?? is in no way faster:
1$ 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);'
20.027347
3 real 0.06s
4 user 0.05s
5 sys 0
6 swapped 0
7 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_exists | 4,747 | 99.7% | 1,120 | 0.4% | 1,539 | 0.6% | 2,776 | 0.0% | 0 | 0.0% |
| Exclusive Metrics for Current Function | 1,120 | 100.0% | 1,539 | 100.0% | 2,776 | 100.0% | 0 | N/A% | ||
| Parent functions | ||||||||||
| Saaze\BuildCommand::build_cat_and_tag | 3,723 | 78.4% | 887 | 79.2% | 1,210 | 78.6% | 568 | 20.5% | 0 | N/A% |
| Saaze\Entry::getContentAndExcerpt | 495 | 10.4% | 123 | 11.0% | 167 | 10.9% | 552 | 19.9% | 0 | N/A% |
| Saaze\Entry::getUrl | 495 | 10.4% | 96 | 8.6% | 151 | 9.8% | 536 | 19.3% | 0 | N/A% |
| Saaze\BuildCommand::buildCollectionIndex | 32 | 0.7% | 14 | 1.2% | 11 | 0.7% | 568 | 20.5% | 0 | N/A% |
| Saaze\BuildCommand::save_cat_and_tag | 2 | 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:
1cd .../content
2rg --count-matches '\[youtube' | perl -ane 'printf("%5d %s",$c+=$1,$_) if /:(\d+)$/'
3 1 blog/2015/05-27-commuting-to-work-with-an-e-bike.md:1
4 3 blog/2015/08-16-urban-planning.md:2
5 5 blog/2022/04-26-various-quotes-from-kristian-koehntopp.md:2
6 6 blog/2022/05-26-upgrading-oneplus-five-to-oppo-reno4.md:1
7 . . .
8 426 music/2021/05-18-music-from-joachim-raff.md:7
9 429 music/2021/08-08-music-from-rodrigo-riera.md:3
10 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!