Work
- 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.
- Actually send profiler output to stdout from Maintenance.php.
- Actually set $wgProfiler in wmf-config for CLI (e.g. PhpAutoPrepend, or otherwise).
- Fix the percentages. - T247332: Percentage of time in MW inline profiler is broken
Analysis
Split off of T221119#6158813.
Even with the provided example, I am unable to get CLI debugging output.
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 ..
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 tideways is only enabled for php-fpm.
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:
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 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 = []; (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 nothing useful when searching for auto-prepend-file, until I realize I should search for auto_prepend_file instead, which gives one informative result. The code says this, too, is for php-fpm only.
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
It seems the current CLI profiling code was introduced in 2014 by 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 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 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 rMW58ee03b13d32: Avoid sending duplicate ProfilerOutputText comments/html, 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: BannerExistenceException due to non-existing CentralNotice banner (after Special:LanguageStats view), 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.