diff options
Diffstat (limited to 'includes/profiler')
19 files changed, 1743 insertions, 1464 deletions
diff --git a/includes/profiler/ProfileSection.php b/includes/profiler/ProfileSection.php new file mode 100644 index 00000000..68ef6680 --- /dev/null +++ b/includes/profiler/ProfileSection.php @@ -0,0 +1,43 @@ +<?php +/** + * Function scope profiling assistant + * + * 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 + */ + +/** + * Class for handling function-scope profiling + * + * @since 1.22 + * @deprecated 1.25 No-op now + */ +class ProfileSection { + /** + * Begin profiling of a function and return an object that ends profiling + * of the function when that object leaves scope. As long as the object is + * not specifically linked to other objects, it will fall out of scope at + * the same moment that the function to be profiled terminates. + * + * This is typically called like: + * <code>$section = new ProfileSection( __METHOD__ );</code> + * + * @param string $name Name of the function to profile + */ + public function __construct( $name ) {} +} diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index 418b5d48..dbf80fa1 100644 --- a/includes/profiler/Profiler.php +++ b/includes/profiler/Profiler.php @@ -1,6 +1,6 @@ <?php /** - * Base class and functions for profiling. + * Base class for profiling. * * 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 @@ -23,113 +23,33 @@ */ /** - * Get system resource usage of current request context. - * Invokes the getrusage(2) system call, requesting RUSAGE_SELF if on PHP5 - * or RUSAGE_THREAD if on HHVM. Returns false if getrusage is not available. - * - * @since 1.24 - * @return array|bool Resource usage data or false if no data available. - */ -function wfGetRusage() { - if ( !function_exists( 'getrusage' ) ) { - return false; - } elseif ( defined ( 'HHVM_VERSION' ) ) { - return getrusage( 2 /* RUSAGE_THREAD */ ); - } else { - return getrusage( 0 /* RUSAGE_SELF */ ); - } -} - -/** - * Begin profiling of a function - * @param string $functionname Name of the function we will profile - */ -function wfProfileIn( $functionname ) { - if ( Profiler::$__instance === null ) { // use this directly to reduce overhead - Profiler::instance(); - } - if ( !( Profiler::$__instance instanceof ProfilerStub ) ) { - Profiler::$__instance->profileIn( $functionname ); - } -} - -/** - * Stop profiling of a function - * @param string $functionname Name of the function we have profiled - */ -function wfProfileOut( $functionname = 'missing' ) { - if ( Profiler::$__instance === null ) { // use this directly to reduce overhead - Profiler::instance(); - } - if ( !( Profiler::$__instance instanceof ProfilerStub ) ) { - Profiler::$__instance->profileOut( $functionname ); - } -} - -/** - * Class for handling function-scope profiling - * - * @since 1.22 - */ -class ProfileSection { - protected $name; // string; method name - protected $enabled = false; // boolean; whether profiling is enabled - - /** - * Begin profiling of a function and return an object that ends profiling of - * the function when that object leaves scope. As long as the object is not - * specifically linked to other objects, it will fall out of scope at the same - * moment that the function to be profiled terminates. - * - * This is typically called like: - * <code>$section = new ProfileSection( __METHOD__ );</code> - * - * @param string $name Name of the function to profile - */ - public function __construct( $name ) { - $this->name = $name; - if ( Profiler::$__instance === null ) { // use this directly to reduce overhead - Profiler::instance(); - } - if ( !( Profiler::$__instance instanceof ProfilerStub ) ) { - $this->enabled = true; - Profiler::$__instance->profileIn( $this->name ); - } - } - - function __destruct() { - if ( $this->enabled ) { - Profiler::$__instance->profileOut( $this->name ); - } - } -} - -/** - * Profiler base class that defines the interface and some trivial functionality + * Profiler base class that defines the interface and some trivial + * functionality * * @ingroup Profiler */ abstract class Profiler { /** @var string|bool Profiler ID for bucketing data */ - protected $mProfileID = false; + protected $profileID = false; /** @var bool Whether MediaWiki is in a SkinTemplate output context */ - protected $mTemplated = false; - + protected $templated = false; + /** @var array All of the params passed from $wgProfiler */ + protected $params = array(); + /** @var IContextSource Current request context */ + protected $context = null; /** @var TransactionProfiler */ protected $trxProfiler; - - // @codingStandardsIgnoreStart PSR2.Classes.PropertyDeclaration.Underscore - /** @var Profiler Do not call this outside Profiler and ProfileSection */ - public static $__instance = null; - // @codingStandardsIgnoreEnd + /** @var Profiler */ + private static $instance = null; /** * @param array $params */ public function __construct( array $params ) { if ( isset( $params['profileID'] ) ) { - $this->mProfileID = $params['profileID']; + $this->profileID = $params['profileID']; } + $this->params = $params; $this->trxProfiler = new TransactionProfiler(); } @@ -138,332 +58,243 @@ abstract class Profiler { * @return Profiler */ final public static function instance() { - if ( self::$__instance === null ) { - global $wgProfiler; + if ( self::$instance === null ) { + global $wgProfiler, $wgProfileLimit; + + $params = array( + 'class' => 'ProfilerStub', + 'sampling' => 1, + 'threshold' => $wgProfileLimit, + 'output' => array(), + ); if ( is_array( $wgProfiler ) ) { - if ( !isset( $wgProfiler['class'] ) ) { - $class = 'ProfilerStub'; - } elseif ( $wgProfiler['class'] === 'Profiler' ) { - $class = 'ProfilerStub'; // b/c; don't explode - } else { - $class = $wgProfiler['class']; - } - self::$__instance = new $class( $wgProfiler ); - } elseif ( $wgProfiler instanceof Profiler ) { - self::$__instance = $wgProfiler; // back-compat - } else { - self::$__instance = new ProfilerStub( array() ); + $params = array_merge( $params, $wgProfiler ); } - } - return self::$__instance; - } - /** - * Set the profiler to a specific profiler instance. Mostly for dumpHTML - * @param Profiler $p - */ - final public static function setInstance( Profiler $p ) { - self::$__instance = $p; - } + $inSample = mt_rand( 0, $params['sampling'] - 1 ) === 0; + if ( PHP_SAPI === 'cli' || !$inSample ) { + $params['class'] = 'ProfilerStub'; + } - /** - * Return whether this a stub profiler - * - * @return bool - */ - abstract public function isStub(); + if ( !is_array( $params['output'] ) ) { + $params['output'] = array( $params['output'] ); + } + + self::$instance = new $params['class']( $params ); + } + return self::$instance; + } /** - * Return whether this profiler stores data - * - * Called by Parser::braceSubstitution. If true, the parser will not - * generate per-title profiling sections, to avoid overloading the - * profiling data collector. + * Replace the current profiler with $profiler if no non-stub profiler is set * - * @see Profiler::logData() - * @return bool + * @param Profiler $profiler + * @throws MWException + * @since 1.25 */ - abstract public function isPersistent(); + final public static function replaceStubInstance( Profiler $profiler ) { + if ( self::$instance && !( self::$instance instanceof ProfilerStub ) ) { + throw new MWException( 'Could not replace non-stub profiler instance.' ); + } else { + self::$instance = $profiler; + } + } /** * @param string $id */ public function setProfileID( $id ) { - $this->mProfileID = $id; + $this->profileID = $id; } /** * @return string */ public function getProfileID() { - if ( $this->mProfileID === false ) { + if ( $this->profileID === false ) { return wfWikiID(); } else { - return $this->mProfileID; + return $this->profileID; } } /** - * Called by wfProfieIn() - * - * @param string $functionname - */ - abstract public function profileIn( $functionname ); - - /** - * Called by wfProfieOut() - * - * @param string $functionname - */ - abstract public function profileOut( $functionname ); - - /** - * Mark a DB as in a transaction with one or more writes pending + * Sets the context for this Profiler * - * Note that there can be multiple connections to a single DB. - * - * @param string $server DB server - * @param string $db DB name - * @param string $id Resource ID string of connection + * @param IContextSource $context + * @since 1.25 */ - public function transactionWritingIn( $server, $db, $id = '' ) { - $this->trxProfiler->transactionWritingIn( $server, $db, $id ); + public function setContext( $context ) { + $this->context = $context; } /** - * Mark a DB as no longer in a transaction - * - * This will check if locks are possibly held for longer than - * needed and log any affected transactions to a special DB log. - * Note that there can be multiple connections to a single DB. + * Gets the context for this Profiler * - * @param string $server DB server - * @param string $db DB name - * @param string $id Resource ID string of connection + * @return IContextSource + * @since 1.25 */ - public function transactionWritingOut( $server, $db, $id = '' ) { - $this->trxProfiler->transactionWritingOut( $server, $db, $id ); + public function getContext() { + if ( $this->context ) { + return $this->context; + } else { + wfDebug( __METHOD__ . " called and \$context is null. " . + "Return RequestContext::getMain(); for sanity\n" ); + return RequestContext::getMain(); + } } - /** - * Close opened profiling sections - */ - abstract public function close(); + // Kept BC for now, remove when possible + public function profileIn( $functionname ) {} + public function profileOut( $functionname ) {} /** - * Log the data to some store or even the page output + * Mark the start of a custom profiling frame (e.g. DB queries). + * The frame ends when the result of this method falls out of scope. + * + * @param string $section + * @return ScopedCallback|null + * @since 1.25 */ - abstract public function logData(); + abstract public function scopedProfileIn( $section ); /** - * Mark this call as templated or not - * - * @param bool $t + * @param ScopedCallback $section */ - public function setTemplated( $t ) { - $this->mTemplated = $t; + public function scopedProfileOut( ScopedCallback &$section = null ) { + $section = null; } /** - * Returns a profiling output to be stored in debug file - * - * @return string + * @return TransactionProfiler + * @since 1.25 */ - abstract public function getOutput(); + public function getTransactionProfiler() { + return $this->trxProfiler; + } /** - * @return array + * Close opened profiling sections */ - abstract public function getRawData(); + abstract public function close(); /** - * Get the initial time of the request, based either on $wgRequestTime or - * $wgRUstart. Will return null if not able to find data. + * Get all usable outputs. * - * @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 + * @throws MWException + * @return array Array of ProfilerOutput instances. + * @since 1.25 */ - protected function getTime( $metric = 'wall' ) { - if ( $metric === 'cpu' || $metric === 'user' ) { - $ru = wfGetRusage(); - if ( !$ru ) { - return 0; + private function getOutputs() { + $outputs = array(); + foreach ( $this->params['output'] as $outputType ) { + // The class may be specified as either the full class name (for + // example, 'ProfilerOutputUdp') or (for backward compatibility) + // the trailing portion of the class name (for example, 'udp'). + $outputClass = strpos( $outputType, 'ProfilerOutput' ) === false + ? 'ProfilerOutput' . ucfirst( $outputType ) + : $outputType; + if ( !class_exists( $outputClass ) ) { + throw new MWException( "'$outputType' is an invalid output type" ); } - $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; + $outputInstance = new $outputClass( $this, $this->params ); + if ( $outputInstance->canUse() ) { + $outputs[] = $outputInstance; } - return $time; - } else { - return microtime( true ); } + return $outputs; } /** - * Get the initial time of the request, based either on $wgRequestTime or - * $wgRUstart. Will return null if not able to find data. + * Log the data to some store or even the page output * - * @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 + * @since 1.25 */ - protected function getInitialTime( $metric = 'wall' ) { - global $wgRequestTime, $wgRUstart; + public function logData() { + $request = $this->getContext()->getRequest(); - if ( $metric === 'cpu' || $metric === 'user' ) { - if ( !count( $wgRUstart ) ) { - return null; - } + $timeElapsed = $request->getElapsedTime(); + $timeElapsedThreshold = $this->params['threshold']; + if ( $timeElapsed <= $timeElapsedThreshold ) { + return; + } - $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; - } + $outputs = $this->getOutputs(); + if ( !$outputs ) { + return; + } + + $stats = $this->getFunctionStats(); + foreach ( $outputs as $output ) { + $output->log( $stats ); } } /** - * Add an entry in the debug log file - * - * @param string $s String to output + * Get the content type sent out to the client. + * Used for profilers that output instead of store data. + * @return string + * @since 1.25 */ - protected function debug( $s ) { - if ( function_exists( 'wfDebug' ) ) { - wfDebug( $s ); + public function getContentType() { + foreach ( headers_list() as $header ) { + if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) { + return $m[1]; + } } + return null; } /** - * Add an entry in the debug log group + * Mark this call as templated or not * - * @param string $group Group to send the message to - * @param string $s String to output + * @param bool $t */ - protected function debugGroup( $group, $s ) { - if ( function_exists( 'wfDebugLog' ) ) { - wfDebugLog( $group, $s ); - } + public function setTemplated( $t ) { + $this->templated = $t; } -} - -/** - * Helper class that detects high-contention DB queries via profiling calls - * - * This class is meant to work with a Profiler, as the later already knows - * when methods start and finish (which may take place during transactions). - * - * @since 1.24 - */ -class TransactionProfiler { - /** @var float Seconds */ - protected $mDBLockThreshold = 3.0; - /** @var array DB/server name => (active trx count, time, DBs involved) */ - protected $mDBTrxHoldingLocks = array(); - /** @var array DB/server name => list of (function name, elapsed time) */ - protected $mDBTrxMethodTimes = array(); /** - * Mark a DB as in a transaction with one or more writes pending - * - * Note that there can be multiple connections to a single DB. + * Was this call as templated or not * - * @param string $server DB server - * @param string $db DB name - * @param string $id ID string of transaction + * @return bool */ - public function transactionWritingIn( $server, $db, $id ) { - $name = "{$server} ({$db}) (TRX#$id)"; - if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) { - wfDebugLog( 'DBPerformance', "Nested transaction for '$name' - out of sync." ); - } - $this->mDBTrxHoldingLocks[$name] = - array( 'start' => microtime( true ), 'conns' => array() ); - $this->mDBTrxMethodTimes[$name] = array(); - - foreach ( $this->mDBTrxHoldingLocks as $name => &$info ) { - $info['conns'][$name] = 1; // track all DBs in transactions for this transaction - } + public function getTemplated() { + return $this->templated; } /** - * Register the name and time of a method for slow DB trx detection + * Get the aggregated inclusive profiling data for each method * - * This method is only to be called by the Profiler class as methods finish + * 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 $method Function name - * @param float $realtime Wal time ellapsed + * 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 + * - min_real : min real time in a call (ms) + * - max_real : max real time in a call (ms) + * @since 1.25 */ - public function recordFunctionCompletion( $method, $realtime ) { - if ( !$this->mDBTrxHoldingLocks ) { - return; // short-circuit - // @todo hardcoded check is a tad janky (what about FOR UPDATE?) - } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method ) - && $realtime < $this->mDBLockThreshold - ) { - return; // not a DB master query nor slow enough - } - $now = microtime( true ); - foreach ( $this->mDBTrxHoldingLocks as $name => $info ) { - // Hacky check to exclude entries from before the first TRX write - if ( ( $now - $realtime ) >= $info['start'] ) { - $this->mDBTrxMethodTimes[$name][] = array( $method, $realtime ); - } - } - } + abstract public function getFunctionStats(); /** - * Mark a DB as no longer in a transaction - * - * This will check if locks are possibly held for longer than - * needed and log any affected transactions to a special DB log. - * Note that there can be multiple connections to a single DB. + * Returns a profiling output to be stored in debug file * - * @param string $server DB server - * @param string $db DB name - * @param string $id ID string of transaction + * @return string */ - public function transactionWritingOut( $server, $db, $id ) { - $name = "{$server} ({$db}) (TRX#$id)"; - if ( !isset( $this->mDBTrxMethodTimes[$name] ) ) { - wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." ); - return; - } - $slow = false; - foreach ( $this->mDBTrxMethodTimes[$name] as $info ) { - $realtime = $info[1]; - if ( $realtime >= $this->mDBLockThreshold ) { - $slow = true; - break; - } - } - if ( $slow ) { - $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks[$name]['conns'] ) ); - $msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n"; - foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) { - list( $method, $realtime ) = $info; - $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method ); - } - wfDebugLog( 'DBPerformance', $msg ); - } - unset( $this->mDBTrxHoldingLocks[$name] ); - unset( $this->mDBTrxMethodTimes[$name] ); - } + abstract public function getOutput(); } diff --git a/includes/profiler/ProfilerFunctions.php b/includes/profiler/ProfilerFunctions.php new file mode 100644 index 00000000..4984e77d --- /dev/null +++ b/includes/profiler/ProfilerFunctions.php @@ -0,0 +1,56 @@ +<?php +/** + * Core profiling functions. Have to exist before basically anything. + * + * 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 + */ + +/** + * Get system resource usage of current request context. + * Invokes the getrusage(2) system call, requesting RUSAGE_SELF if on PHP5 + * or RUSAGE_THREAD if on HHVM. Returns false if getrusage is not available. + * + * @since 1.24 + * @return array|bool Resource usage data or false if no data available. + */ +function wfGetRusage() { + if ( !function_exists( 'getrusage' ) ) { + return false; + } elseif ( defined ( 'HHVM_VERSION' ) ) { + return getrusage( 2 /* RUSAGE_THREAD */ ); + } else { + return getrusage( 0 /* RUSAGE_SELF */ ); + } +} + +/** + * Begin profiling of a function + * @param string $functionname Name of the function we will profile + * @deprecated 1.25 + */ +function wfProfileIn( $functionname ) { +} + +/** + * Stop profiling of a function + * @param string $functionname Name of the function we have profiled + * @deprecated 1.25 + */ +function wfProfileOut( $functionname = 'missing' ) { +} diff --git a/includes/profiler/ProfilerMwprof.php b/includes/profiler/ProfilerMwprof.php deleted file mode 100644 index af3c7741..00000000 --- a/includes/profiler/ProfilerMwprof.php +++ /dev/null @@ -1,256 +0,0 @@ -<?php -/** - * Profiler class for Mwprof. - * - * 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 - */ - -/** - * Profiler class for Mwprof. - * - * Mwprof is a high-performance MediaWiki profiling data collector, designed to - * collect profiling data from multiple hosts running in tandem. This class - * serializes profiling samples into MessagePack arrays and sends them to an - * Mwprof instance via UDP. - * - * @see https://github.com/wikimedia/operations-software-mwprof - * @since 1.23 - */ -class ProfilerMwprof extends Profiler { - /** @var array Queue of open profile calls with start data */ - protected $mWorkStack = array(); - - /** @var array Map of (function name => aggregate data array) */ - protected $mCollated = array(); - /** @var array Cache of a standard broken collation entry */ - protected $mErrorEntry; - - // Message types - const TYPE_SINGLE = 1; - const TYPE_RUNNING = 2; - - public function isStub() { - return false; - } - - public function isPersistent() { - return true; - } - - /** - * Start a profiling section. - * - * Marks the beginning of the function or code-block that should be time - * and logged under some specific name. - * - * @param string $inName Section to start - */ - public function profileIn( $inName ) { - $this->mWorkStack[] = array( $inName, count( $this->mWorkStack ), - $this->getTime(), $this->getTime( 'cpu' ), 0 ); - } - - /** - * Close a profiling section. - * - * Marks the end of the function or code-block that should be timed and - * logged under some specific name. - * - * @param string $outName Section to close - */ - public function profileOut( $outName ) { - list( $inName, $inCount, $inWall, $inCpu ) = array_pop( $this->mWorkStack ); - - // Check for unbalanced profileIn / profileOut calls. - // Bad entries are logged but not sent. - if ( $inName !== $outName ) { - $this->debugGroup( 'ProfilerUnbalanced', json_encode( array( $inName, $outName ) ) ); - return; - } - - $elapsedCpu = $this->getTime( 'cpu' ) - $inCpu; - $elapsedWall = $this->getTime() - $inWall; - $this->updateRunningEntry( $outName, $elapsedCpu, $elapsedWall ); - $this->trxProfiler->recordFunctionCompletion( $outName, $elapsedWall ); - } - - /** - * Update an entry with timing data. - * - * @param string $name Section name - * @param float $elapsedCpu Elapsed CPU time - * @param float $elapsedWall Elapsed wall-clock time - */ - public function updateRunningEntry( $name, $elapsedCpu, $elapsedWall ) { - // If this is the first measurement for this entry, store plain values. - // Many profiled functions will only be called once per request. - if ( !isset( $this->mCollated[$name] ) ) { - $this->mCollated[$name] = array( - 'cpu' => $elapsedCpu, - 'wall' => $elapsedWall, - 'count' => 1, - ); - return; - } - - $entry = &$this->mCollated[$name]; - - // If it's the second measurement, convert the plain values to - // RunningStat instances, so we can push the incoming values on top. - if ( $entry['count'] === 1 ) { - $cpu = new RunningStat(); - $cpu->push( $entry['cpu'] ); - $entry['cpu'] = $cpu; - - $wall = new RunningStat(); - $wall->push( $entry['wall'] ); - $entry['wall'] = $wall; - } - - $entry['count']++; - $entry['cpu']->push( $elapsedCpu ); - $entry['wall']->push( $elapsedWall ); - } - - /** - * @return array - */ - public function getRawData() { - // 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. - if ( count( $this->mWorkStack ) > 1 ) { - $oldWorkStack = $this->mWorkStack; - $this->mWorkStack = array( $this->mWorkStack[0] ); // just the "-total" one - } else { - $oldWorkStack = null; - } - $this->close(); - // If this trick is used, then the old work stack is swapped back afterwards. - // This means that logData() will still make use of all the method data since - // the missing wfProfileOut() calls should be made by the time it is called. - if ( $oldWorkStack ) { - $this->mWorkStack = $oldWorkStack; - } - - $totalWall = 0.0; - $profile = array(); - foreach ( $this->mCollated as $fname => $data ) { - if ( $data['count'] == 1 ) { - $profile[] = array( - 'name' => $fname, - 'calls' => $data['count'], - 'elapsed' => $data['wall'] * 1000, - 'memory' => 0, // not supported - 'min' => $data['wall'] * 1000, - 'max' => $data['wall'] * 1000, - 'overhead' => 0, // not supported - 'periods' => array() // not supported - ); - $totalWall += $data['wall']; - } else { - $profile[] = array( - 'name' => $fname, - 'calls' => $data['count'], - 'elapsed' => $data['wall']->n * $data['wall']->getMean() * 1000, - 'memory' => 0, // not supported - 'min' => $data['wall']->min * 1000, - 'max' => $data['wall']->max * 1000, - 'overhead' => 0, // not supported - 'periods' => array() // not supported - ); - $totalWall += $data['wall']->n * $data['wall']->getMean(); - } - } - $totalWall = $totalWall * 1000; - - foreach ( $profile as &$item ) { - $item['percent'] = $totalWall ? 100 * $item['elapsed'] / $totalWall : 0; - } - - return $profile; - } - - /** - * Serialize profiling data and send to a profiling data aggregator. - * - * Individual entries are represented as arrays and then encoded using - * MessagePack, an efficient binary data-interchange format. Encoded - * entries are accumulated into a buffer and sent in batch via UDP to the - * profiling data aggregator. - */ - public function logData() { - global $wgUDPProfilerHost, $wgUDPProfilerPort; - - $this->close(); - - if ( !function_exists( 'socket_create' ) ) { - return; // avoid fatal - } - - $sock = socket_create( AF_INET, SOCK_DGRAM, SOL_UDP ); - socket_connect( $sock, $wgUDPProfilerHost, $wgUDPProfilerPort ); - $bufferLength = 0; - $buffer = ''; - foreach ( $this->mCollated as $name => $entry ) { - $count = $entry['count']; - $cpu = $entry['cpu']; - $wall = $entry['wall']; - - if ( $count === 1 ) { - $data = array( self::TYPE_SINGLE, $name, $cpu, $wall ); - } else { - $data = array( self::TYPE_RUNNING, $name, $count, - $cpu->m1, $cpu->m2, $cpu->min, $cpu->max, - $wall->m1, $wall->m2, $wall->min, $wall->max ); - } - - $encoded = MWMessagePack::pack( $data ); - $length = strlen( $encoded ); - - // If adding this entry would cause the size of the buffer to - // exceed the standard ethernet MTU size less the UDP header, - // send all pending data and reset the buffer. Otherwise, continue - // accumulating entries into the current buffer. - if ( $length + $bufferLength > 1450 ) { - socket_send( $sock, $buffer, $bufferLength, 0 ); - $buffer = ''; - $bufferLength = 0; - } - $buffer .= $encoded; - $bufferLength += $length; - } - if ( $bufferLength !== 0 ) { - socket_send( $sock, $buffer, $bufferLength, 0 ); - } - } - - /** - * Close opened profiling sections - */ - public function close() { - while ( count( $this->mWorkStack ) ) { - $this->profileOut( 'close' ); - } - } - - public function getOutput() { - return ''; // no report - } -} diff --git a/includes/profiler/ProfilerSectionOnly.php b/includes/profiler/ProfilerSectionOnly.php new file mode 100644 index 00000000..1f8d33b1 --- /dev/null +++ b/includes/profiler/ProfilerSectionOnly.php @@ -0,0 +1,104 @@ +<?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 + */ + +/** + * Profiler that only tracks explicit profiling sections + * + * @code + * $wgProfiler['class'] = 'ProfilerSectionOnly'; + * $wgProfiler['output'] = 'text'; + * $wgProfiler['visible'] = true; + * @endcode + * + * @author Aaron Schulz + * @ingroup Profiler + * @since 1.25 + */ +class ProfilerSectionOnly extends Profiler { + /** @var SectionProfiler */ + protected $sprofiler; + + public function __construct( array $params = array() ) { + parent::__construct( $params ); + $this->sprofiler = new SectionProfiler(); + } + + public function scopedProfileIn( $section ) { + return $this->sprofiler->scopedProfileIn( $section ); + } + + public function close() { + } + + public function getFunctionStats() { + return $this->sprofiler->getFunctionStats(); + } + + public function getOutput() { + return $this->getFunctionReport(); + } + + /** + * Get a report of profiled functions sorted by inclusive wall clock time + * in descending order. + * + * Each line of the report includes this data: + * - Function name + * - Number of times function was called + * - Total wall clock time spent in function in microseconds + * - Minimum wall clock time spent in function in microseconds + * - Average wall clock time spent in function in microseconds + * - Maximum wall clock time spent in function in microseconds + * - Percentage of total wall clock time spent in function + * - Total delta of memory usage from start to end of function in bytes + * + * @return string + */ + protected function getFunctionReport() { + $data = $this->getFunctionStats(); + usort( $data, function( $a, $b ) { + if ( $a['real'] === $b['real'] ) { + return 0; + } + return ( $a['real'] > $b['real'] ) ? -1 : 1; // descending + } ); + + $width = 140; + $nameWidth = $width - 65; + $format = "%-{$nameWidth}s %6d %9d %9d %9d %9d %7.3f%% %9d"; + $out = array(); + $out[] = sprintf( "%-{$nameWidth}s %6s %9s %9s %9s %9s %7s %9s", + 'Name', 'Calls', 'Total', 'Min', 'Each', 'Max', '%', 'Mem' + ); + foreach ( $data as $stats ) { + $out[] = sprintf( $format, + $stats['name'], + $stats['calls'], + $stats['real'] * 1000, + $stats['min_real'] * 1000, + $stats['real'] / $stats['calls'] * 1000, + $stats['max_real'] * 1000, + $stats['%real'], + $stats['memory'] + ); + } + return implode( "\n", $out ); + } +} diff --git a/includes/profiler/ProfilerSimpleText.php b/includes/profiler/ProfilerSimpleText.php deleted file mode 100644 index 0ee7aad2..00000000 --- a/includes/profiler/ProfilerSimpleText.php +++ /dev/null @@ -1,82 +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 <!-- ? */ - static private $out; - - public function __construct( $profileConfig ) { - if ( isset( $profileConfig['visible'] ) && $profileConfig['visible'] ) { - $this->visible = true; - } - parent::__construct( $profileConfig ); - } - - protected function collateOnly() { - return true; - } - - public function logData() { - if ( $this->mTemplated ) { - $this->close(); - $totalReal = isset( $this->mCollated['-total'] ) - ? $this->mCollated['-total']['real'] - : 0; // profiling mismatch error? - uasort( $this->mCollated, array( 'self', 'sort' ) ); - array_walk( $this->mCollated, array( 'self', 'format' ), $totalReal ); - if ( PHP_SAPI === 'cli' ) { - print "<!--\n" . self::$out . "\n-->\n"; - } elseif ( $this->getContentType() === 'text/html' ) { - if ( $this->visible ) { - print '<pre>' . self::$out . '</pre>'; - } else { - print "<!--\n" . self::$out . "\n-->\n"; - } - } elseif ( $this->getContentType() === 'text/javascript' ) { - print "\n/*\n" . self::$out . "*/\n"; - } elseif ( $this->getContentType() === 'text/css' ) { - print "\n/*\n" . self::$out . "*/\n"; - } - } - } - - static function sort( $a, $b ) { - return $a['real'] < $b['real']; /* sort descending by time elapsed */ - } - - static function format( $item, $key, $totalReal ) { - $perc = $totalReal ? $item['real'] / $totalReal * 100 : 0; - self::$out .= sprintf( "%6.2f%% %3.6f %6d - %s\n", - $perc, $item['real'], $item['count'], $key ); - } -} diff --git a/includes/profiler/ProfilerSimpleTrace.php b/includes/profiler/ProfilerSimpleTrace.php deleted file mode 100644 index 2a444948..00000000 --- a/includes/profiler/ProfilerSimpleTrace.php +++ /dev/null @@ -1,85 +0,0 @@ -<?php -/** - * Profiler showing execution trace. - * - * 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 - */ - -/** - * Execution trace profiler - * @todo document methods (?) - * @ingroup Profiler - */ -class ProfilerSimpleTrace extends ProfilerStandard { - protected $trace = "Beginning trace: \n"; - protected $memory = 0; - - protected function collateOnly() { - return true; - } - - public function profileIn( $functionname ) { - parent::profileIn( $functionname ); - - $this->trace .= " " . sprintf( "%6.1f", $this->memoryDiff() ) . - str_repeat( " ", count( $this->mWorkStack ) ) . " > " . $functionname . "\n"; - } - - public function profileOut( $functionname ) { - $item = end( $this->mWorkStack ); - - parent::profileOut( $functionname ); - - if ( !$item ) { - $this->trace .= "Profiling error: $functionname\n"; - } else { - list( $ofname, /* $ocount */, $ortime ) = $item; - if ( $functionname == 'close' ) { - $message = "Profile section ended by close(): {$ofname}"; - $functionname = $ofname; - $this->trace .= $message . "\n"; - } elseif ( $ofname != $functionname ) { - $this->trace .= "Profiling error: in({$ofname}), out($functionname)"; - } - $elapsedreal = $this->getTime() - $ortime; - $this->trace .= sprintf( "%03.6f %6.1f", $elapsedreal, $this->memoryDiff() ) . - str_repeat( " ", count( $this->mWorkStack ) + 1 ) . " < " . $functionname . "\n"; - } - } - - protected function memoryDiff() { - $diff = memory_get_usage() - $this->memory; - $this->memory = memory_get_usage(); - return $diff / 1024; - } - - public function logData() { - if ( $this->mTemplated ) { - if ( PHP_SAPI === 'cli' ) { - print "<!-- \n {$this->trace} \n -->"; - } elseif ( $this->getContentType() === 'text/html' ) { - print "<!-- \n {$this->trace} \n -->"; - } elseif ( $this->getContentType() === 'text/javascript' ) { - print "\n/*\n {$this->trace}\n*/"; - } elseif ( $this->getContentType() === 'text/css' ) { - print "\n/*\n {$this->trace}\n*/"; - } - } - } -} diff --git a/includes/profiler/ProfilerSimpleUDP.php b/includes/profiler/ProfilerSimpleUDP.php deleted file mode 100644 index 627b4de2..00000000 --- a/includes/profiler/ProfilerSimpleUDP.php +++ /dev/null @@ -1,75 +0,0 @@ -<?php -/** - * Profiler sending messages over UDP. - * - * 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 - */ - -/** - * ProfilerSimpleUDP class, that sends out messages for 'udpprofile' daemon - * (the one from - * http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile) - * @ingroup Profiler - */ -class ProfilerSimpleUDP extends ProfilerStandard { - protected function collateOnly() { - return true; - } - - public function isPersistent() { - return true; - } - - public function logData() { - 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->mCollated 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'] ); - $length = strlen( $pfline ); - /* printf("<!-- $pfline -->"); */ - if ( $length + $plength > 1400 ) { - socket_sendto( $sock, $packet, $plength, 0, $wgUDPProfilerHost, $wgUDPProfilerPort ); - $packet = ""; - $plength = 0; - } - $packet .= $pfline; - $plength += $length; - } - socket_sendto( $sock, $packet, $plength, 0x100, $wgUDPProfilerHost, $wgUDPProfilerPort ); - } -} diff --git a/includes/profiler/ProfilerStandard.php b/includes/profiler/ProfilerStandard.php deleted file mode 100644 index cc134165..00000000 --- a/includes/profiler/ProfilerStandard.php +++ /dev/null @@ -1,559 +0,0 @@ -<?php -/** - * Common implementation class for profiling. - * - * 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 - */ - -/** - * Standard profiler that tracks real time, cpu time, and memory deltas - * - * This supports profile reports, the debug toolbar, and high-contention - * DB query warnings. This does not persist the profiling data though. - * - * @ingroup Profiler - * @since 1.24 - */ -class ProfilerStandard extends Profiler { - /** @var array List of resolved profile calls with start/end data */ - protected $mStack = array(); - /** @var array Queue of open profile calls with start data */ - protected $mWorkStack = array(); - - /** @var array Map of (function name => aggregate data array) */ - protected $mCollated = array(); - /** @var bool */ - protected $mCollateDone = false; - /** @var bool */ - protected $mCollateOnly = false; - /** @var array Cache of a standard broken collation entry */ - protected $mErrorEntry; - - /** - * @param array $params - */ - public function __construct( array $params ) { - parent::__construct( $params ); - - $this->mCollateOnly = $this->collateOnly(); - - $this->addInitialStack(); - } - - /** - * Return whether this a stub profiler - * - * @return bool - */ - public function isStub() { - return false; - } - - /** - * Return whether this profiler stores data - * - * @see Profiler::logData() - * @return bool - */ - public function isPersistent() { - return false; - } - - /** - * Whether to internally just track aggregates and ignore the full stack trace - * - * Only doing collation saves memory overhead but limits the use of certain - * features like that of graph generation for the debug toolbar. - * - * @return bool - */ - protected function collateOnly() { - return false; - } - - /** - * Add the inital item in the stack. - */ - protected function addInitialStack() { - $this->mErrorEntry = $this->getErrorEntry(); - - $initialTime = $this->getInitialTime( 'wall' ); - $initialCpu = $this->getInitialTime( 'cpu' ); - if ( $initialTime !== null && $initialCpu !== null ) { - $this->mWorkStack[] = array( '-total', 0, $initialTime, $initialCpu, 0 ); - if ( $this->mCollateOnly ) { - $this->mWorkStack[] = array( '-setup', 1, $initialTime, $initialCpu, 0 ); - $this->profileOut( '-setup' ); - } else { - $this->mStack[] = array( '-setup', 1, $initialTime, $initialCpu, 0, - $this->getTime( 'wall' ), $this->getTime( 'cpu' ), 0 ); - } - } else { - $this->profileIn( '-total' ); - } - } - - /** - * @return array Initial collation entry - */ - protected function getZeroEntry() { - return array( - 'cpu' => 0.0, - 'cpu_sq' => 0.0, - 'real' => 0.0, - 'real_sq' => 0.0, - 'memory' => 0, - 'count' => 0, - 'min_cpu' => 0.0, - 'max_cpu' => 0.0, - 'min_real' => 0.0, - 'max_real' => 0.0, - 'periods' => array(), // not filled if mCollateOnly - 'overhead' => 0 // not filled if mCollateOnly - ); - } - - /** - * @return array Initial collation entry for errors - */ - protected function getErrorEntry() { - $entry = $this->getZeroEntry(); - $entry['count'] = 1; - return $entry; - } - - /** - * Update the collation entry for a given method name - * - * @param string $name - * @param float $elapsedCpu - * @param float $elapsedReal - * @param int $memChange - * @param int $subcalls - * @param array|null $period Map of ('start','end','memory','subcalls') - */ - protected function updateEntry( - $name, $elapsedCpu, $elapsedReal, $memChange, $subcalls = 0, $period = null - ) { - $entry =& $this->mCollated[$name]; - if ( !is_array( $entry ) ) { - $entry = $this->getZeroEntry(); - $this->mCollated[$name] =& $entry; - } - $entry['cpu'] += $elapsedCpu; - $entry['cpu_sq'] += $elapsedCpu * $elapsedCpu; - $entry['real'] += $elapsedReal; - $entry['real_sq'] += $elapsedReal * $elapsedReal; - $entry['memory'] += $memChange > 0 ? $memChange : 0; - $entry['count']++; - $entry['min_cpu'] = $elapsedCpu < $entry['min_cpu'] ? $elapsedCpu : $entry['min_cpu']; - $entry['max_cpu'] = $elapsedCpu > $entry['max_cpu'] ? $elapsedCpu : $entry['max_cpu']; - $entry['min_real'] = $elapsedReal < $entry['min_real'] ? $elapsedReal : $entry['min_real']; - $entry['max_real'] = $elapsedReal > $entry['max_real'] ? $elapsedReal : $entry['max_real']; - // Apply optional fields - $entry['overhead'] += $subcalls; - if ( $period ) { - $entry['periods'][] = $period; - } - } - - /** - * Called by wfProfieIn() - * - * @param string $functionname - */ - public function profileIn( $functionname ) { - global $wgDebugFunctionEntry; - - if ( $wgDebugFunctionEntry ) { - $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) . - 'Entering ' . $functionname . "\n" ); - } - - $this->mWorkStack[] = array( - $functionname, - count( $this->mWorkStack ), - $this->getTime( 'time' ), - $this->getTime( 'cpu' ), - memory_get_usage() - ); - } - - /** - * Called by wfProfieOut() - * - * @param string $functionname - */ - public function profileOut( $functionname ) { - global $wgDebugFunctionEntry; - - if ( $wgDebugFunctionEntry ) { - $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . - 'Exiting ' . $functionname . "\n" ); - } - - $item = array_pop( $this->mWorkStack ); - list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item; - - if ( $item === null ) { - $this->debugGroup( 'profileerror', "Profiling error: $functionname" ); - } else { - if ( $functionname === 'close' ) { - if ( $ofname !== '-total' ) { - $message = "Profile section ended by close(): {$ofname}"; - $this->debugGroup( 'profileerror', $message ); - if ( $this->mCollateOnly ) { - $this->mCollated[$message] = $this->mErrorEntry; - } else { - $this->mStack[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ); - } - } - $functionname = $ofname; - } elseif ( $ofname !== $functionname ) { - $message = "Profiling error: in({$ofname}), out($functionname)"; - $this->debugGroup( 'profileerror', $message ); - if ( $this->mCollateOnly ) { - $this->mCollated[$message] = $this->mErrorEntry; - } else { - $this->mStack[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ); - } - } - $realTime = $this->getTime( 'wall' ); - $cpuTime = $this->getTime( 'cpu' ); - if ( $this->mCollateOnly ) { - $elapsedcpu = $cpuTime - $octime; - $elapsedreal = $realTime - $ortime; - $memchange = memory_get_usage() - $omem; - $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange ); - } else { - $this->mStack[] = array_merge( $item, - array( $realTime, $cpuTime, memory_get_usage() ) ); - } - $this->trxProfiler->recordFunctionCompletion( $functionname, $realTime - $ortime ); - } - } - - /** - * Close opened profiling sections - */ - public function close() { - while ( count( $this->mWorkStack ) ) { - $this->profileOut( 'close' ); - } - } - - /** - * 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 - */ - public function getOutput() { - global $wgDebugFunctionEntry, $wgProfileCallTree; - - $wgDebugFunctionEntry = false; // hack - - if ( !count( $this->mStack ) && !count( $this->mCollated ) ) { - return "No profiling output\n"; - } - - if ( $wgProfileCallTree ) { - return $this->getCallTree(); - } else { - return $this->getFunctionReport(); - } - } - - /** - * Returns a tree of function call instead of a list of functions - * @return string - */ - protected function getCallTree() { - return implode( '', array_map( - array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) - ) ); - } - - /** - * Recursive function the format the current profiling array into a tree - * - * @param array $stack Profiling array - * @return array - */ - protected function remapCallTree( array $stack ) { - if ( count( $stack ) < 2 ) { - return $stack; - } - $outputs = array(); - for ( $max = count( $stack ) - 1; $max > 0; ) { - /* Find all items under this entry */ - $level = $stack[$max][1]; - $working = array(); - for ( $i = $max -1; $i >= 0; $i-- ) { - if ( $stack[$i][1] > $level ) { - $working[] = $stack[$i]; - } else { - break; - } - } - $working = $this->remapCallTree( array_reverse( $working ) ); - $output = array(); - foreach ( $working as $item ) { - array_push( $output, $item ); - } - array_unshift( $output, $stack[$max] ); - $max = $i; - - array_unshift( $outputs, $output ); - } - $final = array(); - foreach ( $outputs as $output ) { - foreach ( $output as $item ) { - $final[] = $item; - } - } - return $final; - } - - /** - * Callback to get a formatted line for the call tree - * @param array $entry - * @return string - */ - protected function getCallTreeLine( $entry ) { - list( $fname, $level, $startreal, , , $endreal ) = $entry; - $delta = $endreal - $startreal; - $space = str_repeat( ' ', $level ); - # The ugly double sprintf is to work around a PHP bug, - # which has been fixed in recent releases. - return sprintf( "%10s %s %s\n", - trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname ); - } - - /** - * Populate mCollated - */ - protected function collateData() { - if ( $this->mCollateDone ) { - return; - } - $this->mCollateDone = true; - $this->close(); // set "-total" entry - - if ( $this->mCollateOnly ) { - return; // already collated as methods exited - } - - $this->mCollated = array(); - - # Estimate profiling overhead - $profileCount = count( $this->mStack ); - self::calculateOverhead( $profileCount ); - - # First, subtract the overhead! - $overheadTotal = $overheadMemory = $overheadInternal = array(); - foreach ( $this->mStack as $entry ) { - // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1) - $fname = $entry[0]; - $elapsed = $entry[5] - $entry[2]; - $memchange = $entry[7] - $entry[4]; - - if ( $fname === '-overhead-total' ) { - $overheadTotal[] = $elapsed; - $overheadMemory[] = max( 0, $memchange ); - } elseif ( $fname === '-overhead-internal' ) { - $overheadInternal[] = $elapsed; - } - } - $overheadTotal = $overheadTotal ? - array_sum( $overheadTotal ) / count( $overheadInternal ) : 0; - $overheadMemory = $overheadMemory ? - array_sum( $overheadMemory ) / count( $overheadInternal ) : 0; - $overheadInternal = $overheadInternal ? - array_sum( $overheadInternal ) / count( $overheadInternal ) : 0; - - # Collate - foreach ( $this->mStack as $index => $entry ) { - // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1) - $fname = $entry[0]; - $elapsedCpu = $entry[6] - $entry[3]; - $elapsedReal = $entry[5] - $entry[2]; - $memchange = $entry[7] - $entry[4]; - $subcalls = $this->calltreeCount( $this->mStack, $index ); - - if ( substr( $fname, 0, 9 ) !== '-overhead' ) { - # Adjust for profiling overhead (except special values with elapsed=0 - if ( $elapsed ) { - $elapsed -= $overheadInternal; - $elapsed -= ( $subcalls * $overheadTotal ); - $memchange -= ( $subcalls * $overheadMemory ); - } - } - - $period = array( 'start' => $entry[2], 'end' => $entry[5], - 'memory' => $memchange, 'subcalls' => $subcalls ); - $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange, $subcalls, $period ); - } - - $this->mCollated['-overhead-total']['count'] = $profileCount; - arsort( $this->mCollated, SORT_NUMERIC ); - } - - /** - * Returns a list of profiled functions. - * - * @return string - */ - protected function getFunctionReport() { - $this->collateData(); - - $width = 140; - $nameWidth = $width - 65; - $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n"; - $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n"; - $prof = "\nProfiling data\n"; - $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' ); - - $total = isset( $this->mCollated['-total'] ) - ? $this->mCollated['-total']['real'] - : 0; - - foreach ( $this->mCollated as $fname => $data ) { - $calls = $data['count']; - $percent = $total ? 100 * $data['real'] / $total : 0; - $memory = $data['memory']; - $prof .= sprintf( $format, - substr( $fname, 0, $nameWidth ), - $calls, - (float)( $data['real'] * 1000 ), - (float)( $data['real'] * 1000 ) / $calls, - $percent, - $memory, - ( $data['min_real'] * 1000.0 ), - ( $data['max_real'] * 1000.0 ), - $data['overhead'] - ); - } - $prof .= "\nTotal: $total\n\n"; - - return $prof; - } - - /** - * @return array - */ - public function getRawData() { - // 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. - // Collate after doing this so the results do not include profile errors. - if ( count( $this->mWorkStack ) > 1 ) { - $oldWorkStack = $this->mWorkStack; - $this->mWorkStack = array( $this->mWorkStack[0] ); // just the "-total" one - } else { - $oldWorkStack = null; - } - $this->collateData(); - // If this trick is used, then the old work stack is swapped back afterwards - // and mCollateDone is reset to false. This means that logData() will still - // make use of all the method data since the missing wfProfileOut() calls - // should be made by the time it is called. - if ( $oldWorkStack ) { - $this->mWorkStack = $oldWorkStack; - $this->mCollateDone = false; - } - - $total = isset( $this->mCollated['-total'] ) - ? $this->mCollated['-total']['real'] - : 0; - - $profile = array(); - foreach ( $this->mCollated 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, - 'memory' => $data['memory'], - 'min' => $data['min_real'] * 1000, - 'max' => $data['max_real'] * 1000, - 'overhead' => $data['overhead'], - 'periods' => $periods - ); - } - - return $profile; - } - - /** - * Dummy calls to wfProfileIn/wfProfileOut to calculate its overhead - * @param int $profileCount - */ - protected static function calculateOverhead( $profileCount ) { - wfProfileIn( '-overhead-total' ); - for ( $i = 0; $i < $profileCount; $i++ ) { - wfProfileIn( '-overhead-internal' ); - wfProfileOut( '-overhead-internal' ); - } - wfProfileOut( '-overhead-total' ); - } - - /** - * Counts the number of profiled function calls sitting under - * the given point in the call graph. Not the most efficient algo. - * - * @param array $stack - * @param int $start - * @return int - */ - protected function calltreeCount( $stack, $start ) { - $level = $stack[$start][1]; - $count = 0; - for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) { - $count ++; - } - return $count; - } - - /** - * Get the content type sent out to the client. - * Used for profilers that output instead of store data. - * @return string - */ - protected function getContentType() { - foreach ( headers_list() as $header ) { - if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) { - return $m[1]; - } - } - return null; - } -} diff --git a/includes/profiler/ProfilerStub.php b/includes/profiler/ProfilerStub.php index 1d3b65d2..244b4e4b 100644 --- a/includes/profiler/ProfilerStub.php +++ b/includes/profiler/ProfilerStub.php @@ -27,18 +27,11 @@ * @ingroup Profiler */ class ProfilerStub extends Profiler { - public function isStub() { - return true; + public function scopedProfileIn( $section ) { + return null; // no-op } - public function isPersistent() { - return false; - } - - public function profileIn( $fn ) { - } - - public function profileOut( $fn ) { + public function getFunctionStats() { } public function getOutput() { @@ -47,20 +40,10 @@ class ProfilerStub extends Profiler { public function close() { } - public function logData() { - } - public function getCurrentSection() { return ''; } - public function transactionWritingIn( $server, $db, $id = '' ) { - } - - public function transactionWritingOut( $server, $db, $id = '' ) { - } - - public function getRawData() { - return array(); + public function logData() { } } diff --git a/includes/profiler/ProfilerXhprof.php b/includes/profiler/ProfilerXhprof.php new file mode 100644 index 00000000..f36cdc1a --- /dev/null +++ b/includes/profiler/ProfilerXhprof.php @@ -0,0 +1,194 @@ +<?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 + */ + +/** + * Profiler wrapper for XHProf extension. + * + * @code + * $wgProfiler['class'] = 'ProfilerXhprof'; + * $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS; + * $wgProfiler['output'] = 'text'; + * $wgProfiler['visible'] = true; + * @endcode + * + * @code + * $wgProfiler['class'] = 'ProfilerXhprof'; + * $wgProfiler['flags'] = XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY | XHPROF_FLAGS_NO_BUILTINS; + * $wgProfiler['output'] = 'udp'; + * @endcode + * + * ProfilerXhprof profiles all functions using the XHProf PHP extenstion. + * For PHP5 users, this extension can be installed via PECL or your operating + * system's package manager. XHProf support is built into HHVM. + * + * 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 functionality is built into HHVM and will completely exclude the + * named functions from profiling collection. The whitelist is implemented by + * 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. + * + * @author Bryan Davis <bd808@wikimedia.org> + * @copyright © 2014 Bryan Davis and Wikimedia Foundation. + * @ingroup Profiler + * @see Xhprof + * @see https://php.net/xhprof + * @see https://github.com/facebook/hhvm/blob/master/hphp/doc/profiling.md + */ +class ProfilerXhprof extends Profiler { + /** + * @var Xhprof $xhprof + */ + protected $xhprof; + + /** + * Profiler for explicit, arbitrary, frame labels + * @var SectionProfiler + */ + protected $sprofiler; + + /** + * @param array $params + * @see Xhprof::__construct() + */ + public function __construct( array $params = array() ) { + parent::__construct( $params ); + $this->xhprof = new Xhprof( $params ); + $this->sprofiler = new SectionProfiler(); + } + + public function scopedProfileIn( $section ) { + return $this->sprofiler->scopedProfileIn( $section ); + } + + /** + * No-op for xhprof profiling. + */ + public function close() { + } + + public function getFunctionStats() { + $metrics = $this->xhprof->getCompleteMetrics(); + $profile = array(); + + $main = null; // units in ms + foreach ( $metrics as $fname => $stats ) { + // Convert elapsed times from μs to ms to match interface + $entry = array( + 'name' => $fname, + 'calls' => $stats['ct'], + '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_real' => $stats['wt']['min'] / 1000, + 'max_real' => $stats['wt']['max'] / 1000 + ); + $profile[] = $entry; + if ( $fname === 'main()' ) { + $main = $entry; + } + } + + // Merge in all of the custom profile sections + foreach ( $this->sprofiler->getFunctionStats() as $stats ) { + if ( $stats['name'] === '-total' ) { + // Discard section profiler running totals + continue; + } + + // @note: getFunctionStats() values already in ms + $stats['%real'] = $main['real'] ? $stats['real'] / $main['real'] * 100 : 0; + $stats['%cpu'] = $main['cpu'] ? $stats['cpu'] / $main['cpu'] * 100 : 0; + $stats['%memory'] = $main['memory'] ? $stats['memory'] / $main['memory'] * 100 : 0; + $profile[] = $stats; // assume no section names collide with $metrics + } + + return $profile; + } + + /** + * Returns a profiling output to be stored in debug file + * + * @return string + */ + public function getOutput() { + return $this->getFunctionReport(); + } + + /** + * Get a report of profiled functions sorted by inclusive wall clock time + * in descending order. + * + * Each line of the report includes this data: + * - Function name + * - Number of times function was called + * - Total wall clock time spent in function in microseconds + * - Minimum wall clock time spent in function in microseconds + * - Average wall clock time spent in function in microseconds + * - Maximum wall clock time spent in function in microseconds + * - Percentage of total wall clock time spent in function + * - Total delta of memory usage from start to end of function in bytes + * + * @return string + */ + protected function getFunctionReport() { + $data = $this->getFunctionStats(); + usort( $data, function( $a, $b ) { + if ( $a['real'] === $b['real'] ) { + return 0; + } + return ( $a['real'] > $b['real'] ) ? -1 : 1; // descending + } ); + + $width = 140; + $nameWidth = $width - 65; + $format = "%-{$nameWidth}s %6d %9d %9d %9d %9d %7.3f%% %9d"; + $out = array(); + $out[] = sprintf( "%-{$nameWidth}s %6s %9s %9s %9s %9s %7s %9s", + 'Name', 'Calls', 'Total', 'Min', 'Each', 'Max', '%', 'Mem' + ); + foreach ( $data as $stats ) { + $out[] = sprintf( $format, + $stats['name'], + $stats['calls'], + $stats['real'] * 1000, + $stats['min_real'] * 1000, + $stats['real'] / $stats['calls'] * 1000, + $stats['max_real'] * 1000, + $stats['%real'], + $stats['memory'] + ); + } + return implode( "\n", $out ); + } + + /** + * Retrieve raw data from xhprof + * @return array + */ + public function getRawData() { + return $this->xhprof->getRawData(); + } +} diff --git a/includes/profiler/SectionProfiler.php b/includes/profiler/SectionProfiler.php new file mode 100644 index 00000000..245022df --- /dev/null +++ b/includes/profiler/SectionProfiler.php @@ -0,0 +1,530 @@ +<?php +/** + * Arbitrary section name based PHP profiling. + * + * 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 + * @author Aaron Schulz + */ + +/** + * Custom PHP profiler for parser/DB type section names that xhprof/xdebug can't handle + * + * @since 1.25 + */ +class SectionProfiler { + /** @var array Map of (mem,real,cpu) */ + protected $start; + /** @var array Map of (mem,real,cpu) */ + protected $end; + /** @var array List of resolved profile calls with start/end data */ + protected $stack = array(); + /** @var array Queue of open profile calls with start data */ + protected $workStack = array(); + + /** @var array Map of (function name => aggregate data array) */ + protected $collated = array(); + /** @var bool */ + protected $collateDone = false; + + /** @var bool Whether to collect the full stack trace or just aggregates */ + protected $collateOnly = true; + /** @var array Cache of a standard broken collation entry */ + protected $errorEntry; + /** @var callable Cache of a profile out callback */ + protected $profileOutCallback; + + /** + * @param array $params + */ + public function __construct( array $params = array() ) { + $this->errorEntry = $this->getErrorEntry(); + $this->collateOnly = empty( $params['trace'] ); + $this->profileOutCallback = function ( $profiler, $section ) { + $profiler->profileOutInternal( $section ); + }; + } + + /** + * @param string $section + * @return ScopedCallback + */ + public function scopedProfileIn( $section ) { + $this->profileInInternal( $section ); + + return new SectionProfileCallback( $this, $section ); + } + + /** + * @param ScopedCallback $section + */ + public function scopedProfileOut( ScopedCallback &$section ) { + $section = null; + } + + /** + * 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. + * + * @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 : real time ellapsed (ms) + * - %cpu : percent real time + * - memory : memory used (bytes) + * - %memory : percent memory used + * - min_real : min real time in a call (ms) + * - max_real : max real time in a call (ms) + */ + public function getFunctionStats() { + $this->collateData(); + + $totalCpu = max( $this->end['cpu'] - $this->start['cpu'], 0 ); + $totalReal = max( $this->end['real'] - $this->start['real'], 0 ); + $totalMem = max( $this->end['memory'] - $this->start['memory'], 0 ); + + $profile = array(); + foreach ( $this->collated as $fname => $data ) { + $profile[] = array( + 'name' => $fname, + 'calls' => $data['count'], + '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_real' => 1000 * $data['min_real'], + 'max_real' => 1000 * $data['max_real'] + ); + } + + $profile[] = array( + 'name' => '-total', + 'calls' => 1, + 'real' => 1000 * $totalReal, + '%real' => 100, + 'cpu' => 1000 * $totalCpu, + '%cpu' => 100, + 'memory' => $totalMem, + '%memory' => 100, + 'min_real' => 1000 * $totalReal, + 'max_real' => 1000 * $totalReal + ); + + return $profile; + } + + /** + * Clear all of the profiling data for another run + */ + public function reset() { + $this->start = null; + $this->end = null; + $this->stack = array(); + $this->workStack = array(); + $this->collated = array(); + $this->collateDone = false; + } + + /** + * @return array Initial collation entry + */ + protected function getZeroEntry() { + return array( + 'cpu' => 0.0, + 'real' => 0.0, + 'memory' => 0, + 'count' => 0, + 'min_real' => 0.0, + 'max_real' => 0.0 + ); + } + + /** + * @return array Initial collation entry for errors + */ + protected function getErrorEntry() { + $entry = $this->getZeroEntry(); + $entry['count'] = 1; + return $entry; + } + + /** + * Update the collation entry for a given method name + * + * @param string $name + * @param float $elapsedCpu + * @param float $elapsedReal + * @param int $memChange + */ + protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) { + $entry =& $this->collated[$name]; + if ( !is_array( $entry ) ) { + $entry = $this->getZeroEntry(); + $this->collated[$name] =& $entry; + } + $entry['cpu'] += $elapsedCpu; + $entry['real'] += $elapsedReal; + $entry['memory'] += $memChange > 0 ? $memChange : 0; + $entry['count']++; + $entry['min_real'] = min( $entry['min_real'], $elapsedReal ); + $entry['max_real'] = max( $entry['max_real'], $elapsedReal ); + } + + /** + * This method should not be called outside SectionProfiler + * + * @param string $functionname + */ + public function profileInInternal( $functionname ) { + // Once the data is collated for reports, any future calls + // should clear the collation cache so the next report will + // reflect them. This matters when trace mode is used. + $this->collateDone = false; + + $cpu = $this->getTime( 'cpu' ); + $real = $this->getTime( 'wall' ); + $memory = memory_get_usage(); + + if ( $this->start === null ) { + $this->start = array( 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ); + } + + $this->workStack[] = array( + $functionname, + count( $this->workStack ), + $real, + $cpu, + $memory + ); + } + + /** + * This method should not be called outside SectionProfiler + * + * @param string $functionname + */ + public function profileOutInternal( $functionname ) { + $item = array_pop( $this->workStack ); + if ( $item === null ) { + $this->debugGroup( 'profileerror', "Profiling error: $functionname" ); + return; + } + list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item; + + if ( $functionname === 'close' ) { + $message = "Profile section ended by close(): {$ofname}"; + $this->debugGroup( 'profileerror', $message ); + if ( $this->collateOnly ) { + $this->collated[$message] = $this->errorEntry; + } else { + $this->stack[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ); + } + $functionname = $ofname; + } elseif ( $ofname !== $functionname ) { + $message = "Profiling error: in({$ofname}), out($functionname)"; + $this->debugGroup( 'profileerror', $message ); + if ( $this->collateOnly ) { + $this->collated[$message] = $this->errorEntry; + } else { + $this->stack[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ); + } + } + + $realTime = $this->getTime( 'wall' ); + $cpuTime = $this->getTime( 'cpu' ); + $memUsage = memory_get_usage(); + + if ( $this->collateOnly ) { + $elapsedcpu = $cpuTime - $octime; + $elapsedreal = $realTime - $ortime; + $memchange = $memUsage - $omem; + $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange ); + } else { + $this->stack[] = array_merge( $item, array( $realTime, $cpuTime, $memUsage ) ); + } + + $this->end = array( + 'cpu' => $cpuTime, + 'real' => $realTime, + 'memory' => $memUsage + ); + } + + /** + * Returns a tree of function calls with their real times + * @return string + * @throws Exception + */ + public function getCallTreeReport() { + if ( $this->collateOnly ) { + throw new Exception( "Tree is only available for trace profiling." ); + } + return implode( '', array_map( + array( $this, 'getCallTreeLine' ), $this->remapCallTree( $this->stack ) + ) ); + } + + /** + * Recursive function the format the current profiling array into a tree + * + * @param array $stack Profiling array + * @return array + */ + protected function remapCallTree( array $stack ) { + if ( count( $stack ) < 2 ) { + return $stack; + } + $outputs = array(); + for ( $max = count( $stack ) - 1; $max > 0; ) { + /* Find all items under this entry */ + $level = $stack[$max][1]; + $working = array(); + for ( $i = $max -1; $i >= 0; $i-- ) { + if ( $stack[$i][1] > $level ) { + $working[] = $stack[$i]; + } else { + break; + } + } + $working = $this->remapCallTree( array_reverse( $working ) ); + $output = array(); + foreach ( $working as $item ) { + array_push( $output, $item ); + } + array_unshift( $output, $stack[$max] ); + $max = $i; + + array_unshift( $outputs, $output ); + } + $final = array(); + foreach ( $outputs as $output ) { + foreach ( $output as $item ) { + $final[] = $item; + } + } + return $final; + } + + /** + * Callback to get a formatted line for the call tree + * @param array $entry + * @return string + */ + protected function getCallTreeLine( $entry ) { + // $entry has (name, level, stime, scpu, smem, etime, ecpu, emem) + list( $fname, $level, $startreal, , , $endreal ) = $entry; + $delta = $endreal - $startreal; + $space = str_repeat( ' ', $level ); + # The ugly double sprintf is to work around a PHP bug, + # which has been fixed in recent releases. + return sprintf( "%10s %s %s\n", + trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname ); + } + + /** + * Populate collated data + */ + protected function collateData() { + if ( $this->collateDone ) { + return; + } + $this->collateDone = true; + // Close opened profiling sections + while ( count( $this->workStack ) ) { + $this->profileOutInternal( 'close' ); + } + + if ( $this->collateOnly ) { + return; // already collated as methods exited + } + + $this->collated = array(); + + # Estimate profiling overhead + $oldEnd = $this->end; + $profileCount = count( $this->stack ); + $this->calculateOverhead( $profileCount ); + + # First, subtract the overhead! + $overheadTotal = $overheadMemory = $overheadInternal = array(); + foreach ( $this->stack as $entry ) { + // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1) + $fname = $entry[0]; + $elapsed = $entry[5] - $entry[2]; + $memchange = $entry[7] - $entry[4]; + + if ( $fname === '-overhead-total' ) { + $overheadTotal[] = $elapsed; + $overheadMemory[] = max( 0, $memchange ); + } elseif ( $fname === '-overhead-internal' ) { + $overheadInternal[] = $elapsed; + } + } + $overheadTotal = $overheadTotal ? + array_sum( $overheadTotal ) / count( $overheadInternal ) : 0; + $overheadMemory = $overheadMemory ? + array_sum( $overheadMemory ) / count( $overheadInternal ) : 0; + $overheadInternal = $overheadInternal ? + array_sum( $overheadInternal ) / count( $overheadInternal ) : 0; + + # Collate + foreach ( $this->stack as $index => $entry ) { + // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1) + $fname = $entry[0]; + $elapsedCpu = $entry[6] - $entry[3]; + $elapsedReal = $entry[5] - $entry[2]; + $memchange = $entry[7] - $entry[4]; + $subcalls = $this->calltreeCount( $this->stack, $index ); + + if ( substr( $fname, 0, 9 ) !== '-overhead' ) { + # Adjust for profiling overhead (except special values with elapsed=0) + if ( $elapsed ) { + $elapsed -= $overheadInternal; + $elapsed -= ( $subcalls * $overheadTotal ); + $memchange -= ( $subcalls * $overheadMemory ); + } + } + + $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange ); + } + + $this->collated['-overhead-total']['count'] = $profileCount; + arsort( $this->collated, SORT_NUMERIC ); + + // Unclobber the end info map (the overhead checking alters it) + $this->end = $oldEnd; + } + + /** + * Dummy calls to calculate profiling overhead + * + * @param int $profileCount + */ + protected function calculateOverhead( $profileCount ) { + $this->profileInInternal( '-overhead-total' ); + for ( $i = 0; $i < $profileCount; $i++ ) { + $this->profileInInternal( '-overhead-internal' ); + $this->profileOutInternal( '-overhead-internal' ); + } + $this->profileOutInternal( '-overhead-total' ); + } + + /** + * Counts the number of profiled function calls sitting under + * the given point in the call graph. Not the most efficient algo. + * + * @param array $stack + * @param int $start + * @return int + */ + protected function calltreeCount( $stack, $start ) { + $level = $stack[$start][1]; + $count = 0; + for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) { + $count ++; + } + return $count; + } + + /** + * 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 ); + } + } + + /** + * Add an entry in the debug log file + * + * @param string $s String to output + */ + protected function debug( $s ) { + if ( function_exists( 'wfDebug' ) ) { + wfDebug( $s ); + } + } + + /** + * Add an entry in the debug log group + * + * @param string $group Group to send the message to + * @param string $s String to output + */ + protected function debugGroup( $group, $s ) { + if ( function_exists( 'wfDebugLog' ) ) { + wfDebugLog( $group, $s ); + } + } +} + +/** + * Subclass ScopedCallback to avoid call_user_func_array(), which is slow + * + * This class should not be used outside of SectionProfiler + */ +class SectionProfileCallback extends ScopedCallback { + /** @var SectionProfiler */ + protected $profiler; + /** @var string */ + protected $section; + + /** + * @param SectionProfiler $profiler + * @param string $section + */ + public function __construct( SectionProfiler $profiler, $section ) { + parent::__construct( null ); + $this->profiler = $profiler; + $this->section = $section; + } + + function __destruct() { + $this->profiler->profileOutInternal( $this->section ); + } +} diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php new file mode 100644 index 00000000..f02d66f8 --- /dev/null +++ b/includes/profiler/TransactionProfiler.php @@ -0,0 +1,274 @@ +<?php +/** + * Transaction profiling for contention + * + * 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 + * @author Aaron Schulz + */ + +use Psr\Log\LoggerInterface; +use Psr\Log\LoggerAwareInterface; +use Psr\Log\NullLogger; +/** + * Helper class that detects high-contention DB queries via profiling calls + * + * This class is meant to work with a DatabaseBase object, which manages queries + * + * @since 1.24 + */ +class TransactionProfiler implements LoggerAwareInterface { + /** @var float Seconds */ + protected $dbLockThreshold = 3.0; + /** @var float Seconds */ + protected $eventThreshold = .25; + + /** @var array transaction ID => (write start time, list of DBs involved) */ + protected $dbTrxHoldingLocks = array(); + /** @var array transaction ID => list of (query name, start time, end time) */ + protected $dbTrxMethodTimes = array(); + + /** @var array */ + protected $hits = array( + 'writes' => 0, + 'queries' => 0, + 'conns' => 0, + 'masterConns' => 0 + ); + /** @var array */ + protected $expect = array( + 'writes' => INF, + 'queries' => INF, + 'conns' => INF, + 'masterConns' => INF, + 'maxAffected' => INF + ); + /** @var array */ + protected $expectBy = array(); + + /** + * @var LoggerInterface + */ + private $logger; + + public function __construct() { + $this->setLogger( new NullLogger() ); + } + + public function setLogger( LoggerInterface $logger ) { + $this->logger = $logger; + } + + /** + * Set performance expectations + * + * With conflicting expect, the most specific ones will be used + * + * @param string $event (writes,queries,conns,mConns) + * @param integer $value Maximum count of the event + * @param string $fname Caller + * @since 1.25 + */ + public function setExpectation( $event, $value, $fname ) { + $this->expect[$event] = isset( $this->expect[$event] ) + ? min( $this->expect[$event], $value ) + : $value; + if ( $this->expect[$event] == $value ) { + $this->expectBy[$event] = $fname; + } + } + + /** + * Reset performance expectations and hit counters + * + * @since 1.25 + */ + public function resetExpectations() { + foreach ( $this->hits as &$val ) { + $val = 0; + } + unset( $val ); + foreach ( $this->expect as &$val ) { + $val = INF; + } + unset( $val ); + $this->expectBy = array(); + } + + /** + * Mark a DB as having been connected to with a new handle + * + * Note that there can be multiple connections to a single DB. + * + * @param string $server DB server + * @param string $db DB name + * @param bool $isMaster + */ + public function recordConnection( $server, $db, $isMaster ) { + // Report when too many connections happen... + if ( $this->hits['conns']++ == $this->expect['conns'] ) { + $this->reportExpectationViolated( 'conns', "[connect to $server ($db)]" ); + } + if ( $isMaster && $this->hits['masterConns']++ == $this->expect['masterConns'] ) { + $this->reportExpectationViolated( 'masterConns', "[connect to $server ($db)]" ); + } + } + + /** + * Mark a DB as in a transaction with one or more writes pending + * + * Note that there can be multiple connections to a single DB. + * + * @param string $server DB server + * @param string $db DB name + * @param string $id ID string of transaction + */ + public function transactionWritingIn( $server, $db, $id ) { + $name = "{$server} ({$db}) (TRX#$id)"; + if ( isset( $this->dbTrxHoldingLocks[$name] ) ) { + $this->logger->info( "Nested transaction for '$name' - out of sync." ); + } + $this->dbTrxHoldingLocks[$name] = array( + 'start' => microtime( true ), + 'conns' => array(), // all connections involved + ); + $this->dbTrxMethodTimes[$name] = array(); + + foreach ( $this->dbTrxHoldingLocks as $name => &$info ) { + // Track all DBs in transactions for this transaction + $info['conns'][$name] = 1; + } + } + + /** + * Register the name and time of a method for slow DB trx detection + * + * This assumes that all queries are synchronous (non-overlapping) + * + * @param string $query Function name or generalized SQL + * @param float $sTime Starting UNIX wall time + * @param bool $isWrite Whether this is a write query + * @param integer $n Number of affected rows + */ + public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) { + $eTime = microtime( true ); + $elapsed = ( $eTime - $sTime ); + + if ( $isWrite && $n > $this->expect['maxAffected'] ) { + $this->logger->info( "Query affected $n row(s):\n" . $query . "\n" . wfBacktrace( true ) ); + } + + // Report when too many writes/queries happen... + if ( $this->hits['queries']++ == $this->expect['queries'] ) { + $this->reportExpectationViolated( 'queries', $query ); + } + if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) { + $this->reportExpectationViolated( 'writes', $query ); + } + + if ( !$this->dbTrxHoldingLocks ) { + // Short-circuit + return; + } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) { + // Not an important query nor slow enough + return; + } + + foreach ( $this->dbTrxHoldingLocks as $name => $info ) { + $lastQuery = end( $this->dbTrxMethodTimes[$name] ); + if ( $lastQuery ) { + // Additional query in the trx... + $lastEnd = $lastQuery[2]; + if ( $sTime >= $lastEnd ) { // sanity check + if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) { + // Add an entry representing the time spent doing non-queries + $this->dbTrxMethodTimes[$name][] = array( '...delay...', $lastEnd, $sTime ); + } + $this->dbTrxMethodTimes[$name][] = array( $query, $sTime, $eTime ); + } + } else { + // First query in the trx... + if ( $sTime >= $info['start'] ) { // sanity check + $this->dbTrxMethodTimes[$name][] = array( $query, $sTime, $eTime ); + } + } + } + } + + /** + * Mark a DB as no longer in a transaction + * + * This will check if locks are possibly held for longer than + * needed and log any affected transactions to a special DB log. + * Note that there can be multiple connections to a single DB. + * + * @param string $server DB server + * @param string $db DB name + * @param string $id ID string of transaction + */ + public function transactionWritingOut( $server, $db, $id ) { + $name = "{$server} ({$db}) (TRX#$id)"; + if ( !isset( $this->dbTrxMethodTimes[$name] ) ) { + $this->logger->info( "Detected no transaction for '$name' - out of sync." ); + return; + } + // Fill in the last non-query period... + $lastQuery = end( $this->dbTrxMethodTimes[$name] ); + if ( $lastQuery ) { + $now = microtime( true ); + $lastEnd = $lastQuery[2]; + if ( ( $now - $lastEnd ) > $this->eventThreshold ) { + $this->dbTrxMethodTimes[$name][] = array( '...delay...', $lastEnd, $now ); + } + } + // Check for any slow queries or non-query periods... + $slow = false; + foreach ( $this->dbTrxMethodTimes[$name] as $info ) { + $elapsed = ( $info[2] - $info[1] ); + if ( $elapsed >= $this->dbLockThreshold ) { + $slow = true; + break; + } + } + if ( $slow ) { + $dbs = implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ); + $msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n"; + foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) { + list( $query, $sTime, $end ) = $info; + $msg .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query ); + } + $this->logger->info( $msg ); + } + unset( $this->dbTrxHoldingLocks[$name] ); + unset( $this->dbTrxMethodTimes[$name] ); + } + + /** + * @param string $expect + * @param string $query + */ + protected function reportExpectationViolated( $expect, $query ) { + global $wgRequest; + + $n = $this->expect[$expect]; + $by = $this->expectBy[$expect]; + $this->logger->info( + "[{$wgRequest->getMethod()}] Expectation ($expect <= $n) by $by not met:\n$query\n" . wfBacktrace( true ) + ); + } +} diff --git a/includes/profiler/output/ProfilerOutput.php b/includes/profiler/output/ProfilerOutput.php new file mode 100644 index 00000000..3473e0b2 --- /dev/null +++ b/includes/profiler/output/ProfilerOutput.php @@ -0,0 +1,57 @@ +<?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; + } + + /** + * Log MediaWiki-style profiling data + * + * @param array $stats Result of Profiler::getFunctionStats() + */ + abstract public function log( array $stats ); +} diff --git a/includes/profiler/ProfilerSimpleDB.php b/includes/profiler/output/ProfilerOutputDb.php index 7ef0ad05..76d62d2e 100644 --- a/includes/profiler/ProfilerSimpleDB.php +++ b/includes/profiler/output/ProfilerOutputDb.php @@ -22,47 +22,45 @@ */ /** - * $wgProfiler['class'] = 'ProfilerSimpleDB'; + * Logs profiling data into the local DB * * @ingroup Profiler + * @since 1.25 */ -class ProfilerSimpleDB extends ProfilerStandard { - protected function collateOnly() { - return true; - } - - public function isPersistent() { - return true; - } +class ProfilerOutputDb extends ProfilerOutput { + /** @var bool Whether to store host data with profiling calls */ + private $perHost = false; - /** - * Log the whole profiling data into the database. - */ - public function logData() { + public function __construct( Profiler $collector, array $params ) { + parent::__construct( $collector, $params ); global $wgProfilePerHost; - # Do not log anything if database is readonly (bug 5375) - if ( wfReadOnly() ) { - return; + // Initialize per-host profiling from config, back-compat if available + if ( isset( $this->params['perHost'] ) ) { + $this->perHost = $this->params['perHost']; + } elseif ( $wgProfilePerHost ) { + $this->perHost = $wgProfilePerHost; } + } - if ( $wgProfilePerHost ) { - $pfhost = wfHostname(); - } else { - $pfhost = ''; - } + public function canUse() { + # Do not log anything if database is readonly (bug 5375) + return !wfReadOnly(); + } - try { - $this->collateData(); + public function log( array $stats ) { + $pfhost = $this->perHost ? wfHostname() : ''; + try { $dbw = wfGetDB( DB_MASTER ); $useTrx = ( $dbw->getType() === 'sqlite' ); // much faster if ( $useTrx ) { $dbw->startAtomic( __METHOD__ ); } - foreach ( $this->mCollated 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 ); @@ -70,37 +68,22 @@ class ProfilerSimpleDB extends ProfilerStandard { $timeSum = $timeSum >= 0 ? $timeSum : 0; $memorySum = $memorySum >= 0 ? $memorySum : 0; - $dbw->update( 'profiling', + $dbw->upsert( 'profiling', + array( + 'pf_name' => $name, + 'pf_count' => $eventCount, + 'pf_time' => $timeSum, + 'pf_memory' => $memorySum, + 'pf_server' => $pfhost + ), + array( array( 'pf_name', 'pf_server' ) ), array( "pf_count=pf_count+{$eventCount}", "pf_time=pf_time+{$timeSum}", "pf_memory=pf_memory+{$memorySum}", ), - array( - 'pf_name' => $name, - 'pf_server' => $pfhost, - ), - __METHOD__ ); - - $rc = $dbw->affectedRows(); - if ( $rc == 0 ) { - $dbw->insert( 'profiling', - array( - 'pf_name' => $name, - 'pf_count' => $eventCount, - 'pf_time' => $timeSum, - 'pf_memory' => $memorySum, - 'pf_server' => $pfhost - ), - __METHOD__, - array( 'IGNORE' ) - ); - } - // When we upgrade to mysql 4.1, the insert+update - // can be merged into just a insert with this construct added: - // "ON DUPLICATE KEY UPDATE ". - // "pf_count=pf_count + VALUES(pf_count), ". - // "pf_time=pf_time + VALUES(pf_time)"; + __METHOD__ + ); } if ( $useTrx ) { $dbw->endAtomic( __METHOD__ ); diff --git a/includes/profiler/output/ProfilerOutputDump.php b/includes/profiler/output/ProfilerOutputDump.php new file mode 100644 index 00000000..bf4b85c2 --- /dev/null +++ b/includes/profiler/output/ProfilerOutputDump.php @@ -0,0 +1,51 @@ +<?php +/** + * Profiler dumping output in xhprof dump file + * + * 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 + */ + +/** + * Profiler dumping output in xhprof dump file + * @ingroup Profiler + * + * @since 1.25 + */ +class ProfilerOutputDump extends ProfilerOutput { + + protected $suffix = ".xhprof"; + + /** + * Can this output type be used? + * + * @return bool + */ + public function canUse() { + if ( empty( $this->params['outputDir'] ) ) { + return false; + } + return true; + } + + public function log( array $stats ) { + $data = $this->collector->getRawData(); + $filename = sprintf( "%s/%s.%s%s", $this->params['outputDir'], uniqid(), $this->collector->getProfileID(), $this->suffix ); + file_put_contents( $filename, serialize( $data ) ); + } +} diff --git a/includes/profiler/output/ProfilerOutputStats.php b/includes/profiler/output/ProfilerOutputStats.php new file mode 100644 index 00000000..ef6ef7c9 --- /dev/null +++ b/includes/profiler/output/ProfilerOutputStats.php @@ -0,0 +1,57 @@ +<?php +/** + * ProfilerOutput class that flushes profiling data to the profiling + * context's stats buffer. + * + * 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 + */ + +/** + * ProfilerOutput class that flushes profiling data to the profiling + * context's stats buffer. + * + * @ingroup Profiler + * @since 1.25 + */ +class ProfilerOutputStats extends ProfilerOutput { + + /** + * Flush profiling data to the current profiling context's stats buffer. + * + * @param array $stats + */ + public function log( array $stats ) { + $contextStats = $this->collector->getContext()->getStats(); + + foreach ( $stats as $stat ) { + // Sanitize the key + $key = str_replace( '::', '.', $stat['name'] ); + $key = preg_replace( '/[^a-z.]+/i', '_', $key ); + $key = trim( $key, '_.' ); + + // Convert fractional seconds to whole milliseconds + $cpu = round( $stat['cpu'] * 1000 ); + $real = round( $stat['real'] * 1000 ); + + $contextStats->increment( "{$key}.calls" ); + $contextStats->timing( "{$key}.cpu", $cpu ); + $contextStats->timing( "{$key}.real", $real ); + } + } +} diff --git a/includes/profiler/output/ProfilerOutputText.php b/includes/profiler/output/ProfilerOutputText.php new file mode 100644 index 00000000..67527798 --- /dev/null +++ b/includes/profiler/output/ProfilerOutputText.php @@ -0,0 +1,77 @@ +<?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! :) + * + * @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; + } + public function log( 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' || $contentType === 'text/css' ) { + print "\n/*\n{$out}*/\n"; + } + } + } +} diff --git a/includes/profiler/output/ProfilerOutputUdp.php b/includes/profiler/output/ProfilerOutputUdp.php new file mode 100644 index 00000000..7da03c11 --- /dev/null +++ b/includes/profiler/output/ProfilerOutputUdp.php @@ -0,0 +1,96 @@ +<?php +/** + * Profiler sending messages over UDP. + * + * 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 + */ + +/** + * ProfilerSimpleUDP class, that sends out messages for 'udpprofile' daemon + * (see http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile) + * + * @ingroup Profiler + * @since 1.25 + */ +class ProfilerOutputUdp extends ProfilerOutput { + /** @var int port to send profiling data to */ + private $port = 3811; + + /** @var string host to send profiling data to */ + private $host = '127.0.0.1'; + + /** @var string format string for profiling data */ + private $format = "%s - %d %f %f %f %f %s\n"; + + public function __construct( Profiler $collector, array $params ) { + parent::__construct( $collector, $params ); + global $wgUDPProfilerPort, $wgUDPProfilerHost, $wgUDPProfilerFormatString; + + // Initialize port, host, and format from config, back-compat if available + if ( isset( $this->params['udpport'] ) ) { + $this->port = $this->params['udpport']; + } elseif ( $wgUDPProfilerPort ) { + $this->port = $wgUDPProfilerPort; + } + + if ( isset( $this->params['udphost'] ) ) { + $this->host = $this->params['udphost']; + } elseif ( $wgUDPProfilerHost ) { + $this->host = $wgUDPProfilerHost; + } + + if ( isset( $this->params['udpformat'] ) ) { + $this->format = $this->params['udpformat']; + } elseif ( $wgUDPProfilerFormatString ) { + $this->format = $wgUDPProfilerFormatString; + } + } + + public function canUse() { + # Sockets are not enabled + return function_exists( 'socket_create' ); + } + + public function log( array $stats ) { + $sock = socket_create( AF_INET, SOCK_DGRAM, SOL_UDP ); + $plength = 0; + $packet = ""; + foreach ( $stats as $pfdata ) { + $pfline = sprintf( $this->format, + $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 ); + if ( $length + $plength > 1400 ) { + socket_sendto( $sock, $packet, $plength, 0, $this->host, $this->port ); + $packet = ""; + $plength = 0; + } + $packet .= $pfline; + $plength += $length; + } + socket_sendto( $sock, $packet, $plength, 0x100, $this->host, $this->port ); + } +} |