## Work
* [x] Enable php-tideways-xhprof for `/etc/php/7.2/cli/` and configure accordingly with `clock_use_rdtsc=0`.
* Validate via `var_dump( extension_loaded( 'tideways_xhprof' ) );` from `mwdebug$ mwscript eval.php --wiki testwiki`.
* [x] Actually send profiler output to stdout from Maintenance.php.
* [ ] Actually set `$wgProfiler` in wmf-config for CLI (e.g. PhpAutoPrepend, or otherwise).
* [x] Fix the percentages. - {T247332}
## Analysis
Split off of T221119#6158813.
Even with the [[ https://wikitech.wikimedia.org/wiki/X-Wikimedia-Debug#Plaintext_request_profile | provided example ]], I am unable to get CLI debugging output.
```name=example,lang=html
mwdebug:~$ mwscript showJobs.php --wiki testwiki --profiler text
0
<!--
100.00% 282.967 1 - main()
89.56% 253.419 1 - section.Setup.php
57.12% 161.627 139 - AutoLoader::autoload
49.59% 140.324 1 - ExtensionRegistry::loadFromQueue
..
```
```name=actual
nikerabbit@mwdebug1001:~$ mwscript showJobs.php --wiki testwiki --profiler text
0
```
@Krinkle says
> Be sure to run it fom an mwdebug server as XHGui/Tideways are not installed on other servers.
XHGui is not relevant as far as I know, it only displays stuff if not using the text output. I check whether tideways is present:
```
nikerabbit@mwdebug1001:~$ php -i | grep -i tideways
```
With a bit of code searching I find that [[ https://gerrit.wikimedia.org/g/operations/puppet/+/5dd90d1d23485f476fd2f164a0d1c7aadca68bda/modules/profile/manifests/mediawiki/php.pp#276 | tideways is only enabled for php-fpm ]].
(NOTE)ACTION ITEM: tideways should also be enabled for cli, either globally or by introducing a wrapper that does it.
Then I wanted to try with enabling tideways manually. For that I need to pass command line switches to the php command, but mwscript hides it. To figure out the actual command, I use bash' xtrace option:
```lang=bash
nikerabbit@mwdebug2001:~$ set -x
nikerabbit@mwdebug2001:~$ echo $SHELLOPTS
+ echo braceexpand:emacs:hashall:histexpand:history:interactive-comments:monitor:xtrace
braceexpand:emacs:hashall:histexpand:history:interactive-comments:monitor:xtrace
nikerabbit@mwdebug1001:~$ mwscript showJobs.php --wiki testwiki --profiler text
+ mwscript showJobs.php --wiki testwiki --profiler text
0
nikerabbit@mwdebug1001:~$ export SHELLOPTS
+ export SHELLOPTS
nikerabbit@mwdebug1001:~$ mwscript showJobs.php --wiki testwiki --profiler text
+ mwscript showJobs.php --wiki testwiki --profiler text
+ . /etc/profile.d/mediawiki.sh
++ MEDIAWIKI_DEPLOYMENT_DIR=/srv/mediawiki
++ MEDIAWIKI_STAGING_DIR=/srv/mediawiki-staging
++ MEDIAWIKI_WEB_USER=www-data
++ grep -Pqw '(wikidev|l10nupdate)'
++ groups
++ umask 0002
+ '[' -d /srv/mediawiki-staging ']'
+ MEDIAWIKI_DEPLOYMENT_DIR_DIR_USE=/srv/mediawiki
+ '[' -z xterm-256color ']'
+ '[' xterm-256color = unknown ']'
+ '[' xterm-256color = dumb ']'
+ '[' '' = '' ']'
+ PHP=php
++ whoami
+ '[' nikerabbit '!=' www-data ']'
+ sudo -u www-data php /srv/mediawiki/multiversion/MWScript.php showJobs.php --wiki testwiki --profiler text
0
nikerabbit@mwdebug1001:~$ set +x
```
From this I learn the command... I check `MWScript.php` for `getenv` to see if those environment variables are needed. It seems they are not. So I tried with tideways manually enabled:
```
nikerabbit@mwdebug1001:~$ sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 /srv/mediawiki/multiversion/MWScript.php showJobs.php --wiki testwiki --profiler=text
0
```
Still no output. After some more code searching, I find this: https://gerrit.wikimedia.org/g/operations/mediawiki-config/+/f252dd31893c560ab3ca80990b077ce4b7f3d516/wmf-config/profiler.php#40
```
nikerabbit@mwdebug1001:~$ sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 /srv/mediawiki/multiversion/MWScript.php eval.php --wiki testwiki
> var_dump( extension_loaded( 'tideways_xhprof' ) );
bool(true)
```
Digging deeper in the code, next thing I find is https://gerrit.wikimedia.org/g/operations/mediawiki-config/+/f252dd31893c560ab3ca80990b077ce4b7f3d516/wmf-config/profiler.php#55
So a shot in the dark attempt is:
```
nikerabbit@mwdebug1001:~$ sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 /srv/mediawiki/multiversion/MWScript.php showJobs.php --wiki testwiki --forceprocile
Unexpected option forceprocile!
```
I'm eyeing at code which reads [[ https://gerrit.wikimedia.org/g/operations/mediawiki-config/+/f252dd31893c560ab3ca80990b077ce4b7f3d516/src/XWikimediaDebug.php#26 | HTTP_X_WIKIMEDIA_DEBUG ]] from `$SERVER`. But reading `profiler.php`, `PHP_SAPI === 'cli'` should be sufficient to enable text profiling. Some more debugging:
```
nikerabbit@mwdebug1001:~$ sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 /srv/mediawiki/multiversion/MWScript.php eval.php --wiki testwiki
> var_dump( $wmgProfiler );
NULL
> var_dump( PHP_SAPI );
string(3) "cli"
```
Given that `profiler.php` sets `$wmgProfiler = [];` ([[ https://gerrit.wikimedia.org/g/operations/mediawiki-config/+/f252dd31893c560ab3ca80990b077ce4b7f3d516/wmf-config/profiler.php#28 | source ]]) I conclude that either the file is not loaded at all, or the function `wmfSetupProfiler` is not called. Further debugging shows that it seems to the former:
```
> var_dump( function_exists( 'wmfSetupProfiler' ) );
bool(false)
```
Just to make sure that this is same for using mwscript directly:
```
nikerabbit@mwdebug1001:~$ mwscript eval.php --wiki=testwiki
> var_dump( function_exists( 'wmfSetupProfiler' ) );
bool(false)
```
`profiler.php` is supposed to be included by `PhpAutoPrepend.php`. First I find [[ https://codesearch.wmflabs.org/search/?q=auto-prepend-file&i=nope&files=&repos= | nothing useful]] when searching for `auto-prepend-file`, until I realize I should search for `auto_prepend_file` instead, which gives [[ https://gerrit.wikimedia.org/g/operations/puppet/+/678e9523d128e1de3fad7b9135e3e40836977049/modules/profile/manifests/mediawiki/php.pp#77 | one informative result ]]. The code says this, too, is for php-fpm only.
(NOTE)ACTION ITEM: Profiler should be automatically configured on CLI when using `--profiler=text`.
Trying again with that enabled manually:
```
nikerabbit@mwdebug1001:~$ sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 -dauto_prepend_file=/srv/mediawiki/wmf-config/PhpAutoPrepend.php /srv/mediawiki/multiversion/MWScript.php showJobs.php --wiki testwiki --profiler text
0
```
Still nothing? Confirming with eval.php:
```
nikerabbit@mwdebug1001:~$ sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 -dauto_prepend_file=/srv/mediawiki/wmf-config/PhpAutoPrepend.php /srv/mediawiki/multiversion/MWScript.php eval.php --wiki testwiki --profiler text
> var_dump( $wmgProfiler );
array(3) {
["class"]=>
string(14) "ProfilerXhprof"
["flags"]=>
int(15)
["output"]=>
string(4) "text"
}
```
So we have the profiler configured, but still no output. Now trying to figure out what is supposed to give the output, starting from reading the `ProfilerXhprof` class. It has `getOutput` which is impossible to search for, and PhpStorm doesn't find any callers. Trying it manually:
```
sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 -dauto_prepend_file=/srv/mediawiki/wmf-config/PhpAutoPrepend.php /srv/mediawiki/multiversion/MWScript.php eval.php --wiki testwiki --profiler text
> var_dump( Profiler::instance()->getOutput() );
string(75924) "Name Calls Total Min Each Max % Mem
Maintenance::readconsole 2 45200002 22600001 22600001 22600001 2260000100.000% 800
AutoLoader::autoload 128 84392 5 659 5041 4219600.000% 8650575
ExtensionRegistry::loadFromQueue 1 60234 60234 60234 60234 3011700.000% 6142512
ExtensionRegistry::readFromQueue 1 35891 35891 35891 35891 1794550.000% 4610648
Wikimedia\Services\ServiceContainer::getService 24 26937 1 1122 13535 1346850.000% 2167776
[....]
```
So it seems this is an issue of the output not being called after the script finishes executing. Now trying to understand if such call existed before, and where it may have gotten removed. Starting from maintenance.php
(NOTE) ACTION ITEM: MW_CMDLINE_CALLBACK` seems completely unused according to code search. Consider removing it, or at least document it. (T305422)
It seems the current CLI profiling code was introduced in 2014 by [[ https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/core/+/66170e7e59171177ccd0538a4b5a5712473135ae%5E%21/ |Aaron]], but there is no call to output data. Maybe it was used to log into database or other place.
There must be some place which logs the output for web requests, as I assume at least that part is working. Searching for `Profiler::instance` should [[ https://codesearch.wmflabs.org/search/?q=Profiler%3A%3Ainstance&i=nope&files=&repos= | reveal it ]], as it is the only way to access the profiler, apart from the code that creates it. It reveals it is done in `wfLogProfilingData`. That is called in the end of [[ https://gerrit.wikimedia.org/g/mediawiki/core/+/02c1ce97cc669f0efe51855ecaf20617c6a31753/maintenance/doMaintenance.php#138 | doMaintenance.php ]]. Seeing if it outputs anything, I will try to call it manually:
```
nikerabbit@mwdebug1001:~$ sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 -dauto_prepend_file=/srv/mediawiki/wmf-config/PhpAutoPrepend.php /srv/mediawiki/multiversion/MWScript.php eval.php --wiki testwiki --profiler text
> wfLogProfilingData();
```
`wfLogProfilingData` calls `Profiler::logData`, which first checks whether we pass elapsed time threshold. That defaults to 0.0, so that should be okay. But it fails in the next check: `if ( !$output->logsToOutput() )`. `ProfileOutputText` returns `true` from `logsToOutput`. There is a separate method `logDataPageOutputOnly` that does the opposite, only logs to the output for those that log to the output, but it is only called from `MediaWiki.php` (aka index.php requests).
This might have gotten broken in {58ee03b}, but I have not confirmed that. So we definitely need a call to `logDataPageOutputOnly` at the end of CLI execution somehow. I am not sure how to do it though. I tried to hack this working with `auto_append_file`, but it seems it is too late and Profiler is no longer accessible.
So my final hack is (and this only works if you can easily call your thing from eval.php)
```
nikerabbit@mwdebug1001:~$ echo 'MessageIndex::singleton()->rebuild(); Profiler::instance()->logDataPageOutputOnly();' | sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 -dauto_prepend_file=/srv/mediawiki/wmf-config/PhpAutoPrepend.php /srv/mediawiki/multiversion/MWScript.php eval.php --wiki testwiki
Caught exception BannerExistenceException: No banner exists where tmp_name = WikiCon. Could not load.
#0 /srv/mediawiki/php-1.35.0-wmf.32/extensions/CentralNotice/includes/Banner.php(174): Banner->populateBasicData()
#1 /srv/mediawiki/php-1.35.0-wmf.32/extensions/CentralNotice/includes/Banner.php(890): Banner->getName()
#2 /srv/mediawiki/php-1.35.0-wmf.32/extensions/CentralNotice/includes/Banner.php(854): Banner->getMessageFieldsCacheKey(Object(WANObjectCache))
#3 /srv/mediawiki/php-1.35.0-wmf.32/extensions/CentralNotice/includes/BannerMessageGroup.php(40): Banner->getMessageFieldsFromCache()
#4 /srv/mediawiki/php-1.35.0-wmf.32/extensions/Translate/utils/MessageIndex.php(375): BannerMessageGroup->getKeys()
#5 /srv/mediawiki/php-1.35.0-wmf.32/extensions/Translate/utils/MessageIndex.php(221): MessageIndex->checkAndAdd(Array, Object(BannerMessageGroup))
#6 /srv/mediawiki/php-1.35.0-wmf.32/maintenance/eval.php(78) : eval()'d code(1): MessageIndex->rebuild()
#7 /srv/mediawiki/php-1.35.0-wmf.32/maintenance/eval.php(78): eval()
#8 /srv/mediawiki/multiversion/MWScript.php(101): require_once('/srv/mediawiki/...')
#9 {main}
```
That is {T157997}, so let's try on MetaWiki:
```
nikerabbit@mwdebug1001:~$ echo 'MessageIndex::singleton()->rebuild(); Profiler::instance()->logDataPageOutputOnly();' | sudo -u www-data php -dextension=tideways_xhprof.so -dtideways_xhprof.clock_use_rdtsc=0 -dauto_prepend_file=/srv/mediawiki/wmf-config/PhpAutoPrepend.php /srv/mediawiki/multiversion/MWScript.php eval.php --wiki metawiki --profiler text
<!--
1855324800.00% 37106.496 1 - MessageIndex::rebuild
1629789850.00% 32595.797 8752 - MessageIndex::checkAndAdd
953680050.00% 19073.601 10660 - MessageGroupOld::getKeys
940971100.00% 18819.422 10659 - WikiPageMessageGroup::getDefinitions
868652650.00% 17373.053 15794 - Wikimedia\Rdbms\Database::select
807331350.00% 16146.627 15887 - Wikimedia\Rdbms\Database::query
795130750.00% 15902.615 15887 - Wikimedia\Rdbms\Database::executeQuery
776173350.00% 15523.467 15887 - Wikimedia\Rdbms\Database::executeQueryAttempt
673419600.00% 13468.392 15887 - Wikimedia\Rdbms\DatabaseMysqli::doQuery
628895450.00% 12577.909 5558 - BannerMessageGroup::getKeys
625662750.00% 12513.255 5558 - Banner::getMessageFieldsFromCache
530646250.00% 10612.925 15816 - Wikimedia\Rdbms\DBConnRef::__call
[...]
```
Some kind of success! The percentages are clearly broken, but the times and call counts seem to be okay.
(NOTE) ACTION ITEM: Call to `logDataPageOutputOnly` should be added in `doMaintenance.php` or `wfLogProfilingData`
(NOTE) ACTION ITEM: Fix the percentages, unless they are only off in this hacky workaround.