Page MenuHomePhabricator

Command line profiling not working on production
Open, MediumPublic

Description

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 set $wgProfiler in wmf-config for CLI (e.g. PhpAutoPrepend, or otherwise).
  • Actually send profiler output to stdout from Maintenance.php.
  • 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.

example
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
 ..
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 tideways is only enabled for php-fpm.

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:

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.

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

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 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.

ACTION ITEM: Call to logDataPageOutputOnly should be added in doMaintenance.php or wfLogProfilingData
ACTION ITEM: Fix the percentages, unless they are only off in this hacky workaround.

Event Timeline

Change 599476 had a related patch set uploaded (by Dave Pifke; owner: Dave Pifke):
[operations/puppet@production] php: $enable_request_profiling should affect CLI

https://gerrit.wikimedia.org/r/599476

Change 599476 merged by Giuseppe Lavagetto:
[operations/puppet@production] php: $enable_request_profiling should affect CLI

https://gerrit.wikimedia.org/r/599476

Krinkle triaged this task as Medium priority.Jul 16 2020, 11:24 PM

Change 725152 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] Deprecate wfLogProfilingData(), improve statsd/profiling docs

https://gerrit.wikimedia.org/r/725152

Change 725152 merged by jenkins-bot:

[mediawiki/core@master] Deprecate wfLogProfilingData(), improve statsd/profiling docs

https://gerrit.wikimedia.org/r/725152

Updated task description to summarise the actual work:

  • Done: Enable php-tideways-xhprof for CLI.
  • TODO: Actually set $wgProfiler in wmf-config for CLI.
  • TODO: Actually send profiler output to stdout from Maintenance.php.
  • Done: Fix the percentages. - T247332