, 7 min read
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.