Manual:Profiling

From MediaWiki.org
Jump to navigation Jump to search

Other languages:
English • ‎polski • ‎日本語

Profiling tracks code execution during a page action and reports back the percentage of total code execution that was spent in any specific function. Profiling is an advanced task intended for developers and system administrators to track sources of slowness in MediaWiki that should be optimized.

PHP profiling[edit]

You can use XHProf, which is available for both HHVM and Zend PHP 5, and provides tracing and profiling. That's how the rest of the PHP world does it.

Starting with MediaWiki 1.29, you can also use tideways, which additionally supports PHP 7. Tideways also advertises a seemingly proprietary UI to visualize results, but if you follow the instructions for without the UI, it should be fine. Installing the php-tideways Debian/Ubuntu package also just includes the PHP extension.

Installing XHProf[edit]

Execute the following commands (assuming you're using PHP 7.2; you can use php -v to find out):

$ git clone https://github.com/longxinH/xhprof
$ cd xhprof/extension
$ phpize
$ ./configure --with-php-config=/usr/bin/php-config7.2
$ sudo make && sudo make install
$ sudo service apache2 restart

MediaWiki custom profiler[edit]

The custom MediaWiki profiling calls (wfProfileIn/wfProfileOut) are deprecated and are being progressively removed and are no-ops in MediaWiki 1.25+.

MediaWiki profiling is configured in StartProfiler.php in the root of your wiki. There's a StartProfiler.sample file there to get you started as well.

MediaWiki version: 1.25

In MediaWiki 1.25 profiling was completely rewritten and many settings previous relating to profiling were removed in favor of consolidating them as parameters to $wgProfiler. Notably, output has been separated from class types. For documentation about profiling prior to 1.25, see an older version of this page.

Here is a typical StartProfiler.php:

<?php
$wgProfiler['class'] = 'ProfilerXhprof';
$wgProfiler['output'] = array( 'ProfilerOutputText' );
$wgProfiler['visible'] = true;

Each of these parameters (and more) are described in detail:

class
'ProfilerXhprof'. ProfilerXhprof is new in MediaWiki 1.25 and provides an Xhprof-backed profiler that captures profiling data for all functions as well as sub-functional units. Old values such as ProfilerStandard, ProfilerUDP, ProfilerDB, etc do not work. Even if you are using Tideways, still specify the ProfilerXhprof class.
output
One or more of 'udp', 'text', 'db', 'dump'[1]. Text outputs the information in either HTML comments or after the skin. DB requires the profiling table to be created[2] and stores data on individual profiling runs. UDP is a format send to a udpprofile daemon. Dump produces a dump of the profiling info for use with xhprof GUI (xhprofgui role on Vagrant setup).
The output classes available to you by default are ProfilerOutputDb, ProfilerOutputDump, ProfilerOutputStats, ProfilerOutputText, and ProfilerOutputUdp.[3] How that works together with the values 'udp', 'text', 'db', 'dump' is unclear!
outputDir
Only applies to 'dump' format. Required to specify where the dump files will be stored.
perHost
Only applies to 'db' format. Whether to store host information with profiling runs.
udphost
Only applies to 'udp' format. Host/IP to send data to.
udpport
Only applies to 'udp' format. Port to send data to.
udpformat
Only applies to 'udp' format. Format string to use. Can usually be left alone.
visible
Only applies to 'text' format. Whether text is shown after the skin or in an HTML comment.

Troubleshooting[edit]

If you get "Fatal error: Uncaught Exception: Neither xhprof nor tideways are installed" then you need to do:

$ sudo apt install php-tideways
$ sudo service apache2 restart

Output[edit]

Text output looks like:

100.00% 508.972      1 - main()
 96.67% 492.003      1 - MediaWiki::run
 96.61% 491.699      1 - MediaWiki::main
 87.12% 443.434      1 - MediaWiki::performRequest
 84.16% 428.356      1 - SpecialPageFactory::executePath
 84.11% 428.073      1 - SpecialPage::run
 84.10% 428.058      1 - SpecialRecentChanges::execute
 63.82% 324.838      1 - ChangesListSpecialPage::execute
 57.07% 290.495      1 - ChangesListSpecialPage::webOutput
 51.06% 259.877      1 - SpecialRecentChanges::outputChangesList
 44.72% 227.633    397 - Wikimedia\Rdbms\Database::query
 31.07% 158.155    922 - Message::fetchMessage
 30.61% 155.788    865 - MessageCache::get
 29.55% 150.398    398 - Wikimedia\Rdbms\Database::doProfiledQuery
 29.39% 149.570    865 - MessageCache::getMessageFromFallbackChain
 29.26% 148.923    869 - MessageCache::getMessageForLang
 29.06% 147.931    393 - Wikimedia\Rdbms\Database::select
 27.30% 138.962      1 - EnhancedChangesList::endRecentChangesList
 27.30% 138.960      1 - EnhancedChangesList::recentChangesBlock
...

The first column is the time percent; the second column is the time (in ms); the third column is the count; and the fourth column is the name of the method.

See also[edit]

Footnotes[edit]

  1. See git #750e4eb9
  2. Use maintenance/archives/patch-profiling.sql script
  3. Source code of StartProfiler.sample, StartProfiler.sample