Thijs/wiki.techinc.nl
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Refactor profiling output from profiling

Browse source 
* Added a standard getFunctionStats() method for Profilers to return
  per function data as maps. This is not toolbar specific like getRawData().
* Cleaned up the interface of SectionProfiler::getFunctionStats() a bit.
* Removed unused cpu_sq, real_sq fields from profiler UDP output.
* Moved getTime/getInitialTime to ProfilerStandard.

Co-Authored-By: Aaron Schulz <aschulz@wikimedia.org>
Change-Id: I266ed82031a434465f64896eb327f3872fdf1db1
This commit is contained in:
Chad Horohoe 2014-11-14 10:58:07 -08:00 committed by Bryan Davis
parent 07527e1e5b
commit b8d93fb4fd
15 changed files with 351 additions and 469 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
RELEASE-NOTES-1.25
View file

@ -19,6 +19,8 @@ production.
* (bug 72951) The UserGetLanguageObject hook may be passed any IContextSource
for its $context parameter. Formerly it was documented as receiving a
RequestContext specifically.
* Profiling was restructured and $wgProfiler now requires an 'output' parameter.
See StartProfiler.sample for details.
=== New features in 1.25 ===
* (bug 62861) Updated plural rules to CLDR 26. Includes incompatible changes

31
StartProfiler.sample
View file

@ -3,24 +3,27 @@
/**
* To use a profiler, copy this file to StartProfiler.php,
* and add either:
* $wgProfiler['class'] = 'ProfilerStandard';
* or
* $wgProfiler['class'] = 'ProfilerXhprof';
*
* // Does not support the debugging toolbar
* // Stores profiling information in the database
* // Requires running maintenance/archives/patch-profiling.sql
* $wgProfiler['class'] = 'ProfilerSimpleDB'
* For output, add:
* $wgProfiler['output'] = array( 'text' );
* 'text' can be one (or more) of 'text' 'udp' or 'db'
* 'db' requires creating the profiling table, see patch-profiling.sql
*
* or:
* The 'text' output will be added to the output page in a comment approriate
* to the output's mime type. For a text/html page, this display can be
* changed to a preformatted text block by setting the 'visible' configuration
* flag:
* $wgProfiler['visible'] = true;
*
* // Supports the debugging toolbar
* // Does not store profiling information in the database
* $wgProfiler['class'] = 'ProfilerStandard';
* The 'db' output expects a database table that can be created by applying
* maintenance/archives/patch-profiling.sql to your database.
*
* Or for a sampling profiler:
* For a rudimentary sampling profiler:
* if ( !mt_rand( 0, 100 ) ) {
* $wgProfiler['class'] = 'ProfilerSimpleDB';
* } else {
* $wgProfiler['class'] = 'ProfilerStub';
* $wgProfiler['class'] = 'ProfilerStandard';
* $wgProfiler['output'] = array( 'db' );
* }
*
* Configuration of the profiler output can be done in LocalSettings.php
*/

9
autoload.php
View file

@ -880,10 +880,11 @@ $wgAutoloadLocalClasses = array(
'ProcessCacheLRU' => __DIR__ . '/includes/libs/ProcessCacheLRU.php',
'ProfileSection' => __DIR__ . '/includes/profiler/ProfileSection.php',
'Profiler' => __DIR__ . '/includes/profiler/Profiler.php',
'ProfilerSimpleDB' => __DIR__ . '/includes/profiler/ProfilerSimpleDB.php',
'ProfilerSimpleText' => __DIR__ . '/includes/profiler/ProfilerSimpleText.php',
'ProfilerOutput' => __DIR__ . '/includes/profiler/output/ProfilerOutput.php',
'ProfilerOutputDb' => __DIR__ . '/includes/profiler/output/ProfilerOutputDb.php',
'ProfilerOutputText' => __DIR__ . '/includes/profiler/output/ProfilerOutputText.php',
'ProfilerOutputUdp' => __DIR__ . '/includes/profiler/output/ProfilerOutputUdp.php',
'ProfilerSimpleTrace' => __DIR__ . '/includes/profiler/ProfilerSimpleTrace.php',
'ProfilerSimpleUDP' => __DIR__ . '/includes/profiler/ProfilerSimpleUDP.php',
'ProfilerStandard' => __DIR__ . '/includes/profiler/ProfilerStandard.php',
'ProfilerStub' => __DIR__ . '/includes/profiler/ProfilerStub.php',
'ProfilerXhprof' => __DIR__ . '/includes/profiler/ProfilerXhprof.php',
@ -1315,4 +1316,4 @@ $wgAutoloadLocalClasses = array(
'lessc_formatter_lessjs' => __DIR__ . '/includes/libs/lessc.inc.php',
'lessc_parser' => __DIR__ . '/includes/libs/lessc.inc.php',
'profile_point' => __DIR__ . '/profileinfo.php',
);
);

4
includes/parser/Parser.php
View file

@ -534,12 +534,12 @@ class Parser {
// Add on template profiling data
$dataByFunc = $this->mProfiler->getFunctionStats();
uasort( $dataByFunc, function( $a, $b ) {
return $a['elapsed'] < $b['elapsed']; // descending order
return $a['real'] < $b['real']; // descending order
} );
$profileReport = "Top template expansion time report (%,ms,calls,template)\n";
foreach ( array_slice( $dataByFunc, 0, 10 ) as $item ) {
$profileReport .= sprintf( "%6.2f%% %3.6f %6d - %s\n",
$item['percent'], $item['elapsed'], $item['calls'],
$item['%real'], $item['real'], $item['calls'],
htmlspecialchars($item['name'] ) );
}
$text .= "\n<!-- \n$profileReport-->\n";

148
includes/profiler/Profiler.php
View file

@ -33,6 +33,8 @@ abstract class Profiler {
protected $profileID = false;
/** @var bool Whether MediaWiki is in a SkinTemplate output context */
protected $templated = false;
/** @var array All of the params passed from $wgProfiler */
protected $params = array();
/** @var TransactionProfiler */
protected $trxProfiler;
@ -49,6 +51,7 @@ abstract class Profiler {
if ( isset( $params['profileID'] ) ) {
$this->profileID = $params['profileID'];
}
$this->params = $params;
$this->trxProfiler = new TransactionProfiler();
}
@ -127,8 +130,45 @@ abstract class Profiler {
/**
* Log the data to some store or even the page output
*
* @since 1.25
*/
abstract public function logData();
public function logData() {
$output = isset( $this->params['output'] ) ?
$this->params['output'] : null;
if ( !$output || $this->isStub() ) {
// return early when no output classes defined or we're a stub
return;
}
if ( !is_array( $output ) ) {
$output = array( $output );
}
foreach ( $output as $outType ) {
$class = 'ProfilerOutput' . ucfirst( strtolower( $outType ) );
$profileOut = new $class( $this, $this->params );
if ( $profileOut->canUse() ) {
$profileOut->log();
}
}
}
/**
* Get the content type sent out to the client.
* Used for profilers that output instead of store data.
* @return string
* @since 1.25
*/
public function getContentType() {
foreach ( headers_list() as $header ) {
if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {
return $m[1];
}
}
return null;
}
/**
* Mark this call as templated or not
@ -139,81 +179,45 @@ abstract class Profiler {
$this->templated = $t;
}
/**
* Was this call as templated or not
*
* @return bool
*/
public function getTemplated() {
return $this->templated;
}
/**
* Get the aggregated inclusive profiling data for each method
*
* The percent time for each time is based on the current "total" time
* used is based on all methods so far. This method can therefore be
* called several times in between several profiling calls without the
* delays in usage of the profiler skewing the results. A "-total" entry
* is always included in the results.
*
* When a call chain involves a method invoked within itself, any
* entries for the cyclic invocation should be be demarked with "@".
* This makes filtering them out easier and follows the xhprof style.
*
* @return array List of method entries arrays, each having:
* - name : method name
* - calls : the number of invoking calls
* - real : real time ellapsed (ms)
* - %real : percent real time
* - cpu : CPU time ellapsed (ms)
* - %cpu : percent CPU time
* - memory : memory used (bytes)
* - %memory : percent memory used
* @since 1.25
*/
abstract public function getFunctionStats();
/**
* Returns a profiling output to be stored in debug file
*
* @return string
*/
abstract public function getOutput();
/**
* Get data for the debugging toolbar.
*
* @return array
*/
abstract public function getRawData();
/**
* Get the initial time of the request, based either on $wgRequestTime or
* $wgRUstart. Will return null if not able to find data.
*
* @param string|bool $metric Metric to use, with the following possibilities:
* - user: User CPU time (without system calls)
* - cpu: Total CPU time (user and system calls)
* - wall (or any other string): elapsed time
* - false (default): will fall back to default metric
* @return float|null
*/
protected function getTime( $metric = 'wall' ) {
if ( $metric === 'cpu' || $metric === 'user' ) {
$ru = wfGetRusage();
if ( !$ru ) {
return 0;
}
$time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
if ( $metric === 'cpu' ) {
# This is the time of system calls, added to the user time
# it gives the total CPU time
$time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
}
return $time;
} else {
return microtime( true );
}
}
/**
* Get the initial time of the request, based either on $wgRequestTime or
* $wgRUstart. Will return null if not able to find data.
*
* @param string|bool $metric Metric to use, with the following possibilities:
* - user: User CPU time (without system calls)
* - cpu: Total CPU time (user and system calls)
* - wall (or any other string): elapsed time
* - false (default): will fall back to default metric
* @return float|null
*/
protected function getInitialTime( $metric = 'wall' ) {
global $wgRequestTime, $wgRUstart;
if ( $metric === 'cpu' || $metric === 'user' ) {
if ( !count( $wgRUstart ) ) {
return null;
}
$time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
if ( $metric === 'cpu' ) {
# This is the time of system calls, added to the user time
# it gives the total CPU time
$time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
}
return $time;
} else {
if ( empty( $wgRequestTime ) ) {
return null;
} else {
return $wgRequestTime;
}
}
}
}

114
includes/profiler/ProfilerStandard.php
View file

@ -236,13 +236,6 @@ class ProfilerStandard extends Profiler {
}
}
/**
* Log the data to some store or even the page output
*/
public function logData() {
/* Implement in subclasses */
}
/**
* Returns a profiling output to be stored in debug file
*
@ -330,6 +323,17 @@ class ProfilerStandard extends Profiler {
trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
}
/**
* Return the collated data, collating first if need be
* @return array
*/
public function getCollatedData() {
if ( !$this->collateDone ) {
$this->collateData();
}
return $this->collated;
}
/**
* Populate collated
*/
@ -439,10 +443,7 @@ class ProfilerStandard extends Profiler {
return $prof;
}
/**
* @return array
*/
public function getRawData() {
public function getFunctionStats() {
// This method is called before shutdown in the footer method on Skins.
// If some outer methods have not yet called wfProfileOut(), work around
// that by clearing anything in the work stack to just the "-total" entry.
@ -463,28 +464,29 @@ class ProfilerStandard extends Profiler {
$this->collateDone = false;
}
$total = isset( $this->collated['-total'] )
$totalCpu = isset( $this->collated['-total'] )
? $this->collated['-total']['cpu']
: 0;
$totalReal = isset( $this->collated['-total'] )
? $this->collated['-total']['real']
: 0;
$totalMem = isset( $this->collated['-total'] )
? $this->collated['-total']['memory']
: 0;
$profile = array();
foreach ( $this->collated as $fname => $data ) {
$periods = array();
foreach ( $data['periods'] as $period ) {
$period['start'] *= 1000;
$period['end'] *= 1000;
$periods[] = $period;
}
$profile[] = array(
'name' => $fname,
'calls' => $data['count'],
'elapsed' => $data['real'] * 1000,
'percent' => $total ? 100 * $data['real'] / $total : 0,
'real' => $data['real'] * 1000,
'%real' => $totalReal ? 100 * $data['real'] / $totalReal : 0,
'cpu' => $data['cpu'] * 1000,
'%cpu' => $totalCpu ? 100 * $data['cpu'] / $totalCpu : 0,
'memory' => $data['memory'],
'%memory' => $totalMem ? 100 * $data['memory'] / $totalMem : 0,
'min' => $data['min_real'] * 1000,
'max' => $data['max_real'] * 1000,
'overhead' => $data['overhead'],
'periods' => $periods
'max' => $data['max_real'] * 1000
);
}
@ -522,17 +524,67 @@ class ProfilerStandard extends Profiler {
}
/**
* Get the content type sent out to the client.
* Used for profilers that output instead of store data.
* @return string
* Get the initial time of the request, based either on $wgRequestTime or
* $wgRUstart. Will return null if not able to find data.
*
* @param string|bool $metric Metric to use, with the following possibilities:
* - user: User CPU time (without system calls)
* - cpu: Total CPU time (user and system calls)
* - wall (or any other string): elapsed time
* - false (default): will fall back to default metric
* @return float|null
*/
protected function getContentType() {
foreach ( headers_list() as $header ) {
if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {
return $m[1];
protected function getTime( $metric = 'wall' ) {
if ( $metric === 'cpu' || $metric === 'user' ) {
$ru = wfGetRusage();
if ( !$ru ) {
return 0;
}
$time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
if ( $metric === 'cpu' ) {
# This is the time of system calls, added to the user time
# it gives the total CPU time
$time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
}
return $time;
} else {
return microtime( true );
}
}
/**
* Get the initial time of the request, based either on $wgRequestTime or
* $wgRUstart. Will return null if not able to find data.
*
* @param string|bool $metric Metric to use, with the following possibilities:
* - user: User CPU time (without system calls)
* - cpu: Total CPU time (user and system calls)
* - wall (or any other string): elapsed time
* - false (default): will fall back to default metric
* @return float|null
*/
protected function getInitialTime( $metric = 'wall' ) {
global $wgRequestTime, $wgRUstart;
if ( $metric === 'cpu' || $metric === 'user' ) {
if ( !count( $wgRUstart ) ) {
return null;
}
$time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
if ( $metric === 'cpu' ) {
# This is the time of system calls, added to the user time
# it gives the total CPU time
$time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
}
return $time;
} else {
if ( empty( $wgRequestTime ) ) {
return null;
} else {
return $wgRequestTime;
}
}
return null;
}
/**

10
includes/profiler/ProfilerStub.php
View file

@ -37,20 +37,16 @@ class ProfilerStub extends Profiler {
public function profileOut( $fn ) {
}
public function getFunctionStats() {
}
public function getOutput() {
}
public function close() {
}
public function logData() {
}
public function getCurrentSection() {
return '';
}
public function getRawData() {
return array();
}
}

267
includes/profiler/ProfilerXhprof.php
View file

@ -22,32 +22,20 @@
/**
* Profiler wrapper for XHProf extension.
*
* Mimics the output of ProfilerSimpleText, ProfilerSimpleUDP or
* ProfilerSimpleTrace but using data collected via the XHProf PHP extension.
* This Profiler also produces data compatable with the debugging toolbar.
* Mimics the output of ProfilerStandard using data collected via the XHProf
* PHP extension.
*
* To mimic ProfilerSimpleText results:
* @code
* $wgProfiler['class'] = 'ProfilerXhprof';
* $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
* $wgProfiler['log'] = 'text';
* $wgProfiler['output'] = 'text';
* $wgProfiler['visible'] = true;
* @endcode
*
* To mimic ProfilerSimpleUDP results:
* @code
* $wgProfiler['class'] = 'ProfilerXhprof';
* $wgProfiler['flags'] = XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY | XHPROF_FLAGS_NO_BUILTINS;
* $wgProfiler['log'] = 'udpprofile';
* @endcode
*
* Similar to ProfilerSimpleTrace results, report the most expensive path
* through the application:
* @code
* $wgProfiler['class'] = 'ProfilerXhprof';
* $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
* $wgProfiler['log'] = 'critpath';
* $wgProfiler['visible'] = true;
* $wgProfiler['output'] = 'udp';
* @endcode
*
* Rather than obeying wfProfileIn() and wfProfileOut() calls placed in the
@ -58,19 +46,12 @@
* To restrict the functions for which profiling data is collected, you can
* use either a whitelist ($wgProfiler['include']) or a blacklist
* ($wgProfiler['exclude']) containing an array of function names. The
* blacklist funcitonality is built into HHVM and will completely exclude the
* blacklist functionality is built into HHVM and will completely exclude the
* named functions from profiling collection. The whitelist is implemented by
* Xhprof class and will filter the data collected by XHProf before reporting.
* Xhprof class which will filter the data collected by XHProf before reporting.
* See documentation for the Xhprof class and the XHProf extension for
* additional information.
*
* Data reported to debug toolbar via getRawData() can be restricted by
* setting $wgProfiler['toolbarCutoff'] to a minumum cumulative wall clock
* percentage. Functions in the call graph which contribute less than this
* percentage to the total wall clock time measured will be excluded from the
* data sent to debug toolbar. The default cutoff is 0.1 (1/1000th of the
* total time measured).
*
* @author Bryan Davis <bd808@wikimedia.org>
* @copyright © 2014 Bryan Davis and Wikimedia Foundation.
* @ingroup Profiler
@ -97,13 +78,6 @@ class ProfilerXhprof extends Profiler {
*/
protected $visible;
/**
* Minimum wall time precentage for a fucntion to be reported to the debug
* toolbar via getRawData().
* @var float $toolbarCutoff
*/
protected $toolbarCutoff;
/**
* @param array $params
* @see Xhprof::__construct()
@ -112,8 +86,7 @@ class ProfilerXhprof extends Profiler {
$params = array_merge(
array(
'log' => 'text',
'visible' => false,
'toolbarCutoff' => 0.1,
'visible' => false
),
$params
);
@ -163,193 +136,29 @@ class ProfilerXhprof extends Profiler {
public function close() {
}
/**
* Get data for the debugging toolbar.
*
* @return array
* @see https://www.mediawiki.org/wiki/Debugging_toolbar
*/
public function getRawData() {
public function getFunctionStats() {
$metrics = $this->xhprof->getCompleteMetrics();
$endEpoch = $this->getTime();
$profile = array();
foreach ( $metrics as $fname => $stats ) {
if ( $stats['wt']['percent'] < $this->toolbarCutoff ) {
// Ignore functions which are not significant contributors
// to the total elapsed time.
continue;
}
$record = array(
// Convert elapsed times from μs to ms to match ProfilerStandard
$profile[] = array(
'name' => $fname,
'calls' => $stats['ct'],
'elapsed' => $stats['wt']['total'] / 1000,
'percent' => $stats['wt']['percent'],
'real' => $stats['wt']['total'] / 1000,
'%real' => $stats['wt']['percent'],
'cpu' => isset( $stats['cpu'] ) ? $stats['cpu']['total'] / 1000 : 0,
'%cpu' => isset( $stats['cpu'] ) ? $stats['cpu']['percent'] : 0,
'memory' => isset( $stats['mu'] ) ? $stats['mu']['total'] : 0,
'%memory' => isset( $stats['mu'] ) ? $stats['mu']['percent'] : 0,
'min' => $stats['wt']['min'] / 1000,
'max' => $stats['wt']['max'] / 1000,
'overhead' => array_reduce(
$stats['subcalls'],
function( $carry, $item ) {
return $carry + $item['ct'];
},
0
),
'periods' => array(),
'max' => $stats['wt']['max'] / 1000
);
// We are making up periods based on the call segments we have.
// What we don't have is the start time for each call (which
// actually may be a collection of multiple calls from the
// caller). We will pretend that all the calls happen sequentially
// and finish at the end of the end of the request.
foreach ( $stats['calls'] as $call ) {
$avgElapsed = $call['wt'] / 1000 / $call['ct'];
$avgMem = isset( $call['mu'] ) ? $call['mu'] / $call['ct'] : 0;
$start = $endEpoch - $avgElapsed;
for ( $i = 0; $i < $call['ct']; $i++ ) {
$callStart = $start + ( $avgElapsed * $i );
$record['periods'][] = array(
'start' => $callStart,
'end' => $callStart + $avgElapsed,
'memory' => $avgMem,
'subcalls' => 0,
);
}
}
$profile[] = $record;
}
return $profile;
}
/**
* Log the data to some store or even the page output.
*/
public function logData() {
if ( $this->logType === 'text' ) {
$this->logText();
} elseif ( $this->logType === 'udpprofile' ) {
$this->logToUdpprofile();
} elseif ( $this->logType === 'critpath' ){
$this->logCriticalPath();
} else {
wfLogWarning(
"Unknown ProfilerXhprof log type '{$this->logType}'"
);
}
}
/**
* Write a brief profile report to stdout.
*/
protected function logText() {
if ( $this->templated ) {
$ct = $this->getContentType();
if ( $ct === 'text/html' && $this->visible ) {
$prefix = '<pre>';
$suffix = '</pre>';
} elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) {
$prefix = "\n/*";
$suffix = "*/\n";
} else {
$prefix = "<!--";
$suffix = "-->\n";
}
print $this->getSummaryReport( $prefix, $suffix );
}
}
/**
* Send collected information to a udpprofile daemon.
*
* @see http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile
* @see $wgUDPProfilerHost
* @see $wgUDPProfilerPort
* @see $wgUDPProfilerFormatString
*/
protected function logToUdpprofile() {
global $wgUDPProfilerHost, $wgUDPProfilerPort;
global $wgUDPProfilerFormatString;
if ( !function_exists( 'socket_create' ) ) {
return;
}
$metrics = $this->xhprof->getInclusiveMetrics();
$sock = socket_create( AF_INET, SOCK_DGRAM, SOL_UDP );
$buffer = '';
$bufferSize = 0;
foreach ( $metrics as $func => $data ) {
if ( strpos( $func, '@' ) !== false ) {
continue; // ignore cyclic re-entries to functions
}
$line = sprintf( $wgUDPProfilerFormatString,
$this->getProfileID(),
$data['ct'],
isset( $data['cpu'] ) ? $data['cpu']['total'] : 0,
isset( $data['cpu'] ) ? $data['cpu']['variance'] : 0,
$data['wt']['total'] / 1000,
$data['wt']['variance'],
$func,
isset( $data['mu'] ) ? $data['mu']['total'] : 0
);
$lineLength = strlen( $line );
if ( $lineLength + $bufferSize > 1400 ) {
// Line would exceed max packet size, send packet before
// appending to buffer.
socket_sendto( $sock, $buffer, $bufferSize, 0,
$wgUDPProfilerHost, $wgUDPProfilerPort
);
$buffer = '';
$bufferSize = 0;
}
$buffer .= $line;
$bufferSize += $lineLength;
}
// Send final buffer
socket_sendto( $sock, $buffer, $bufferSize, 0x100 /* EOF */,
$wgUDPProfilerHost, $wgUDPProfilerPort
);
}
/**
* Write a critical path report to stdout.
*/
protected function logCriticalPath() {
if ( $this->templated ) {
$ct = $this->getContentType();
if ( $ct === 'text/html' && $this->visible ) {
$prefix = '<pre>Critical path:';
$suffix = '</pre>';
} elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) {
$prefix = "\n/* Critical path:";
$suffix = "*/\n";
} else {
$prefix = "<!-- Critical path:";
$suffix = "-->\n";
}
print $this->getCriticalPathReport( $prefix, $suffix );
}
}
/**
* Get the content type of the current request.
* @return string
*/
protected function getContentType() {
foreach ( headers_list() as $header ) {
if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {
return $m[1];
}
}
return 'application/octet-stream';
}
/**
* Returns a profiling output to be stored in debug file
*
@ -432,46 +241,4 @@ class ProfilerXhprof extends Profiler {
$out[] = $footer;
return implode( "\n", $out );
}
/**
* Get a brief report of the most costly code path by wall clock time.
*
* Each line of the report includes this data:
* - Total wall clock time spent in function in seconds
* - Function name
*
* @param string $header Header text to prepend to report
* @param string $footer Footer text to append to report
* @return string
*/
protected function getCriticalPathReport( $header = '', $footer = '' ) {
$data = $this->xhprof->getCriticalPath();
$out = array( $header );
$out[] = sprintf( "%7s %9s %9s %6s %4s",
'Time%', 'Time', 'Mem', 'Calls', 'Name'
);
$format = '%6.2f%% %9.6f %9d %6d %s%s';
$total = null;
$nest = 0;
foreach ( $data as $key => $stats ) {
list( $parent, $child ) = Xhprof::splitKey( $key );
if ( $total === null ) {
$total = $stats;
}
$out[] = sprintf( $format,
100 * $stats['wt'] / $total['wt'],
$stats['wt'] / 1e6,
isset( $stats['mu'] ) ? $stats['mu'] : 0,
$stats['ct'],
//$nest ? str_repeat( ' ', $nest - 1 ) . '┗ ' : '',
$nest ? str_repeat( ' ', $nest - 1 ) . '└─' : '',
$child
);
$nest++;
}
$out[] = $footer;
return implode( "\n", $out );
}
}

34
includes/profiler/SectionProfiler.php
View file

@ -61,7 +61,7 @@ class SectionProfiler {
}
/**
* Get the raw and collated breakdown data for each method
* Get the aggregated inclusive profiling data for each method
*
* The percent time for each time is based on the current "total" time
* used is based on all methods so far. This method can therefore be
@ -70,37 +70,41 @@ class SectionProfiler {
* is always included in the results.
*
* @return array List of method entries arrays, each having:
* - name : method name
* - calls : the number of method calls
* - elapsed : real time ellapsed (ms)
* - percent : percent real time
* - memory : memory used (bytes)
* - min : min real time of all calls (ms)
* - max : max real time of all calls (ms)
* - name : method name
* - calls : the number of invoking calls
* - real : real time ellapsed (ms)
* - %real : percent real time
* - cpu : real time ellapsed (ms)
* - %cpu : percent real time
* - memory : memory used (bytes)
* - %memory : percent memory used
*/
public function getFunctionStats() {
$data = $this->profiler->getRawData();
$data = $this->profiler->getFunctionStats();
$cpuTotal = 0;
$memoryTotal = 0;
$elapsedTotal = 0;
foreach ( $data as $item ) {
$memoryTotal += $item['memory'];
$elapsedTotal += $item['elapsed'];
$elapsedTotal += $item['real'];
$cpuTotal += $item['cpu'];
}
foreach ( $data as &$item ) {
$item['percent'] = $item['elapsed'] / $elapsedTotal * 100;
$item['%cpu'] = $item['cpu'] ? $item['cpu'] / $cpuTotal * 100 : 0;
$item['%real'] = $elapsedTotal ? $item['real'] / $elapsedTotal * 100 : 0;
$item['%memory'] = $item['memory'] ? $item['memory'] / $memoryTotal * 100 : 0;
}
unset( $item );
$data[] = array(
'name' => '-total',
'calls' => 1,
'elapsed' => $elapsedTotal,
'percent' => 100,
'real' => $elapsedTotal,
'%real' => 100,
'memory' => $memoryTotal,
'min' => $elapsedTotal,
'max' => $elapsedTotal
'%memory' => 100,
);
return $data;

64
includes/profiler/output/ProfilerOutput.php Normal file
View file

@ -0,0 +1,64 @@
<?php
/**
* This program is free software; you can redistribute it and/or modify
* it under the terms of the GNU General Public License as published by
* the Free Software Foundation; either version 2 of the License, or
* (at your option) any later version.
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License along
* with this program; if not, write to the Free Software Foundation, Inc.,
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
* http://www.gnu.org/copyleft/gpl.html
*
* @file
* @ingroup Profiler
*/
/**
* Base class for profiling output
*
* Since 1.25
*/
abstract class ProfilerOutput {
/** @var Profiler */
protected $collector;
/** @var array Configuration of $wgProfiler */
protected $params = array();
/**
* Constructor
* @param Profiler $collector The actual profiler
* @param array $params Configuration array, passed down from $wgProfiler
*/
public function __construct( Profiler $collector, array $params ) {
$this->collector = $collector;
$this->params = $params;
}
/**
* Can this output type be used?
* @return bool
*/
public function canUse() {
return true;
}
/**
* Delegate to the proper method
*/
public function log() {
$this->logStandardData( $this->collector->getFunctionStats() );
}
/**
* Log MediaWiki-style profiling data
*
* @param array $stats Result of Profiler::getFunctionStats()
*/
abstract protected function logStandardData( array $stats );
}

29
includes/profiler/ProfilerSimpleDB.php → includes/profiler/output/ProfilerOutputDb.php
View file

@ -22,21 +22,21 @@
*/
/**
* Logs profiling data into the local DB
*
* $wgProfiler['class'] = 'ProfilerSimpleDB';
*
* @ingroup Profiler
* @since 1.25
*/
class ProfilerSimpleDB extends ProfilerStandard {
/**
* Log the whole profiling data into the database.
*/
public function logData() {
global $wgProfilePerHost;
class ProfilerOutputDb extends ProfilerOutput {
public function canUse() {
# Do not log anything if database is readonly (bug 5375)
if ( wfReadOnly() ) {
return;
}
return !wfReadOnly();
}
protected function logStandardData( array $stats ) {
global $wgProfilePerHost;
if ( $wgProfilePerHost ) {
$pfhost = wfHostname();
@ -45,16 +45,15 @@ class ProfilerSimpleDB extends ProfilerStandard {
}
try {
$this->collateData();
$dbw = wfGetDB( DB_MASTER );
$useTrx = ( $dbw->getType() === 'sqlite' ); // much faster
if ( $useTrx ) {
$dbw->startAtomic( __METHOD__ );
}
foreach ( $this->collated as $name => $data ) {
$eventCount = $data['count'];
$timeSum = (float)( $data['real'] * 1000 );
foreach ( $stats as $data ) {
$name = $data['name'];
$eventCount = $data['calls'];
$timeSum = (float)$data['real'];
$memorySum = (float)$data['memory'];
$name = substr( $name, 0, 255 );

51
includes/profiler/ProfilerSimpleText.php → includes/profiler/output/ProfilerOutputText.php
View file

@ -30,43 +30,46 @@
* $wgProfiler['visible'] = true;
*
* @ingroup Profiler
* @since 1.25
*/
class ProfilerSimpleText extends ProfilerStandard {
public $visible = false; /* Show as <PRE> or <!-- ? */
class ProfilerOutputText extends ProfilerOutput {
/** @var float Min real time display threshold */
protected $thresholdMs;
public function __construct( $profileConfig ) {
if ( isset( $profileConfig['visible'] ) && $profileConfig['visible'] ) {
$this->visible = true;
}
parent::__construct( $profileConfig );
function __construct( Profiler $collector, array $params ) {
parent::__construct( $collector, $params );
$this->thresholdMs = isset( $params['thresholdMs'] )
? $params['thresholdMs']
: .25;
}
protected function logStandardData( array $stats ) {
if ( $this->collector->getTemplated() ) {
$out = '';
public function logData() {
$out = '';
if ( $this->templated ) {
$this->close();
$totalReal = isset( $this->collated['-total'] )
? $this->collated['-total']['real']
: 0; // profiling mismatch error?
uasort( $this->collated, function( $a, $b ) {
// sort descending by time elapsed
// Filter out really tiny entries
$min = $this->thresholdMs;
$stats = array_filter( $stats, function( $a ) use ( $min ) {
return $a['real'] > $min;
} );
// Sort descending by time elapsed
usort( $stats, function( $a, $b ) {
return $a['real'] < $b['real'];
} );
array_walk( $this->collated,
function( $item, $key ) use ( &$out, $totalReal ) {
$perc = $totalReal ? $item['real'] / $totalReal * 100 : 0;
$out .= sprintf( "%6.2f%% %3.6f %6d - %s\n",
$perc, $item['real'], $item['count'], $key );
array_walk( $stats,
function ( $item ) use ( &$out ) {
$out .= sprintf( "%6.2f%% %3.3f %6d - %s\n",
$item['%real'], $item['real'], $item['calls'], $item['name'] );
}
);
$contentType = $this->getContentType();
$contentType = $this->collector->getContentType();
if ( PHP_SAPI === 'cli' ) {
print "<!--\n{$out}\n-->\n";
} elseif ( $contentType === 'text/html' ) {
if ( $this->visible ) {
$visible = isset( $this->params['visible'] ) ?
$this->params['visible'] : false;
if ( $visible ) {
print "<pre>{$out}</pre>";
} else {
print "<!--\n{$out}\n-->\n";

44
includes/profiler/ProfilerSimpleUDP.php → includes/profiler/output/ProfilerOutputUdp.php
View file

@ -23,37 +23,35 @@
/**
* ProfilerSimpleUDP class, that sends out messages for 'udpprofile' daemon
* (the one from
* http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile)
* (see http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile)
*
* @ingroup Profiler
* @since 1.25
*/
class ProfilerSimpleUDP extends ProfilerStandard {
public function logData() {
class ProfilerOutputUdp extends ProfilerOutput {
public function canUse() {
# Sockets are not enabled
return function_exists( 'socket_create' );
}
protected function logStandardData( array $stats ) {
global $wgUDPProfilerHost, $wgUDPProfilerPort, $wgUDPProfilerFormatString;
$this->close();
if ( !function_exists( 'socket_create' ) ) {
# Sockets are not enabled
return;
}
$sock = socket_create( AF_INET, SOCK_DGRAM, SOL_UDP );
$plength = 0;
$packet = "";
foreach ( $this->collated as $entry => $pfdata ) {
if ( !isset( $pfdata['count'] )
|| !isset( $pfdata['cpu'] )
|| !isset( $pfdata['cpu_sq'] )
|| !isset( $pfdata['real'] )
|| !isset( $pfdata['real_sq'] ) ) {
continue;
}
$pfline = sprintf( $wgUDPProfilerFormatString, $this->getProfileID(), $pfdata['count'],
$pfdata['cpu'], $pfdata['cpu_sq'], $pfdata['real'], $pfdata['real_sq'], $entry,
$pfdata['memory'] );
foreach ( $stats as $pfdata ) {
$pfline = sprintf( $wgUDPProfilerFormatString,
$this->collector->getProfileID(),
$pfdata['calls'],
$pfdata['cpu'] / 1000, // ms => sec
0.0, // sum of CPU^2 for each invocation (unused)
$pfdata['real'] / 1000, // ms => sec
0.0, // sum of real^2 for each invocation (unused)
$pfdata['name'],
$pfdata['memory']
);
$length = strlen( $pfline );
/* printf("<!-- $pfline -->"); */
if ( $length + $plength > 1400 ) {
socket_sendto( $sock, $packet, $plength, 0, $wgUDPProfilerHost, $wgUDPProfilerPort );
$packet = "";

11
maintenance/Maintenance.php
View file

@ -446,7 +446,6 @@ abstract class Maintenance {
$this->addOption( 'server', "The protocol and server name to use in URLs, e.g. " .
"http://en.wikipedia.org. This is sometimes necessary because " .
"server name detection may fail in command line scripts.", false, true );
$this->addOption( 'profiler', 'Set to "text" or "trace" to show profiling output', false, true );
# Save generic options to display them separately in help
$this->mGenericParameters = $this->mParams;
@ -930,16 +929,6 @@ abstract class Maintenance {
// @codingStandardsIgnoreStart
$this->adjustMemoryLimit();
// Per-script profiling; useful for debugging
$forcedProfiler = $this->getOption( 'profiler' );
if ( $forcedProfiler === 'text' ) {
Profiler::setInstance( new ProfilerSimpleText( array() ) );
Profiler::instance()->setTemplated( true );
} elseif ( $forcedProfiler === 'trace' ) {
Profiler::setInstance( new ProfilerSimpleTrace( array() ) );
Profiler::instance()->setTemplated( true );
}
}
/**

2
profileinfo.php
View file

@ -384,7 +384,7 @@ if ( isset( $_REQUEST['filter'] ) ) {
$last = false;
foreach ( $res as $o ) {
$next = new profile_point( $o->pf_name, $o->pf_count, $o->pf_time, $o->pf_memory );
if ( $next->name() == '-total' ) {
if ( $next->name() == '-total' || $next->name() == 'main()' ) {
profile_point::$totaltime = $next->time();
profile_point::$totalcount = $next->count();
profile_point::$totalmemory = $next->memory();