, 8 min read
Simplified Saaze Monitored with PHPSPY
Original post is here eklausmeier.goip.de/blog/2023/10-29-simplified-saaze-monitored-with-phpspy.
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.
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.
phpspy -p 940 -p 17132 -p 61898 -p 61899 -@
samp_count=666 err_count=10 func_count=67
tincl texcl incl excl excl% func
313 151 0 0 0.00 ComposerAutoloaderInit50920a90746408ba7a500bacdb4908c1::getLoader /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:19
132 103 0 0 0.00 composerRequire50920a90746408ba7a500bacdb4908c1 /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:50
99 99 0 0 0.00 Composer\Autoload\includeFile /home/klm/php/sndsaaze/vendor/composer/ClassLoader.php:569
76 76 0 0 0.00 json_decode <internal>:-1
298 34 0 0 0.00 Saaze\Saaze::run /home/klm/php/sndsaaze/vendor/eklausme/saaze/Saaze.php:32
30 30 0 0 0.00 ComposerAutoloaderInit50920a90746408ba7a500bacdb4908c1::loadClassLoader /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:9
23 23 0 0 0.00 FFI::cdef <internal>:-1
19 19 0 0 0.00 file_get_contents <internal>:-1
15 15 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-mbstring/bootstrap.php:1
13 13 0 0 0.00 md4c_toHtml <internal>:-1
14 11 0 0 0.00 str_word_count <internal>:-1
10 10 0 0 0.00 yaml_parse <internal>:-1
322 9 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/autoload.php:1
90 9 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/blog/entry.php:1
8 8 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-intl-grapheme/bootstrap.php:1
5 5 0 0 0.00 FFI::string <internal>:-1
653 4 0 0 0.00 <main> /home/klm/php/sndsaaze/public/index.php:1
5 4 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/error.php:1
5 3 0 0 0.00 microtime <internal>:-1
4 3 0 0 0.00 strpos <internal>:-1
3 3 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-ctype/bootstrap.php:1
3 3 0 0 0.00 shell_exec <internal>:-1
27 2 0 0 0.00 Saaze\CollectionArray::loadCollections /home/klm/php/sndsaaze/vendor/eklausme/saaze/CollectionArray.php:27
21 2 0 0 0.00 <main> <internal>:-1
10 2 0 0 0.00 is_dir <internal>:-1
9 2 0 0 0.00 Saaze\Collection::__construct /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:15
9 2 0 0 0.00 Saaze\TemplateManager::renderError /home/klm/php/sndsaaze/vendor/eklausme/saaze/TemplateManager.php:62
4 2 0 0 0.00 scandir <internal>:-1
3 2 0 0 0.00 strlen <internal>:-1
2 2 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/top-layout.php:1
2 2 0 0 0.00 Saaze\MarkdownContentParser::inlineMath /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:172
2 2 0 0 0.00 strip_tags <internal>:-1
23 1 0 0 0.00 Saaze\MarkdownContentParser::toHtml /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:562
9 1 0 0 0.00 substr <internal>:-1
1 1 0 0 0.00 substr_replace <internal>:-1
1 1 0 0 0.00 usort <internal>:-1
1 1 0 0 0.00 printf <internal>:-1
1 1 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-intl-normalizer/bootstrap.php:1
1 1 0 0 0.00 ob_end_clean <internal>:-1
1 1 0 0 0.00 str_replace <internal>:-1
1 1 0 0 0.00 file_put_contents <internal>:-1
1 1 0 0 0.00 max <internal>:-1
1 1 0 0 0.00 is_readable <internal>:-1
111 0 0 0 0.00 Saaze\Collection::loadMkdwnRecursive /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:70
91 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.
phpspy -p 879 -p 1015 -p 1016 -p 20333 -@
samp_count=2422 err_count=55 func_count=97
tincl texcl incl excl excl% func
1077 491 0 0 0.00 ComposerAutoloaderInit50920a90746408ba7a500bacdb4908c1::getLoader /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:19
506 369 0 0 0.00 composerRequire50920a90746408ba7a500bacdb4908c1 /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:50
353 353 0 0 0.00 json_decode <internal>:-1
335 335 0 0 0.00 Composer\Autoload\includeFile /home/klm/php/sndsaaze/vendor/composer/ClassLoader.php:569
81 81 0 0 0.00 md4c_toHtml <internal>:-1
76 76 0 0 0.00 ComposerAutoloaderInit50920a90746408ba7a500bacdb4908c1::loadClassLoader /home/klm/php/sndsaaze/vendor/composer/autoload_real.php:9
75 75 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-mbstring/bootstrap.php:1
459 69 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/blog/entry.php:1
67 67 0 0 0.00 FFI::cdef <internal>:-1
58 58 0 0 0.00 file_get_contents <internal>:-1
48 35 0 0 0.00 str_word_count <internal>:-1
1162 29 0 0 0.00 Saaze\Saaze::run /home/klm/php/sndsaaze/vendor/eklausme/saaze/Saaze.php:32
28 28 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-intl-grapheme/bootstrap.php:1
26 26 0 0 0.00 yaml_parse <internal>:-1
1096 23 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/autoload.php:1
22 20 0 0 0.00 scandir <internal>:-1
21 20 0 0 0.00 strpos <internal>:-1
491 19 0 0 0.00 Saaze\TemplateManager::renderEntry /home/klm/php/sndsaaze/vendor/eklausme/saaze/TemplateManager.php:37
21 16 0 0 0.00 microtime <internal>:-1
16 16 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-ctype/bootstrap.php:1
32 15 0 0 0.00 substr <internal>:-1
74 14 0 0 0.00 <main> <internal>:-1
2384 12 0 0 0.00 <main> /home/klm/php/sndsaaze/public/index.php:1
15 12 0 0 0.00 Saaze\MarkdownContentParser::inlineMath /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:172
12 12 0 0 0.00 strip_tags <internal>:-1
20 11 0 0 0.00 is_dir <internal>:-1
12 10 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/top-layout.php:1
7 7 0 0 0.00 str_replace <internal>:-1
260 6 0 0 0.00 Saaze\Collection::loadEntry /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:82
159 6 0 0 0.00 Saaze\MarkdownContentParser::toHtml /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:562
8 6 0 0 0.00 FFI::string <internal>:-1
6 6 0 0 0.00 shell_exec <internal>:-1
233 5 0 0 0.00 Saaze\Entry::getContentAndExcerpt /home/klm/php/sndsaaze/vendor/eklausme/saaze/Entry.php:86
6 5 0 0 0.00 <main> /home/klm/php/sndsaaze/vendor/symfony/polyfill-intl-normalizer/bootstrap.php:1
5 5 0 0 0.00 function_exists <internal>:-1
71 4 0 0 0.00 Saaze\CollectionArray::loadCollections /home/klm/php/sndsaaze/vendor/eklausme/saaze/CollectionArray.php:27
50 4 0 0 0.00 Saaze\Entry::parseEntry /home/klm/php/sndsaaze/vendor/eklausme/saaze/Entry.php:21
6 4 0 0 0.00 Saaze\TemplateManager::<main> /home/klm/php/sndsaaze/templates/error.php:1
6 4 0 0 0.00 is_readable <internal>:-1
21 3 0 0 0.00 Saaze\Collection::__construct /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:15
5 3 0 0 0.00 Saaze\TemplateManager::<main> <internal>:-1
4 3 0 0 0.00 Saaze\MarkdownContentParser::myTag /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:212
3 3 0 0 0.00 substr_replace <internal>:-1
3 3 0 0 0.00 max <internal>:-1
3 3 0 0 0.00 Saaze\MarkdownContentParser::displayMath /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:145
3 3 0 0 0.00 dirname <internal>:-1
3 3 0 0 0.00 getenv <internal>:-1
3 3 0 0 0.00 rtrim <internal>:-1
549 2 0 0 0.00 Saaze\Collection::loadMkdwnRecursive /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:70
72 2 0 0 0.00 Saaze\Config::init /home/klm/php/sndsaaze/vendor/eklausme/saaze/Config.php:14
20 2 0 0 0.00 Saaze\Collection::parseCollection /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:22
16 2 0 0 0.00 Saaze\MarkdownContentParser::gallery /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:397
5 2 0 0 0.00 date <internal>:-1
3 2 0 0 0.00 strlen <internal>:-1
2 2 0 0 0.00 ltrim <internal>:-1
2 2 0 0 0.00 Saaze\Collection::Saaze\{closure} /home/klm/php/sndsaaze/vendor/eklausme/saaze/Collection.php:54
2 2 0 0 0.00 Saaze\TemplateManager::templateExists /home/klm/php/sndsaaze/vendor/eklausme/saaze/TemplateManager.php:7
2 2 0 0 0.00 Saaze\MarkdownContentParser::twitter /home/klm/php/sndsaaze/vendor/eklausme/saaze/MarkdownContentParser.php:333
2 2 0 0 0.00 fopen <internal>:-1
2 2 0 0 0.00 Composer\Autoload\ClassLoader::register /home/klm/php/sndsaaze/vendor/composer/ClassLoader.php:389
2 2 0 0 0.00 strtotime <internal>:-1
192 1 0 0 0.00 Saaze\Entry::__construct /home/klm/php/sndsaaze/vendor/eklausme/saaze/Entry.php:13
10 1 0 0 0.00 Saaze\Entry::getUrl /home/klm/php/sndsaaze/vendor/eklausme/saaze/Entry.php:74
4 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.
phpspy -H 9999 --pgrep=php-fpm -@
samp_count=2651 err_count=575856 func_count=58
tincl texcl incl excl excl% func
1047 850 0 0 0.00 FFI::string <internal>:-1
230 207 0 0 0.00 substr <internal>:-1
209 206 0 0 0.00 str_replace <internal>:-1
212 194 0 0 0.00 <main> <internal>:-1
269 193 0 0 0.00 max <internal>:-1
200 185 0 0 0.00 strpos <internal>:-1
147 147 0 0 0.00 ctype_space <internal>:-1
102 99 0 0 0.00 printf <internal>:-1
82 82 0 0 0.00 rtrim <internal>:-1
68 68 0 0 0.00 json_decode <internal>:-1
123 43 0 0 0.00 date <internal>:-1
42 41 0 0 0.00 strlen <internal>:-1
30 30 0 0 0.00 strip_tags <internal>:-1
28 28 0 0 0.00 md4c_toHtml <internal>:-1
47 23 0 0 0.00 str_word_count <internal>:-1
21 21 0 0 0.00 preg_match <internal>:-1
18 18 0 0 0.00 str_contains <internal>:-1
17 16 0 0 0.00 implode <internal>:-1
20 15 0 0 0.00 Saaze\TemplateManager::<main> <internal>:-1
15 15 0 0 0.00 strrpos <internal>:-1
14 14 0 0 0.00 is_dir <internal>:-1
13 13 0 0 0.00 define <internal>:-1
58 12 0 0 0.00 microtime <internal>:-1
12 12 0 0 0.00 getenv <internal>:-1
11 11 0 0 0.00 sprintf <internal>:-1
11 11 0 0 0.00 substr_replace <internal>:-1
11 10 0 0 0.00 FFI::cdef <internal>:-1
9 9 0 0 0.00 str_split <internal>:-1
8 8 0 0 0.00 function_exists <internal>:-1
14 7 0 0 0.00 urlencode <internal>:-1
7 7 0 0 0.00 DateTime::__construct <internal>:-1
6 6 0 0 0.00 yaml_parse <internal>:-1
13 5 0 0 0.00 is_array <internal>:-1
5 5 0 0 0.00 ltrim <internal>:-1
4 3 0 0 0.00 explode <internal>:-1
3 3 0 0 0.00 is_readable <internal>:-1
3 3 0 0 0.00 preg_replace <internal>:-1
3 3 0 0 0.00 extension_loaded <internal>:-1
3 3 0 0 0.00 str_starts_with <internal>:-1
3 3 0 0 0.00 spl_autoload_register <internal>:-1
3 3 0 0 0.00 trim <internal>:-1
3 2 0 0 0.00 count <internal>:-1
2 2 0 0 0.00 is_string <internal>:-1
2 2 0 0 0.00 is_bool <internal>:-1
1 1 0 0 0.00 round <internal>:-1
1 1 0 0 0.00 error_reporting <internal>:-1
1 1 0 0 0.00 print_r <internal>:-1
1 1 0 0 0.00 header <internal>:-1
1 1 0 0 0.00 mb_strtolower <internal>:-1
1 1 0 0 0.00 array_key_exists <internal>:-1
1 1 0 0 0.00 spl_autoload_unregister <internal>:-1
1 1 0 0 0.00 gettype <internal>:-1
1 1 0 0 0.00 mb_substr <internal>:-1
1 1 0 0 0.00 ucwords <internal>:-1
1 1 0 0 0.00 openssl_cipher_iv_length <internal>:-1
1 1 0 0 0.00 file_exists <internal>:-1
1 1 0 0 0.00 defined <internal>:-1
1 0 0 0 0.00 is_object <internal>:-1
At a later time:
phpspy -H 9999 --pgrep=php-fpm -@
samp_count=5475 err_count=1004659 func_count=64
tincl texcl incl excl excl% func
2301 1842 0 0 0.00 FFI::string <internal>:-1
462 458 0 0 0.00 str_replace <internal>:-1
491 447 0 0 0.00 substr <internal>:-1
467 431 0 0 0.00 strpos <internal>:-1
556 414 0 0 0.00 max <internal>:-1
353 310 0 0 0.00 <main> <internal>:-1
299 299 0 0 0.00 ctype_space <internal>:-1
207 203 0 0 0.00 printf <internal>:-1
145 142 0 0 0.00 rtrim <internal>:-1
122 122 0 0 0.00 json_decode <internal>:-1
88 85 0 0 0.00 strlen <internal>:-1
196 57 0 0 0.00 date <internal>:-1
56 56 0 0 0.00 md4c_toHtml <internal>:-1
55 55 0 0 0.00 strip_tags <internal>:-1
88 47 0 0 0.00 str_word_count <internal>:-1
46 46 0 0 0.00 preg_match <internal>:-1
44 44 0 0 0.00 str_contains <internal>:-1
118 39 0 0 0.00 microtime <internal>:-1
30 30 0 0 0.00 strrpos <internal>:-1
29 29 0 0 0.00 is_dir <internal>:-1
25 25 0 0 0.00 substr_replace <internal>:-1
27 24 0 0 0.00 implode <internal>:-1
29 20 0 0 0.00 Saaze\TemplateManager::<main> <internal>:-1
19 19 0 0 0.00 sprintf <internal>:-1
19 19 0 0 0.00 getenv <internal>:-1
27 16 0 0 0.00 urlencode <internal>:-1
16 16 0 0 0.00 str_split <internal>:-1
18 14 0 0 0.00 FFI::cdef <internal>:-1
14 14 0 0 0.00 define <internal>:-1
31 13 0 0 0.00 is_array <internal>:-1
13 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.
phpspy -H 9999 --pgrep=php-fpm -@
samp_count=1004 err_count=216898 func_count=39
tincl texcl incl excl excl% func
277 200 0 0 0.00 max <internal>:-1
176 176 0 0 0.00 json_decode <internal>:-1
121 121 0 0 0.00 <main> <internal>:-1
106 106 0 0 0.00 printf <internal>:-1
75 75 0 0 0.00 ctype_space <internal>:-1
44 43 0 0 0.00 md4c_toHtml <internal>:-1
45 40 0 0 0.00 strpos <internal>:-1
41 39 0 0 0.00 substr <internal>:-1
29 29 0 0 0.00 strip_tags <internal>:-1
26 21 0 0 0.00 rtrim <internal>:-1
196 20 0 0 0.00 date <internal>:-1
14 14 0 0 0.00 ltrim <internal>:-1
13 13 0 0 0.00 yaml_parse <internal>:-1
11 11 0 0 0.00 implode <internal>:-1
23 10 0 0 0.00 urlencode <internal>:-1
10 10 0 0 0.00 str_replace <internal>:-1
10 10 0 0 0.00 substr_replace <internal>:-1
13 9 0 0 0.00 Saaze\TemplateManager::<main> <internal>:-1
9 9 0 0 0.00 trim <internal>:-1
7 7 0 0 0.00 is_dir <internal>:-1
43 4 0 0 0.00 microtime <internal>:-1
8 4 0 0 0.00 define <internal>:-1
4 4 0 0 0.00 preg_match <internal>:-1
4 4 0 0 0.00 strlen <internal>:-1
5 3 0 0 0.00 str_word_count <internal>:-1
3 3 0 0 0.00 getenv <internal>:-1
3 3 0 0 0.00 spl_autoload_register <internal>:-1
3 3 0 0 0.00 function_exists <internal>:-1
2 2 0 0 0.00 array_key_exists <internal>:-1
2 2 0 0 0.00 str_starts_with <internal>:-1
2 2 0 0 0.00 file_exists <internal>:-1
1 1 0 0 0.00 file_get_contents <internal>:-1
1 1 0 0 0.00 extension_loaded <internal>:-1
1 1 0 0 0.00 is_readable <internal>:-1
1 1 0 0 0.00 base64_encode <internal>:-1
1 1 0 0 0.00 DateTime::__construct <internal>:-1
1 1 0 0 0.00 sprintf <internal>:-1
1 1 0 0 0.00 html_entity_decode <internal>:-1
6 0 0 0 0.00 basename <internal>:-1