diff options
Diffstat (limited to 'includes/profiler')
| -rw-r--r-- | includes/profiler/Profiler.php | 637 | ||||
| -rw-r--r-- | includes/profiler/ProfilerMwprof.php | 256 | ||||
| -rw-r--r-- | includes/profiler/ProfilerSimple.php | 133 | ||||
| -rw-r--r-- | includes/profiler/ProfilerSimpleDB.php | 111 | ||||
| -rw-r--r-- | includes/profiler/ProfilerSimpleText.php | 6 | ||||
| -rw-r--r-- | includes/profiler/ProfilerSimpleTrace.php | 59 | ||||
| -rw-r--r-- | includes/profiler/ProfilerSimpleUDP.php | 17 | ||||
| -rw-r--r-- | includes/profiler/ProfilerStandard.php | 559 | ||||
| -rw-r--r-- | includes/profiler/ProfilerStub.php | 38 |
9 files changed, 1185 insertions, 631 deletions
diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index 2282a3af..418b5d48 100644 --- a/includes/profiler/Profiler.php +++ b/includes/profiler/Profiler.php @@ -19,16 +19,30 @@ * * @file * @ingroup Profiler - * This file is only included if profiling is enabled + * @defgroup Profiler Profiler */ /** - * @defgroup Profiler 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 + * @param string $functionname Name of the function we will profile */ function wfProfileIn( $functionname ) { if ( Profiler::$__instance === null ) { // use this directly to reduce overhead @@ -41,7 +55,7 @@ function wfProfileIn( $functionname ) { /** * Stop profiling of a function - * @param string $functionname name of the function we have profiled + * @param string $functionname Name of the function we have profiled */ function wfProfileOut( $functionname = 'missing' ) { if ( Profiler::$__instance === null ) { // use this directly to reduce overhead @@ -91,45 +105,46 @@ class ProfileSection { } /** + * Profiler base class that defines the interface and some trivial functionality + * * @ingroup Profiler - * @todo document */ -class Profiler { - protected $mStack = array(), $mWorkStack = array(), $mCollated = array(), - $mCalls = array(), $mTotals = array(); - protected $mTimeMetric = 'wall'; - protected $mProfileID = false, $mCollateDone = false, $mTemplated = false; - - protected $mDBLockThreshold = 5.0; // float; seconds - /** @var Array DB/server name => (active trx count,timestamp) */ - protected $mDBTrxHoldingLocks = array(); - /** @var Array DB/server name => list of (method, elapsed time) */ - protected $mDBTrxMethodTimes = array(); +abstract class Profiler { + /** @var string|bool Profiler ID for bucketing data */ + protected $mProfileID = false; + /** @var bool Whether MediaWiki is in a SkinTemplate output context */ + protected $mTemplated = false; - /** @var Profiler */ - public static $__instance = null; // do not call this outside Profiler and ProfileSection + /** @var TransactionProfiler */ + protected $trxProfiler; - function __construct( $params ) { - if ( isset( $params['timeMetric'] ) ) { - $this->mTimeMetric = $params['timeMetric']; - } + // @codingStandardsIgnoreStart PSR2.Classes.PropertyDeclaration.Underscore + /** @var Profiler Do not call this outside Profiler and ProfileSection */ + public static $__instance = null; + // @codingStandardsIgnoreEnd + + /** + * @param array $params + */ + public function __construct( array $params ) { if ( isset( $params['profileID'] ) ) { $this->mProfileID = $params['profileID']; } - - $this->addInitialStack(); + $this->trxProfiler = new TransactionProfiler(); } /** * Singleton * @return Profiler */ - public static function instance() { + final public static function instance() { if ( self::$__instance === null ) { global $wgProfiler; 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']; } @@ -137,7 +152,7 @@ class Profiler { } elseif ( $wgProfiler instanceof Profiler ) { self::$__instance = $wgProfiler; // back-compat } else { - self::$__instance = new ProfilerStub( $wgProfiler ); + self::$__instance = new ProfilerStub( array() ); } } return self::$__instance; @@ -145,35 +160,41 @@ class Profiler { /** * Set the profiler to a specific profiler instance. Mostly for dumpHTML - * @param $p Profiler object + * @param Profiler $p */ - public static function setInstance( Profiler $p ) { + final public static function setInstance( Profiler $p ) { self::$__instance = $p; } /** * Return whether this a stub profiler * - * @return Boolean + * @return bool */ - public function isStub() { - return false; - } + abstract public function isStub(); /** * 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. + * * @see Profiler::logData() - * @return Boolean + * @return bool */ - public function isPersistent() { - return true; - } + abstract public function isPersistent(); + /** + * @param string $id + */ public function setProfileID( $id ) { $this->mProfileID = $id; } + /** + * @return string + */ public function getProfileID() { if ( $this->mProfileID === false ) { return wfWikiID(); @@ -183,76 +204,18 @@ class Profiler { } /** - * Add the inital item in the stack. - */ - protected function addInitialStack() { - // Push an entry for the pre-profile setup time onto the stack - $initial = $this->getInitialTime(); - if ( $initial !== null ) { - $this->mWorkStack[] = array( '-total', 0, $initial, 0 ); - $this->mStack[] = array( '-setup', 1, $initial, 0, $this->getTime(), 0 ); - } else { - $this->profileIn( '-total' ); - } - } - - /** * Called by wfProfieIn() * - * @param $functionname String + * @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(), memory_get_usage() ); - } + abstract public function profileIn( $functionname ); /** * Called by wfProfieOut() * - * @param $functionname String - */ - public function profileOut( $functionname ) { - global $wgDebugFunctionEntry; - $memory = memory_get_usage(); - $time = $this->getTime(); - - if ( $wgDebugFunctionEntry ) { - $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . 'Exiting ' . $functionname . "\n" ); - } - - $bit = array_pop( $this->mWorkStack ); - - if ( !$bit ) { - $this->debug( "Profiling error, !\$bit: $functionname\n" ); - } else { - if ( $functionname == 'close' ) { - $message = "Profile section ended by close(): {$bit[0]}"; - $this->debug( "$message\n" ); - $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 ); - } elseif ( $bit[0] != $functionname ) { - $message = "Profiling error: in({$bit[0]}), out($functionname)"; - $this->debug( "$message\n" ); - $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 ); - } - $bit[] = $time; - $bit[] = $memory; - $this->mStack[] = $bit; - $this->updateTrxProfiling( $functionname, $time ); - } - } - - /** - * Close opened profiling sections + * @param string $functionname */ - public function close() { - while ( count( $this->mWorkStack ) ) { - $this->profileOut( 'close' ); - } - } + abstract public function profileOut( $functionname ); /** * Mark a DB as in a transaction with one or more writes pending @@ -261,39 +224,10 @@ class Profiler { * * @param string $server DB server * @param string $db DB name + * @param string $id Resource ID string of connection */ - public function transactionWritingIn( $server, $db ) { - $name = "{$server} ({$db})"; - if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) { - ++$this->mDBTrxHoldingLocks[$name]['refs']; - } else { - $this->mDBTrxHoldingLocks[$name] = array( 'refs' => 1, 'start' => microtime( true ) ); - $this->mDBTrxMethodTimes[$name] = array(); - } - } - - /** - * Register the name and time of a method for slow DB trx detection - * - * @param string $method Function name - * @param float $realtime Wal time ellapsed - */ - protected function updateTrxProfiling( $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 ); - } - } + public function transactionWritingIn( $server, $db, $id = '' ) { + $this->trxProfiler->transactionWritingIn( $server, $db, $id ); } /** @@ -305,144 +239,60 @@ class Profiler { * * @param string $server DB server * @param string $db DB name + * @param string $id Resource ID string of connection */ - public function transactionWritingOut( $server, $db ) { - $name = "{$server} ({$db})"; - if ( --$this->mDBTrxHoldingLocks[$name]['refs'] <= 0 ) { - $slow = false; - foreach ( $this->mDBTrxMethodTimes[$name] as $info ) { - list( $method, $realtime ) = $info; - if ( $realtime >= $this->mDBLockThreshold ) { - $slow = true; - break; - } - } - if ( $slow ) { - $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks ) ); - $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] ); - } + public function transactionWritingOut( $server, $db, $id = '' ) { + $this->trxProfiler->transactionWritingOut( $server, $db, $id ); } /** - * Mark this call as templated or not - * - * @param $t Boolean + * Close opened profiling sections */ - function setTemplated( $t ) { - $this->mTemplated = $t; - } + abstract public function close(); /** - * Returns a profiling output to be stored in debug file - * - * @return String + * Log the data to some store or even the page output */ - public function getOutput() { - global $wgDebugFunctionEntry, $wgProfileCallTree; - $wgDebugFunctionEntry = false; - - if ( !count( $this->mStack ) && !count( $this->mCollated ) ) { - return "No profiling output\n"; - } - - if ( $wgProfileCallTree ) { - return $this->getCallTree(); - } else { - return $this->getFunctionReport(); - } - } + abstract public function logData(); /** - * Returns a tree of function call instead of a list of functions - * @return string + * Mark this call as templated or not + * + * @param bool $t */ - function getCallTree() { - return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) ) ); + public function setTemplated( $t ) { + $this->mTemplated = $t; } /** - * Recursive function the format the current profiling array into a tree + * Returns a profiling output to be stored in debug file * - * @param array $stack profiling array - * @return array + * @return string */ - function remapCallTree( $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; - } + abstract public function getOutput(); /** - * Callback to get a formatted line for the call tree - * @return string + * @return array */ - function getCallTreeLine( $entry ) { - list( $fname, $level, $start, /* $x */, $end ) = $entry; - $delta = $end - $start; - $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 ); - } + abstract public function getRawData(); /** * Get the initial time of the request, based either on $wgRequestTime or * $wgRUstart. Will return null if not able to find data. * - * @param string|false $metric metric to use, with the following possibilities: + * @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 */ - function getTime( $metric = false ) { - if ( $metric === false ) { - $metric = $this->mTimeMetric; - } - - if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) { - if ( !function_exists( 'getrusage' ) ) { + protected function getTime( $metric = 'wall' ) { + if ( $metric === 'cpu' || $metric === 'user' ) { + $ru = wfGetRusage(); + if ( !$ru ) { return 0; } - $ru = getrusage(); $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 @@ -459,21 +309,17 @@ class Profiler { * Get the initial time of the request, based either on $wgRequestTime or * $wgRUstart. Will return null if not able to find data. * - * @param string|false $metric metric to use, with the following possibilities: + * @param string|bool $metric Metric to use, with the following possibilities: * - user: User CPU time (without system calls) * - cpu: Total CPU time (user and system calls) * - wall (or any other string): elapsed time * - false (default): will fall back to default metric * @return float|null */ - protected function getInitialTime( $metric = false ) { + protected function getInitialTime( $metric = 'wall' ) { global $wgRequestTime, $wgRUstart; - if ( $metric === false ) { - $metric = $this->mTimeMetric; - } - - if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) { + if ( $metric === 'cpu' || $metric === 'user' ) { if ( !count( $wgRUstart ) ) { return null; } @@ -494,243 +340,130 @@ class Profiler { } } - protected function collateData() { - if ( $this->mCollateDone ) { - return; - } - $this->mCollateDone = true; - - $this->close(); - - $this->mCollated = array(); - $this->mCalls = array(); - $this->mMemory = array(); - - # Estimate profiling overhead - $profileCount = count( $this->mStack ); - self::calculateOverhead( $profileCount ); - - # First, subtract the overhead! - $overheadTotal = $overheadMemory = $overheadInternal = array(); - foreach ( $this->mStack as $entry ) { - $fname = $entry[0]; - $start = $entry[2]; - $end = $entry[4]; - $elapsed = $end - $start; - $memory = $entry[5] - $entry[3]; - - if ( $fname == '-overhead-total' ) { - $overheadTotal[] = $elapsed; - $overheadMemory[] = $memory; - } 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 ) { - $fname = $entry[0]; - $start = $entry[2]; - $end = $entry[4]; - $elapsed = $end - $start; - - $memory = $entry[5] - $entry[3]; - $subcalls = $this->calltreeCount( $this->mStack, $index ); - - if ( !preg_match( '/^-overhead/', $fname ) ) { - # Adjust for profiling overhead (except special values with elapsed=0 - if ( $elapsed ) { - $elapsed -= $overheadInternal; - $elapsed -= ( $subcalls * $overheadTotal ); - $memory -= ( $subcalls * $overheadMemory ); - } - } - - if ( !array_key_exists( $fname, $this->mCollated ) ) { - $this->mCollated[$fname] = 0; - $this->mCalls[$fname] = 0; - $this->mMemory[$fname] = 0; - $this->mMin[$fname] = 1 << 24; - $this->mMax[$fname] = 0; - $this->mOverhead[$fname] = 0; - } - - $this->mCollated[$fname] += $elapsed; - $this->mCalls[$fname]++; - $this->mMemory[$fname] += $memory; - $this->mMin[$fname] = min( $this->mMin[$fname], $elapsed ); - $this->mMax[$fname] = max( $this->mMax[$fname], $elapsed ); - $this->mOverhead[$fname] += $subcalls; - } - - $this->mCalls['-overhead-total'] = $profileCount; - arsort( $this->mCollated, SORT_NUMERIC ); - } - /** - * Returns a list of profiled functions. + * Add an entry in the debug log file * - * @return string - */ - 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'] : 0; - - foreach ( $this->mCollated as $fname => $elapsed ) { - $calls = $this->mCalls[$fname]; - $percent = $total ? 100. * $elapsed / $total : 0; - $memory = $this->mMemory[$fname]; - $prof .= sprintf( $format, - substr( $fname, 0, $nameWidth ), - $calls, - (float)( $elapsed * 1000 ), - (float)( $elapsed * 1000 ) / $calls, - $percent, - $memory, - ( $this->mMin[$fname] * 1000.0 ), - ( $this->mMax[$fname] * 1000.0 ), - $this->mOverhead[$fname] - ); - } - $prof .= "\nTotal: $total\n\n"; - - return $prof; - } - - /** - * Dummy calls to wfProfileIn/wfProfileOut to calculate its overhead + * @param string $s String to output */ - protected static function calculateOverhead( $profileCount ) { - wfProfileIn( '-overhead-total' ); - for ( $i = 0; $i < $profileCount; $i++ ) { - wfProfileIn( '-overhead-internal' ); - wfProfileOut( '-overhead-internal' ); + protected function debug( $s ) { + if ( function_exists( 'wfDebug' ) ) { + wfDebug( $s ); } - wfProfileOut( '-overhead-total' ); } /** - * Counts the number of profiled function calls sitting under - * the given point in the call graph. Not the most efficient algo. + * Add an entry in the debug log group * - * @param $stack Array: - * @param $start Integer: - * @return Integer - * @private + * @param string $group Group to send the message to + * @param string $s String to output */ - function calltreeCount( $stack, $start ) { - $level = $stack[$start][1]; - $count = 0; - for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) { - $count ++; + protected function debugGroup( $group, $s ) { + if ( function_exists( 'wfDebugLog' ) ) { + wfDebugLog( $group, $s ); } - return $count; } +} + +/** + * 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(); /** - * Log the whole profiling data into the database. + * 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 logData() { - global $wgProfilePerHost, $wgProfileToDatabase; - - # Do not log anything if database is readonly (bug 5375) - if ( wfReadOnly() || !$wgProfileToDatabase ) { - return; - } - - $dbw = wfGetDB( DB_MASTER ); - if ( !is_object( $dbw ) ) { - return; + 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(); - if ( $wgProfilePerHost ) { - $pfhost = wfHostname(); - } else { - $pfhost = ''; + foreach ( $this->mDBTrxHoldingLocks as $name => &$info ) { + $info['conns'][$name] = 1; // track all DBs in transactions for this transaction } - - try { - $this->collateData(); - - foreach ( $this->mCollated as $name => $elapsed ) { - $eventCount = $this->mCalls[$name]; - $timeSum = (float)( $elapsed * 1000 ); - $memorySum = (float)$this->mMemory[$name]; - $name = substr( $name, 0, 255 ); - - // Kludge - $timeSum = $timeSum >= 0 ? $timeSum : 0; - $memorySum = $memorySum >= 0 ? $memorySum : 0; - - $dbw->update( 'profiling', - 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)"; - } - } catch ( DBError $e ) {} } /** - * Get the function name of the current profiling section - * @return - */ - function getCurrentSection() { - $elt = end( $this->mWorkStack ); - return $elt[0]; - } - - /** - * Add an entry in the debug log file + * Register the name and time of a method for slow DB trx detection * - * @param string $s to output + * This method is only to be called by the Profiler class as methods finish + * + * @param string $method Function name + * @param float $realtime Wal time ellapsed */ - function debug( $s ) { - if ( function_exists( 'wfDebug' ) ) { - wfDebug( $s ); + 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 ); + } } } /** - * Get the content type sent out to the client. - * Used for profilers that output instead of store data. - * @return string + * 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 */ - protected function getContentType() { - foreach ( headers_list() as $header ) { - if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) { - return $m[1]; + 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 ); } - return null; + unset( $this->mDBTrxHoldingLocks[$name] ); + unset( $this->mDBTrxMethodTimes[$name] ); } } diff --git a/includes/profiler/ProfilerMwprof.php b/includes/profiler/ProfilerMwprof.php new file mode 100644 index 00000000..af3c7741 --- /dev/null +++ b/includes/profiler/ProfilerMwprof.php @@ -0,0 +1,256 @@ +<?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/ProfilerSimple.php b/includes/profiler/ProfilerSimple.php deleted file mode 100644 index 805c60f4..00000000 --- a/includes/profiler/ProfilerSimple.php +++ /dev/null @@ -1,133 +0,0 @@ -<?php -/** - * Base class for simple 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 - */ - -/** - * Simple profiler base class. - * @todo document methods (?) - * @ingroup Profiler - */ -class ProfilerSimple extends Profiler { - var $mMinimumTime = 0; - - var $zeroEntry = array( 'cpu' => 0.0, 'cpu_sq' => 0.0, 'real' => 0.0, 'real_sq' => 0.0, 'count' => 0 ); - var $errorEntry; - - public function isPersistent() { - /* Implement in output subclasses */ - return false; - } - - protected function addInitialStack() { - $this->errorEntry = $this->zeroEntry; - $this->errorEntry['count'] = 1; - - $initialTime = $this->getInitialTime(); - $initialCpu = $this->getInitialTime( 'cpu' ); - if ( $initialTime !== null && $initialCpu !== null ) { - $this->mWorkStack[] = array( '-total', 0, $initialTime, $initialCpu ); - $this->mWorkStack[] = array( '-setup', 1, $initialTime, $initialCpu ); - - $this->profileOut( '-setup' ); - } else { - $this->profileIn( '-total' ); - } - } - - function setMinimum( $min ) { - $this->mMinimumTime = $min; - } - - 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(), $this->getTime( 'cpu' ) ); - } - - function profileOut( $functionname ) { - global $wgDebugFunctionEntry; - - if ( $wgDebugFunctionEntry ) { - $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . 'Exiting ' . $functionname . "\n" ); - } - - list( $ofname, /* $ocount */, $ortime, $octime ) = array_pop( $this->mWorkStack ); - - if ( !$ofname ) { - $this->debug( "Profiling error: $functionname\n" ); - } else { - if ( $functionname == 'close' ) { - $message = "Profile section ended by close(): {$ofname}"; - $functionname = $ofname; - $this->debug( "$message\n" ); - $this->mCollated[$message] = $this->errorEntry; - } - elseif ( $ofname != $functionname ) { - $message = "Profiling error: in({$ofname}), out($functionname)"; - $this->debug( "$message\n" ); - $this->mCollated[$message] = $this->errorEntry; - } - $entry =& $this->mCollated[$functionname]; - $elapsedcpu = $this->getTime( 'cpu' ) - $octime; - $elapsedreal = $this->getTime() - $ortime; - if ( !is_array( $entry ) ) { - $entry = $this->zeroEntry; - $this->mCollated[$functionname] =& $entry; - } - $entry['cpu'] += $elapsedcpu; - $entry['cpu_sq'] += $elapsedcpu * $elapsedcpu; - $entry['real'] += $elapsedreal; - $entry['real_sq'] += $elapsedreal * $elapsedreal; - $entry['count']++; - - $this->updateTrxProfiling( $functionname, $elapsedreal ); - } - } - - public function getFunctionReport() { - /* Implement in output subclasses */ - return ''; - } - - public function logData() { - /* Implement in subclasses */ - } - - /** - * Get the actual CPU time or the initial one if $ru is set. - * - * @deprecated in 1.20 - * @return float|null - */ - function getCpuTime( $ru = null ) { - wfDeprecated( __METHOD__, '1.20' ); - - if ( $ru === null ) { - return $this->getTime( 'cpu' ); - } else { - # It theory we should use $ru here, but it always $wgRUstart that is passed here - return $this->getInitialTime( 'cpu' ); - } - } -} diff --git a/includes/profiler/ProfilerSimpleDB.php b/includes/profiler/ProfilerSimpleDB.php new file mode 100644 index 00000000..7ef0ad05 --- /dev/null +++ b/includes/profiler/ProfilerSimpleDB.php @@ -0,0 +1,111 @@ +<?php +/** + * Profiler storing information in the DB. + * + * 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 + */ + +/** + * $wgProfiler['class'] = 'ProfilerSimpleDB'; + * + * @ingroup Profiler + */ +class ProfilerSimpleDB extends ProfilerStandard { + protected function collateOnly() { + return true; + } + + public function isPersistent() { + return true; + } + + /** + * Log the whole profiling data into the database. + */ + public function logData() { + global $wgProfilePerHost; + + # Do not log anything if database is readonly (bug 5375) + if ( wfReadOnly() ) { + return; + } + + if ( $wgProfilePerHost ) { + $pfhost = wfHostname(); + } else { + $pfhost = ''; + } + + try { + $this->collateData(); + + $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 ); + $memorySum = (float)$data['memory']; + $name = substr( $name, 0, 255 ); + + // Kludge + $timeSum = $timeSum >= 0 ? $timeSum : 0; + $memorySum = $memorySum >= 0 ? $memorySum : 0; + + $dbw->update( 'profiling', + 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)"; + } + if ( $useTrx ) { + $dbw->endAtomic( __METHOD__ ); + } + } catch ( DBError $e ) { + } + } +} diff --git a/includes/profiler/ProfilerSimpleText.php b/includes/profiler/ProfilerSimpleText.php index 1d57ea8d..0ee7aad2 100644 --- a/includes/profiler/ProfilerSimpleText.php +++ b/includes/profiler/ProfilerSimpleText.php @@ -31,7 +31,7 @@ * * @ingroup Profiler */ -class ProfilerSimpleText extends ProfilerSimple { +class ProfilerSimpleText extends ProfilerStandard { public $visible = false; /* Show as <PRE> or <!-- ? */ static private $out; @@ -42,6 +42,10 @@ class ProfilerSimpleText extends ProfilerSimple { parent::__construct( $profileConfig ); } + protected function collateOnly() { + return true; + } + public function logData() { if ( $this->mTemplated ) { $this->close(); diff --git a/includes/profiler/ProfilerSimpleTrace.php b/includes/profiler/ProfilerSimpleTrace.php index 5588d1e2..2a444948 100644 --- a/includes/profiler/ProfilerSimpleTrace.php +++ b/includes/profiler/ProfilerSimpleTrace.php @@ -22,63 +22,64 @@ */ /** - * Execution trace + * Execution trace profiler * @todo document methods (?) * @ingroup Profiler */ -class ProfilerSimpleTrace extends ProfilerSimple { - var $trace = "Beginning trace: \n"; - var $memory = 0; +class ProfilerSimpleTrace extends ProfilerStandard { + protected $trace = "Beginning trace: \n"; + protected $memory = 0; - function profileIn( $functionname ) { + 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"; + str_repeat( " ", count( $this->mWorkStack ) ) . " > " . $functionname . "\n"; } - function profileOut( $functionname ) { - global $wgDebugFunctionEntry; - - if ( $wgDebugFunctionEntry ) { - $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . 'Exiting ' . $functionname . "\n" ); - } + public function profileOut( $functionname ) { + $item = end( $this->mWorkStack ); - list( $ofname, /* $ocount */, $ortime ) = array_pop( $this->mWorkStack ); + parent::profileOut( $functionname ); - if ( !$ofname ) { + 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 ) { + } 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"; - - $this->updateTrxProfiling( $functionname, $elapsedreal ); + str_repeat( " ", count( $this->mWorkStack ) + 1 ) . " < " . $functionname . "\n"; } } - function memoryDiff() { + protected function memoryDiff() { $diff = memory_get_usage() - $this->memory; $this->memory = memory_get_usage(); return $diff / 1024; } - function logData() { - 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*/"; + 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 index 0a1f3b10..627b4de2 100644 --- a/includes/profiler/ProfilerSimpleUDP.php +++ b/includes/profiler/ProfilerSimpleUDP.php @@ -23,10 +23,15 @@ /** * ProfilerSimpleUDP class, that sends out messages for 'udpprofile' daemon - * (the one from mediawiki/trunk/udpprofile SVN ) + * (the one from + * http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile) * @ingroup Profiler */ -class ProfilerSimpleUDP extends ProfilerSimple { +class ProfilerSimpleUDP extends ProfilerStandard { + protected function collateOnly() { + return true; + } + public function isPersistent() { return true; } @@ -36,11 +41,6 @@ class ProfilerSimpleUDP extends ProfilerSimple { $this->close(); - if ( isset( $this->mCollated['-total'] ) && $this->mCollated['-total']['real'] < $this->mMinimumTime ) { - # Less than minimum, ignore - return; - } - if ( !function_exists( 'socket_create' ) ) { # Sockets are not enabled return; @@ -58,7 +58,8 @@ class ProfilerSimpleUDP extends ProfilerSimple { continue; } $pfline = sprintf( $wgUDPProfilerFormatString, $this->getProfileID(), $pfdata['count'], - $pfdata['cpu'], $pfdata['cpu_sq'], $pfdata['real'], $pfdata['real_sq'], $entry ); + $pfdata['cpu'], $pfdata['cpu_sq'], $pfdata['real'], $pfdata['real_sq'], $entry, + $pfdata['memory'] ); $length = strlen( $pfline ); /* printf("<!-- $pfline -->"); */ if ( $length + $plength > 1400 ) { diff --git a/includes/profiler/ProfilerStandard.php b/includes/profiler/ProfilerStandard.php new file mode 100644 index 00000000..cc134165 --- /dev/null +++ b/includes/profiler/ProfilerStandard.php @@ -0,0 +1,559 @@ +<?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 3697f352..1d3b65d2 100644 --- a/includes/profiler/ProfilerStub.php +++ b/includes/profiler/ProfilerStub.php @@ -30,15 +30,37 @@ class ProfilerStub extends Profiler { public function isStub() { return true; } + public function isPersistent() { return false; } - public function profileIn( $fn ) {} - public function profileOut( $fn ) {} - public function getOutput() {} - public function close() {} - public function logData() {} - public function getCurrentSection() { return ''; } - public function transactionWritingIn( $server, $db ) {} - public function transactionWritingOut( $server, $db ) {} + + public function profileIn( $fn ) { + } + + public function profileOut( $fn ) { + } + + public function getOutput() { + } + + 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(); + } } |