From b8d93fb4fd0661c4994e6895b5e654516ba1c965 Mon Sep 17 00:00:00 2001 From: Chad Horohoe Date: Fri, 14 Nov 2014 10:58:07 -0800 Subject: [PATCH] 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 Change-Id: I266ed82031a434465f64896eb327f3872fdf1db1 --- RELEASE-NOTES-1.25 | 2 + StartProfiler.sample | 31 +- autoload.php | 9 +- includes/parser/Parser.php | 4 +- includes/profiler/Profiler.php | 136 ++++----- includes/profiler/ProfilerStandard.php | 114 ++++++-- includes/profiler/ProfilerStub.php | 10 +- includes/profiler/ProfilerXhprof.php | 267 ++---------------- includes/profiler/SectionProfiler.php | 34 ++- includes/profiler/output/ProfilerOutput.php | 64 +++++ .../ProfilerOutputDb.php} | 29 +- .../ProfilerOutputText.php} | 51 ++-- .../ProfilerOutputUdp.php} | 44 ++- maintenance/Maintenance.php | 11 - profileinfo.php | 2 +- 15 files changed, 345 insertions(+), 463 deletions(-) create mode 100644 includes/profiler/output/ProfilerOutput.php rename includes/profiler/{ProfilerSimpleDB.php => output/ProfilerOutputDb.php} (87%) rename includes/profiler/{ProfilerSimpleText.php => output/ProfilerOutputText.php} (59%) rename includes/profiler/{ProfilerSimpleUDP.php => output/ProfilerOutputUdp.php} (65%) diff --git a/RELEASE-NOTES-1.25 b/RELEASE-NOTES-1.25 index ea5e8b8e7c..3531cac1a6 100644 --- a/RELEASE-NOTES-1.25 +++ b/RELEASE-NOTES-1.25 @@ -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 diff --git a/StartProfiler.sample b/StartProfiler.sample index d9b5288411..b72d5d59ff 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 488f9ddf9a..bc039e9bfe 100644 --- a/autoload.php +++ b/autoload.php @@ -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', -); +); \ No newline at end of file diff --git a/includes/parser/Parser.php b/includes/parser/Parser.php index d310836498..14aad1a6e9 100644 --- a/includes/parser/Parser.php +++ b/includes/parser/Parser.php @@ -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"; diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index 078b66bdc2..12e999b8da 100644 --- a/includes/profiler/Profiler.php +++ b/includes/profiler/Profiler.php @@ -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 @@ -140,80 +180,44 @@ abstract class Profiler { } /** - * Returns a profiling output to be stored in debug file + * Was this call as templated or not * - * @return string + * @return bool */ - abstract public function getOutput(); + public function getTemplated() { + return $this->templated; + } /** - * Get data for the debugging toolbar. + * Get the aggregated inclusive profiling data for each method * - * @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. + * 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. * - * @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 + * 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 */ - 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 ); - } - } + abstract public function getFunctionStats(); /** - * Get the initial time of the request, based either on $wgRequestTime or - * $wgRUstart. Will return null if not able to find data. + * Returns a profiling output to be stored in debug file * - * @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 + * @return string */ - 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; - } - } - } + abstract public function getOutput(); } diff --git a/includes/profiler/ProfilerStandard.php b/includes/profiler/ProfilerStandard.php index b873806ab8..15c5cdd04b 100644 --- a/includes/profiler/ProfilerStandard.php +++ b/includes/profiler/ProfilerStandard.php @@ -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; } /** diff --git a/includes/profiler/ProfilerStub.php b/includes/profiler/ProfilerStub.php index 43e219387f..510a0a0d95 100644 --- a/includes/profiler/ProfilerStub.php +++ b/includes/profiler/ProfilerStub.php @@ -37,20 +37,16 @@ class ProfilerStub extends Profiler { public function profileOut( $fn ) { } - public function getOutput() { + public function getFunctionStats() { } - public function close() { + public function getOutput() { } - public function logData() { + public function close() { } public function getCurrentSection() { return ''; } - - public function getRawData() { - return array(); - } } diff --git a/includes/profiler/ProfilerXhprof.php b/includes/profiler/ProfilerXhprof.php index 5e70aa9e81..93793790dd 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,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 * @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,191 +136,27 @@ 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(), - ); - - // 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 = '
';
-				$suffix = '
'; - } elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) { - $prefix = "\n/*"; - $suffix = "*/\n"; - } else { - $prefix = "\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 + 'max' => $stats['wt']['max'] / 1000 ); - $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 = '
Critical path:';
-				$suffix = '
'; - } elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) { - $prefix = "\n/* Critical path:"; - $suffix = "*/\n"; - } else { - $prefix = "\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'; + return $profile; } /** @@ -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 ); - } } diff --git a/includes/profiler/SectionProfiler.php b/includes/profiler/SectionProfiler.php index a418d308c3..2d8a6892a8 100644 --- a/includes/profiler/SectionProfiler.php +++ b/includes/profiler/SectionProfiler.php @@ -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; diff --git a/includes/profiler/output/ProfilerOutput.php b/includes/profiler/output/ProfilerOutput.php new file mode 100644 index 0000000000..e8e0085155 --- /dev/null +++ b/includes/profiler/output/ProfilerOutput.php @@ -0,0 +1,64 @@ +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 87% rename from includes/profiler/ProfilerSimpleDB.php rename to includes/profiler/output/ProfilerOutputDb.php index 911b926a7a..3c2912eef4 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 @@ 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 ); diff --git a/includes/profiler/ProfilerSimpleText.php b/includes/profiler/output/ProfilerOutputText.php similarity index 59% rename from includes/profiler/ProfilerSimpleText.php rename to includes/profiler/output/ProfilerOutputText.php index 264845e291..1fa74952ee 100644 --- a/includes/profiler/ProfilerSimpleText.php +++ b/includes/profiler/output/ProfilerOutputText.php @@ -30,43 +30,46 @@ * $wgProfiler['visible'] = true; * * @ingroup Profiler + * @since 1.25 */ -class ProfilerSimpleText extends ProfilerStandard { - public $visible = false; /* Show as 
 or \n";
 			} elseif ( $contentType === 'text/html' ) {
-				if ( $this->visible ) {
+				$visible = isset( $this->params['visible'] ) ?
+					$this->params['visible'] : false;
+				if ( $visible ) {
 					print "
{$out}
";
 				} else {
 					print "\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 ad16a18ed8..c16ece2d11 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() {
-		global $wgUDPProfilerHost, $wgUDPProfilerPort, $wgUDPProfilerFormatString;
-
-		$this->close();
+class ProfilerOutputUdp extends ProfilerOutput {
+	public function canUse() {
+		# Sockets are not enabled
+		return function_exists( 'socket_create' );
+	}
 
-		if ( !function_exists( 'socket_create' ) ) {
-			# Sockets are not enabled
-			return;
-		}
+	protected function logStandardData( array $stats ) {
+		global $wgUDPProfilerHost, $wgUDPProfilerPort, $wgUDPProfilerFormatString;
 
 		$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(""); */
 			if ( $length + $plength > 1400 ) {
 				socket_sendto( $sock, $packet, $plength, 0, $wgUDPProfilerHost, $wgUDPProfilerPort );
 				$packet = "";
diff --git a/maintenance/Maintenance.php b/maintenance/Maintenance.php
index d740f56bbf..3f8f6e8a32 100644
--- a/maintenance/Maintenance.php
+++ b/maintenance/Maintenance.php
@@ -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 );
-		}
 	}
 
 	/**
diff --git a/profileinfo.php b/profileinfo.php
index 762af69ccb..b930f42fcf 100644
--- a/profileinfo.php
+++ b/profileinfo.php
@@ -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();
-- 
2.20.1