jenkins-bot has submitted this change and it was merged.
Change subject: Refactor profiling output from profiling
......................................................................
Refactor profiling output from profiling
* 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 <asch...@wikimedia.org>
Change-Id: I266ed82031a434465f64896eb327f3872fdf1db1
---
M RELEASE-NOTES-1.25
M StartProfiler.sample
M autoload.php
M includes/parser/Parser.php
M includes/profiler/Profiler.php
D includes/profiler/ProfilerSimpleText.php
M includes/profiler/ProfilerStandard.php
M includes/profiler/ProfilerStub.php
M includes/profiler/ProfilerXhprof.php
M includes/profiler/SectionProfiler.php
A includes/profiler/output/ProfilerOutput.php
R includes/profiler/output/ProfilerOutputDb.php
A includes/profiler/output/ProfilerOutputText.php
R includes/profiler/output/ProfilerOutputUdp.php
M maintenance/Maintenance.php
M profileinfo.php
16 files changed, 408 insertions(+), 526 deletions(-)
Approvals:
BryanDavis: Looks good to me, approved
Legoktm: Looks good to me, but someone else must approve
jenkins-bot: Verified
diff --git a/RELEASE-NOTES-1.25 b/RELEASE-NOTES-1.25
index ea5e8b8..3531cac 100644
--- a/RELEASE-NOTES-1.25
+++ b/RELEASE-NOTES-1.25
@@ -19,6 +19,8 @@
* (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
diff --git a/StartProfiler.sample b/StartProfiler.sample
index d9b5288..b72d5d5 100644
--- a/StartProfiler.sample
+++ b/StartProfiler.sample
@@ -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
*/
diff --git a/autoload.php b/autoload.php
index 488f9dd..bc039e9 100644
--- a/autoload.php
+++ b/autoload.php
@@ -880,10 +880,11 @@
'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 @@
'lessc_formatter_lessjs' => __DIR__ . '/includes/libs/lessc.inc.php',
'lessc_parser' => __DIR__ . '/includes/libs/lessc.inc.php',
'profile_point' => __DIR__ . '/profileinfo.php',
-);
+);
\ No newline at end of file
diff --git a/includes/parser/Parser.php b/includes/parser/Parser.php
index d310836..14aad1a 100644
--- a/includes/parser/Parser.php
+++ b/includes/parser/Parser.php
@@ -534,12 +534,12 @@
// 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";
diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php
index 078b66b..12e999b 100644
--- a/includes/profiler/Profiler.php
+++ b/includes/profiler/Profiler.php
@@ -33,6 +33,8 @@
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 @@
if ( isset( $params['profileID'] ) ) {
$this->profileID = $params['profileID'];
}
+ $this->params = $params;
$this->trxProfiler = new TransactionProfiler();
}
@@ -127,8 +130,45 @@
/**
* 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
@@ -140,80 +180,44 @@
}
/**
+ * 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;
- }
- }
- }
}
diff --git a/includes/profiler/ProfilerSimpleText.php
b/includes/profiler/ProfilerSimpleText.php
deleted file mode 100644
index 264845e..0000000
--- a/includes/profiler/ProfilerSimpleText.php
+++ /dev/null
@@ -1,81 +0,0 @@
-<?php
-/**
- * Profiler showing output in page source.
- *
- * 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
- */
-
-/**
- * The least sophisticated profiler output class possible, view your source! :)
- *
- * Put the following 2 lines in StartProfiler.php:
- *
- * $wgProfiler['class'] = 'ProfilerSimpleText';
- * $wgProfiler['visible'] = true;
- *
- * @ingroup Profiler
- */
-class ProfilerSimpleText extends ProfilerStandard {
- public $visible = false; /* Show as <PRE> or <!-- ? */
-
- public function __construct( $profileConfig ) {
- if ( isset( $profileConfig['visible'] ) &&
$profileConfig['visible'] ) {
- $this->visible = true;
- }
- parent::__construct( $profileConfig );
- }
-
- 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
- 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 );
- }
- );
-
- $contentType = $this->getContentType();
- if ( PHP_SAPI === 'cli' ) {
- print "<!--\n{$out}\n-->\n";
- } elseif ( $contentType === 'text/html' ) {
- if ( $this->visible ) {
- print "<pre>{$out}</pre>";
- } else {
- print "<!--\n{$out}\n-->\n";
- }
- } elseif ( $contentType === 'text/javascript' ) {
- print "\n/*\n${$out}*/\n";
- } elseif ( $contentType === 'text/css' ) {
- print "\n/*\n{$out}*/\n";
- }
- }
- }
-}
diff --git a/includes/profiler/ProfilerStandard.php
b/includes/profiler/ProfilerStandard.php
index b873806..15c5cdd 100644
--- a/includes/profiler/ProfilerStandard.php
+++ b/includes/profiler/ProfilerStandard.php
@@ -237,13 +237,6 @@
}
/**
- * 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
*
* @return string
@@ -328,6 +321,17 @@
# which has been fixed in recent releases.
return sprintf( "%10s %s %s\n",
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;
}
/**
@@ -439,10 +443,7 @@
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 @@
$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 @@
}
/**
- * 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;
}
/**
diff --git a/includes/profiler/ProfilerStub.php
b/includes/profiler/ProfilerStub.php
index 43e2193..510a0a0 100644
--- a/includes/profiler/ProfilerStub.php
+++ b/includes/profiler/ProfilerStub.php
@@ -37,20 +37,16 @@
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();
}
}
diff --git a/includes/profiler/ProfilerXhprof.php
b/includes/profiler/ProfilerXhprof.php
index 5e70aa9..9379379 100644
--- a/includes/profiler/ProfilerXhprof.php
+++ b/includes/profiler/ProfilerXhprof.php
@@ -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,18 +46,11 @@
* 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 <bd...@wikimedia.org>
* @copyright © 2014 Bryan Davis and Wikimedia Foundation.
@@ -98,13 +79,6 @@
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 @@
$params = array_merge(
array(
'log' => 'text',
- 'visible' => false,
- 'toolbarCutoff' => 0.1,
+ 'visible' => false
),
$params
);
@@ -163,191 +136,27 @@
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';
}
/**
@@ -428,48 +237,6 @@
$stats['ct'],
$func
);
- }
- $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 );
diff --git a/includes/profiler/SectionProfiler.php
b/includes/profiler/SectionProfiler.php
index a418d30..2d8a689 100644
--- a/includes/profiler/SectionProfiler.php
+++ b/includes/profiler/SectionProfiler.php
@@ -61,7 +61,7 @@
}
/**
- * 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 @@
* 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;
diff --git a/includes/profiler/output/ProfilerOutput.php
b/includes/profiler/output/ProfilerOutput.php
new file mode 100644
index 0000000..e8e0085
--- /dev/null
+++ b/includes/profiler/output/ProfilerOutput.php
@@ -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 );
+}
diff --git a/includes/profiler/ProfilerSimpleDB.php
b/includes/profiler/output/ProfilerOutputDb.php
similarity index 86%
rename from includes/profiler/ProfilerSimpleDB.php
rename to includes/profiler/output/ProfilerOutputDb.php
index 911b926..3c2912e 100644
--- a/includes/profiler/ProfilerSimpleDB.php
+++ b/includes/profiler/output/ProfilerOutputDb.php
@@ -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 @@
}
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 );
diff --git a/includes/profiler/output/ProfilerOutputText.php
b/includes/profiler/output/ProfilerOutputText.php
new file mode 100644
index 0000000..1fa7495
--- /dev/null
+++ b/includes/profiler/output/ProfilerOutputText.php
@@ -0,0 +1,84 @@
+<?php
+/**
+ * Profiler showing output in page source.
+ *
+ * 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
+ */
+
+/**
+ * The least sophisticated profiler output class possible, view your source! :)
+ *
+ * Put the following 2 lines in StartProfiler.php:
+ *
+ * $wgProfiler['class'] = 'ProfilerSimpleText';
+ * $wgProfiler['visible'] = true;
+ *
+ * @ingroup Profiler
+ * @since 1.25
+ */
+class ProfilerOutputText extends ProfilerOutput {
+ /** @var float Min real time display threshold */
+ protected $thresholdMs;
+
+ 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 = '';
+
+ // 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( $stats,
+ function ( $item ) use ( &$out ) {
+ $out .= sprintf( "%6.2f%% %3.3f %6d -
%s\n",
+ $item['%real'], $item['real'],
$item['calls'], $item['name'] );
+ }
+ );
+
+ $contentType = $this->collector->getContentType();
+ if ( PHP_SAPI === 'cli' ) {
+ print "<!--\n{$out}\n-->\n";
+ } elseif ( $contentType === 'text/html' ) {
+ $visible = isset( $this->params['visible'] ) ?
+ $this->params['visible'] : false;
+ if ( $visible ) {
+ print "<pre>{$out}</pre>";
+ } else {
+ print "<!--\n{$out}\n-->\n";
+ }
+ } elseif ( $contentType === 'text/javascript' ) {
+ print "\n/*\n${$out}*/\n";
+ } elseif ( $contentType === 'text/css' ) {
+ print "\n/*\n{$out}*/\n";
+ }
+ }
+ }
+}
diff --git a/includes/profiler/ProfilerSimpleUDP.php
b/includes/profiler/output/ProfilerOutputUdp.php
similarity index 65%
rename from includes/profiler/ProfilerSimpleUDP.php
rename to includes/profiler/output/ProfilerOutputUdp.php
index ad16a18..c16ece2 100644
--- a/includes/profiler/ProfilerSimpleUDP.php
+++ b/includes/profiler/output/ProfilerOutputUdp.php
@@ -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 = "";
diff --git a/maintenance/Maintenance.php b/maintenance/Maintenance.php
index d740f56..3f8f6e8 100644
--- a/maintenance/Maintenance.php
+++ b/maintenance/Maintenance.php
@@ -446,7 +446,6 @@
$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 @@
// @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 );
- }
}
/**
diff --git a/profileinfo.php b/profileinfo.php
index 762af69..b930f42 100644
--- a/profileinfo.php
+++ b/profileinfo.php
@@ -384,7 +384,7 @@
$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();
--
To view, visit https://gerrit.wikimedia.org/r/173348
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: merged
Gerrit-Change-Id: I266ed82031a434465f64896eb327f3872fdf1db1
Gerrit-PatchSet: 8
Gerrit-Project: mediawiki/core
Gerrit-Branch: master
Gerrit-Owner: Chad <ch...@wikimedia.org>
Gerrit-Reviewer: Aaron Schulz <asch...@wikimedia.org>
Gerrit-Reviewer: BryanDavis <bda...@wikimedia.org>
Gerrit-Reviewer: Chad <ch...@wikimedia.org>
Gerrit-Reviewer: Legoktm <legoktm.wikipe...@gmail.com>
Gerrit-Reviewer: Parent5446 <tylerro...@gmail.com>
Gerrit-Reviewer: jenkins-bot <>
_______________________________________________
MediaWiki-commits mailing list
MediaWiki-commits@lists.wikimedia.org
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
