Original post is here: eklausmeier.goip.de
This blog uses the PHP-based Simplified Saaze software. I measured Simplified Saaze using XHProf:
Still I am interested whether I missed anything.
In multiple talks Rasmus Lerdorf, the creator of PHP, advertises PHPSPY. [youtube]3cD1N7IMwSE[/youtube]
PHPSPY was written by Adam Saponara. The source code is in GitHub: https://github.com/adsr/phpspy.
I ran PHPSPY in top mode for some days using the dynamic mode of Simplified Saaze: phpspy -p 940 -p 17132 -p 61898 -p 61899 -t. The output is below. Some remarks on inclusive and exclusive times or counts:
- Inclusive counts everything for the function and all its function it calls.
- Exclusive only counts a particular function.
1phpspy -p 940 -p 17132 -p 61898 -p 61899 -@
2samp_count=666 err_count=10 func_count=67
3
4tincl texcl incl excl excl% func
5313 151 0 0 0.00 ComposerAutoloaderInit50920a90746408ba7a500bacdb4908c1::getLoader /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:19
6132 103 0 0 0.00 composerRequire50920a90746408ba7a500bacdb4908c1 /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:50
799 99 0 0 0.00 Composer\Autoload\includeFile /home/klm/php/sndsaaze/vendor/composer/ClassLoader.php:569
876 76 0 0 0.00 json_decode <internal>:-1
9298 34 0 0 0.00 Saaze\Saaze::run /home/klm/php/sndsaaze/vendor/eklausme/saaze/Saaze.php:32
1030 30 0 0 0.00 ComposerAutoloaderInit50920a90746408ba7a500bacdb4908c1::loadClassLoader /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:9
1123 23 0 0 0.00 FFI::cdef <internal>:-1
1219 19 0 0 0.00 file_get_contents <internal>:-1
1315 15 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-mbstring/bootstrap.php:1
1413 13 0 0 0.00 md4c_toHtml <internal>:-1
1514 11 0 0 0.00 str_word_count <internal>:-1
1610 10 0 0 0.00 yaml_parse <internal>:-1
17322 9 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/autoload.php:1
1890 9 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/blog/entry.php:1
198 8 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-intl-grapheme/bootstrap.php:1
205 5 0 0 0.00 FFI::string <internal>:-1
21653 4 0 0 0.00 <main> /home/klm/php/sndsaaze/public/index.php:1
225 4 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/error.php:1
235 3 0 0 0.00 microtime <internal>:-1
244 3 0 0 0.00 strpos <internal>:-1
253 3 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-ctype/bootstrap.php:1
263 3 0 0 0.00 shell_exec <internal>:-1
2727 2 0 0 0.00 Saaze\CollectionArray::loadCollections /home/klm/php/sndsaaze/vendor/eklausme/saaze/CollectionArray.php:27
2821 2 0 0 0.00 <main> <internal>:-1
2910 2 0 0 0.00 is_dir <internal>:-1
309 2 0 0 0.00 Saaze\Collection::__construct /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:15
319 2 0 0 0.00 Saaze\TemplateManager::renderError /home/klm/php/sndsaaze/vendor/eklausme/saaze/TemplateManager.php:62
324 2 0 0 0.00 scandir <internal>:-1
333 2 0 0 0.00 strlen <internal>:-1
342 2 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/top-layout.php:1
352 2 0 0 0.00 Saaze\MarkdownContentParser::inlineMath /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:172
362 2 0 0 0.00 strip_tags <internal>:-1
3723 1 0 0 0.00 Saaze\MarkdownContentParser::toHtml /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:562
389 1 0 0 0.00 substr <internal>:-1
391 1 0 0 0.00 substr_replace <internal>:-1
401 1 0 0 0.00 usort <internal>:-1
411 1 0 0 0.00 printf <internal>:-1
421 1 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-intl-normalizer/bootstrap.php:1
431 1 0 0 0.00 ob_end_clean <internal>:-1
441 1 0 0 0.00 str_replace <internal>:-1
451 1 0 0 0.00 file_put_contents <internal>:-1
461 1 0 0 0.00 max <internal>:-1
471 1 0 0 0.00 is_readable <internal>:-1
48111 0 0 0 0.00 Saaze\Collection::loadMkdwnRecursive /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:70
4991 0 0 0 0.00 Saaze\TemplateManager::renderEntry /home/klm/php/sndsaaze/vendor/eklausme/saaze/TemplateManager.php:37
Interestingly, the time spent by Composer-classes is greater than the actual runtime of Simplified Saaze!
Added 11-Dec-2023: Measured once again. Results are below.
1phpspy -p 879 -p 1015 -p 1016 -p 20333 -@
2samp_count=2422 err_count=55 func_count=97
3
4tincl texcl incl excl excl% func
51077 491 0 0 0.00 ComposerAutoloaderInit50920a90746408ba7a500bacdb4908c1::getLoader /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:19
6506 369 0 0 0.00 composerRequire50920a90746408ba7a500bacdb4908c1 /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:50
7353 353 0 0 0.00 json_decode <internal>:-1
8335 335 0 0 0.00 Composer\Autoload\includeFile /home/klm/php/sndsaaze/vendor/composer/ClassLoader.php:569
981 81 0 0 0.00 md4c_toHtml <internal>:-1
1076 76 0 0 0.00 ComposerAutoloaderInit50920a90746408ba7a500bacdb4908c1::loadClassLoader /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:9
1175 75 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-mbstring/bootstrap.php:1
12459 69 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/blog/entry.php:1
1367 67 0 0 0.00 FFI::cdef <internal>:-1
1458 58 0 0 0.00 file_get_contents <internal>:-1
1548 35 0 0 0.00 str_word_count <internal>:-1
161162 29 0 0 0.00 Saaze\Saaze::run /home/klm/php/sndsaaze/vendor/eklausme/saaze/Saaze.php:32
1728 28 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-intl-grapheme/bootstrap.php:1
1826 26 0 0 0.00 yaml_parse <internal>:-1
191096 23 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/autoload.php:1
2022 20 0 0 0.00 scandir <internal>:-1
2121 20 0 0 0.00 strpos <internal>:-1
22491 19 0 0 0.00 Saaze\TemplateManager::renderEntry /home/klm/php/sndsaaze/vendor/eklausme/saaze/TemplateManager.php:37
2321 16 0 0 0.00 microtime <internal>:-1
2416 16 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-ctype/bootstrap.php:1
2532 15 0 0 0.00 substr <internal>:-1
2674 14 0 0 0.00 <main> <internal>:-1
272384 12 0 0 0.00 <main> /home/klm/php/sndsaaze/public/index.php:1
2815 12 0 0 0.00 Saaze\MarkdownContentParser::inlineMath /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:172
2912 12 0 0 0.00 strip_tags <internal>:-1
3020 11 0 0 0.00 is_dir <internal>:-1
3112 10 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/top-layout.php:1
327 7 0 0 0.00 str_replace <internal>:-1
33260 6 0 0 0.00 Saaze\Collection::loadEntry /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:82
34159 6 0 0 0.00 Saaze\MarkdownContentParser::toHtml /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:562
358 6 0 0 0.00 FFI::string <internal>:-1
366 6 0 0 0.00 shell_exec <internal>:-1
37233 5 0 0 0.00 Saaze\Entry::getContentAndExcerpt /home/klm/php/sndsaaze/vendor/eklausme/saaze/Entry.php:86
386 5 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-intl-normalizer/bootstrap.php:1
395 5 0 0 0.00 function_exists <internal>:-1
4071 4 0 0 0.00 Saaze\CollectionArray::loadCollections /home/klm/php/sndsaaze/vendor/eklausme/saaze/CollectionArray.php:27
4150 4 0 0 0.00 Saaze\Entry::parseEntry /home/klm/php/sndsaaze/vendor/eklausme/saaze/Entry.php:21
426 4 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/error.php:1
436 4 0 0 0.00 is_readable <internal>:-1
4421 3 0 0 0.00 Saaze\Collection::__construct /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:15
455 3 0 0 0.00 Saaze\TemplateManager::<main> <internal>:-1
464 3 0 0 0.00 Saaze\MarkdownContentParser::myTag /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:212
473 3 0 0 0.00 substr_replace <internal>:-1
483 3 0 0 0.00 max <internal>:-1
493 3 0 0 0.00 Saaze\MarkdownContentParser::displayMath /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:145
503 3 0 0 0.00 dirname <internal>:-1
513 3 0 0 0.00 getenv <internal>:-1
523 3 0 0 0.00 rtrim <internal>:-1
53549 2 0 0 0.00 Saaze\Collection::loadMkdwnRecursive /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:70
5472 2 0 0 0.00 Saaze\Config::init /home/klm/php/sndsaaze/vendor/eklausme/saaze/Config.php:14
5520 2 0 0 0.00 Saaze\Collection::parseCollection /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:22
5616 2 0 0 0.00 Saaze\MarkdownContentParser::gallery /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:397
575 2 0 0 0.00 date <internal>:-1
583 2 0 0 0.00 strlen <internal>:-1
592 2 0 0 0.00 ltrim <internal>:-1
602 2 0 0 0.00 Saaze\Collection::Saaze\{closure} /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:54
612 2 0 0 0.00 Saaze\TemplateManager::templateExists /home/klm/php/sndsaaze/vendor/eklausme/saaze/TemplateManager.php:7
622 2 0 0 0.00 Saaze\MarkdownContentParser::twitter /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:333
632 2 0 0 0.00 fopen <internal>:-1
642 2 0 0 0.00 Composer\Autoload\ClassLoader::register /home/klm/php/sndsaaze/vendor/composer/ClassLoader.php:389
652 2 0 0 0.00 strtotime <internal>:-1
66192 1 0 0 0.00 Saaze\Entry::__construct /home/klm/php/sndsaaze/vendor/eklausme/saaze/Entry.php:13
6710 1 0 0 0.00 Saaze\Entry::getUrl /home/klm/php/sndsaaze/vendor/eklausme/saaze/Entry.php:74
684 1 0 0 0.00 ob_end_clean <internal>:-1
Results are similar. Clearly even more accentuating the importance of Composer.
Added 08-Feb-2024: I had some trouble getting PHPSPY to work again, see phpspy no longer works #136. I ran PHPSPY again but this time I dropped composer, which was marked as dominant in above PHPSPY sessions. Results for three days are as below.
1phpspy -H 9999 --pgrep=php-fpm -@
2samp_count=2651 err_count=575856 func_count=58
3
4tincl texcl incl excl excl% func
51047 850 0 0 0.00 FFI::string <internal>:-1
6230 207 0 0 0.00 substr <internal>:-1
7209 206 0 0 0.00 str_replace <internal>:-1
8212 194 0 0 0.00 <main> <internal>:-1
9269 193 0 0 0.00 max <internal>:-1
10200 185 0 0 0.00 strpos <internal>:-1
11147 147 0 0 0.00 ctype_space <internal>:-1
12102 99 0 0 0.00 printf <internal>:-1
1382 82 0 0 0.00 rtrim <internal>:-1
1468 68 0 0 0.00 json_decode <internal>:-1
15123 43 0 0 0.00 date <internal>:-1
1642 41 0 0 0.00 strlen <internal>:-1
1730 30 0 0 0.00 strip_tags <internal>:-1
1828 28 0 0 0.00 md4c_toHtml <internal>:-1
1947 23 0 0 0.00 str_word_count <internal>:-1
2021 21 0 0 0.00 preg_match <internal>:-1
2118 18 0 0 0.00 str_contains <internal>:-1
2217 16 0 0 0.00 implode <internal>:-1
2320 15 0 0 0.00 Saaze\TemplateManager::<main> <internal>:-1
2415 15 0 0 0.00 strrpos <internal>:-1
2514 14 0 0 0.00 is_dir <internal>:-1
2613 13 0 0 0.00 define <internal>:-1
2758 12 0 0 0.00 microtime <internal>:-1
2812 12 0 0 0.00 getenv <internal>:-1
2911 11 0 0 0.00 sprintf <internal>:-1
3011 11 0 0 0.00 substr_replace <internal>:-1
3111 10 0 0 0.00 FFI::cdef <internal>:-1
329 9 0 0 0.00 str_split <internal>:-1
338 8 0 0 0.00 function_exists <internal>:-1
3414 7 0 0 0.00 urlencode <internal>:-1
357 7 0 0 0.00 DateTime::__construct <internal>:-1
366 6 0 0 0.00 yaml_parse <internal>:-1
3713 5 0 0 0.00 is_array <internal>:-1
385 5 0 0 0.00 ltrim <internal>:-1
394 3 0 0 0.00 explode <internal>:-1
403 3 0 0 0.00 is_readable <internal>:-1
413 3 0 0 0.00 preg_replace <internal>:-1
423 3 0 0 0.00 extension_loaded <internal>:-1
433 3 0 0 0.00 str_starts_with <internal>:-1
443 3 0 0 0.00 spl_autoload_register <internal>:-1
453 3 0 0 0.00 trim <internal>:-1
463 2 0 0 0.00 count <internal>:-1
472 2 0 0 0.00 is_string <internal>:-1
482 2 0 0 0.00 is_bool <internal>:-1
491 1 0 0 0.00 round <internal>:-1
501 1 0 0 0.00 error_reporting <internal>:-1
511 1 0 0 0.00 print_r <internal>:-1
521 1 0 0 0.00 header <internal>:-1
531 1 0 0 0.00 mb_strtolower <internal>:-1
541 1 0 0 0.00 array_key_exists <internal>:-1
551 1 0 0 0.00 spl_autoload_unregister <internal>:-1
561 1 0 0 0.00 gettype <internal>:-1
571 1 0 0 0.00 mb_substr <internal>:-1
581 1 0 0 0.00 ucwords <internal>:-1
591 1 0 0 0.00 openssl_cipher_iv_length <internal>:-1
601 1 0 0 0.00 file_exists <internal>:-1
611 1 0 0 0.00 defined <internal>:-1
621 0 0 0 0.00 is_object <internal>:-1
At a later time:
1phpspy -H 9999 --pgrep=php-fpm -@
2samp_count=5475 err_count=1004659 func_count=64
3
4tincl texcl incl excl excl% func
52301 1842 0 0 0.00 FFI::string <internal>:-1
6462 458 0 0 0.00 str_replace <internal>:-1
7491 447 0 0 0.00 substr <internal>:-1
8467 431 0 0 0.00 strpos <internal>:-1
9556 414 0 0 0.00 max <internal>:-1
10353 310 0 0 0.00 <main> <internal>:-1
11299 299 0 0 0.00 ctype_space <internal>:-1
12207 203 0 0 0.00 printf <internal>:-1
13145 142 0 0 0.00 rtrim <internal>:-1
14122 122 0 0 0.00 json_decode <internal>:-1
1588 85 0 0 0.00 strlen <internal>:-1
16196 57 0 0 0.00 date <internal>:-1
1756 56 0 0 0.00 md4c_toHtml <internal>:-1
1855 55 0 0 0.00 strip_tags <internal>:-1
1988 47 0 0 0.00 str_word_count <internal>:-1
2046 46 0 0 0.00 preg_match <internal>:-1
2144 44 0 0 0.00 str_contains <internal>:-1
22118 39 0 0 0.00 microtime <internal>:-1
2330 30 0 0 0.00 strrpos <internal>:-1
2429 29 0 0 0.00 is_dir <internal>:-1
2525 25 0 0 0.00 substr_replace <internal>:-1
2627 24 0 0 0.00 implode <internal>:-1
2729 20 0 0 0.00 Saaze\TemplateManager::<main> <internal>:-1
2819 19 0 0 0.00 sprintf <internal>:-1
2919 19 0 0 0.00 getenv <internal>:-1
3027 16 0 0 0.00 urlencode <internal>:-1
3116 16 0 0 0.00 str_split <internal>:-1
3218 14 0 0 0.00 FFI::cdef <internal>:-1
3314 14 0 0 0.00 define <internal>:-1
3431 13 0 0 0.00 is_array <internal>:-1
3513 13 0 0 0.00 ltrim <internal>:-1
Eliminating composer indeed cut away all composer related CPU usage.
It looks that above run cannot be fully compared to the two previous runs.
This time FFI::string became dominant, which was not dominant in previous runs.
No PHP source code from Simplified Saaze is visible except Saaze\TemplateManager::<main>.
Instead string-processing, like substr(), str_replace(), and strpos() seem to be important.
I am still hesitant how much I can trust above run as the err_count is so alarmingly high.
Added 12-May-2024: Another measurement with phpspy, this time with MD4C used as an extension, i.e., no FFI.
Watch out for the very high error count.
It is remarkable that the max() function is so dominant.
1phpspy -H 9999 --pgrep=php-fpm -@
2samp_count=1004 err_count=216898 func_count=39
3
4tincl texcl incl excl excl% func
5277 200 0 0 0.00 max <internal>:-1
6176 176 0 0 0.00 json_decode <internal>:-1
7121 121 0 0 0.00 <main> <internal>:-1
8106 106 0 0 0.00 printf <internal>:-1
975 75 0 0 0.00 ctype_space <internal>:-1
1044 43 0 0 0.00 md4c_toHtml <internal>:-1
1145 40 0 0 0.00 strpos <internal>:-1
1241 39 0 0 0.00 substr <internal>:-1
1329 29 0 0 0.00 strip_tags <internal>:-1
1426 21 0 0 0.00 rtrim <internal>:-1
15196 20 0 0 0.00 date <internal>:-1
1614 14 0 0 0.00 ltrim <internal>:-1
1713 13 0 0 0.00 yaml_parse <internal>:-1
1811 11 0 0 0.00 implode <internal>:-1
1923 10 0 0 0.00 urlencode <internal>:-1
2010 10 0 0 0.00 str_replace <internal>:-1
2110 10 0 0 0.00 substr_replace <internal>:-1
2213 9 0 0 0.00 Saaze\TemplateManager::<main> <internal>:-1
239 9 0 0 0.00 trim <internal>:-1
247 7 0 0 0.00 is_dir <internal>:-1
2543 4 0 0 0.00 microtime <internal>:-1
268 4 0 0 0.00 define <internal>:-1
274 4 0 0 0.00 preg_match <internal>:-1
284 4 0 0 0.00 strlen <internal>:-1
295 3 0 0 0.00 str_word_count <internal>:-1
303 3 0 0 0.00 getenv <internal>:-1
313 3 0 0 0.00 spl_autoload_register <internal>:-1
323 3 0 0 0.00 function_exists <internal>:-1
332 2 0 0 0.00 array_key_exists <internal>:-1
342 2 0 0 0.00 str_starts_with <internal>:-1
352 2 0 0 0.00 file_exists <internal>:-1
361 1 0 0 0.00 file_get_contents <internal>:-1
371 1 0 0 0.00 extension_loaded <internal>:-1
381 1 0 0 0.00 is_readable <internal>:-1
391 1 0 0 0.00 base64_encode <internal>:-1
401 1 0 0 0.00 DateTime::__construct <internal>:-1
411 1 0 0 0.00 sprintf <internal>:-1
421 1 0 0 0.00 html_entity_decode <internal>:-1
436 0 0 0 0.00 basename <internal>:-1