From afa6af07d7236e868b80bebf0c80ed131db592c3 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Wed, 9 Apr 2014 15:43:12 -0700 Subject: [PATCH] Profiler class refactoring * Merged the "collate at end" and "running collate" logic into the base class to make it more unified and consistent. * Pulled out DB code into ProfilerSimpleDB class. * Removed the ProfilerSimple class and updated child classes. * Made ProfilerSimpleTrace set the debug information too. * Work around "ended by close()" bug from 99aef03f. Since the getRawData() method gets called while some wfProfileOut() calls have not yet happened, make it use the matched call data and let the final logData() method work on the full data as normal. * Let ProfilerSimple classes use getFunctionReport() for the profiler debug log if it is setup instead of making it just return "". * Made getRawData() work as best as possible with ProfilerMwprof. * Removed $wgProfileToDatabase since it is now useless. * Improved DB profile performance with sqlite. * Updated visibility of various methods. Change-Id: I1260bab2b5ba12dccbba701bcae4a637cb85c6e8 --- RELEASE-NOTES-1.23 | 2 + includes/AutoLoader.php | 2 +- includes/DefaultSettings.php | 12 - includes/profiler/Profiler.php | 439 +++++++++++++--------- includes/profiler/ProfilerMwprof.php | 99 ++++- includes/profiler/ProfilerSimple.php | 140 ------- includes/profiler/ProfilerSimpleDB.php | 110 ++++++ includes/profiler/ProfilerSimpleText.php | 6 +- includes/profiler/ProfilerSimpleTrace.php | 59 +-- includes/profiler/ProfilerSimpleUDP.php | 8 +- 10 files changed, 500 insertions(+), 377 deletions(-) delete mode 100644 includes/profiler/ProfilerSimple.php create mode 100644 includes/profiler/ProfilerSimpleDB.php diff --git a/RELEASE-NOTES-1.23 b/RELEASE-NOTES-1.23 index 754c177002..08fb7a2964 100644 --- a/RELEASE-NOTES-1.23 +++ b/RELEASE-NOTES-1.23 @@ -148,6 +148,8 @@ production. process the result set prior to rendering. * A PoolCounterRedis class was added which can be make use of in $wgPoolCounterConf. This requires at least one Redis 2.6+ server. +* $wgProfileToDatabase was removed. Set $wgProfiler to ProfilerSimpleDB + in StartProfiler.php instead of using this. === Bug fixes in 1.23 === * (bug 41759) The "updated since last visit" markers (on history pages, recent diff --git a/includes/AutoLoader.php b/includes/AutoLoader.php index 6675860091..923c8d1ae0 100644 --- a/includes/AutoLoader.php +++ b/includes/AutoLoader.php @@ -831,7 +831,7 @@ $wgAutoloadLocalClasses = array( # includes/profiler 'Profiler' => 'includes/profiler/Profiler.php', 'ProfilerMwprof' => 'includes/profiler/ProfilerMwprof.php', - 'ProfilerSimple' => 'includes/profiler/ProfilerSimple.php', + 'ProfilerSimpleDB' => 'includes/profiler/ProfilerSimpleDB.php', 'ProfilerSimpleText' => 'includes/profiler/ProfilerSimpleText.php', 'ProfilerSimpleTrace' => 'includes/profiler/ProfilerSimpleTrace.php', 'ProfilerSimpleUDP' => 'includes/profiler/ProfilerSimpleUDP.php', diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php index f086107e2b..663098f91b 100644 --- a/includes/DefaultSettings.php +++ b/includes/DefaultSettings.php @@ -5092,18 +5092,6 @@ $wgProfileLimit = 0.0; */ $wgProfileOnly = false; -/** - * Log sums from profiling into "profiling" table in db. - * - * You have to create a 'profiling' table in your database before using - * this feature. Run set $wgProfileToDatabase to true in - * LocalSettings.php and run maintenance/update.php or otherwise - * manually add patch-profiling.sql to your database. - * - * To enable profiling, edit StartProfiler.php - */ -$wgProfileToDatabase = false; - /** * If true, print a raw call tree instead of per-function report */ diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index f992d83fdb..02367e14de 100644 --- a/includes/profiler/Profiler.php +++ b/includes/profiler/Profiler.php @@ -95,21 +95,41 @@ class ProfileSection { * @todo document */ class Profiler { - protected $mStack = array(), $mWorkStack = array(), $mCollated = array(), - $mCalls = array(), $mTotals = array(), $mPeriods = array(); + /** @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; + + /** @var string wall|cpu|user */ protected $mTimeMetric = 'wall'; - protected $mProfileID = false, $mCollateDone = false, $mTemplated = false; + /** @var string|bool Profiler ID for bucketing data */ + protected $mProfileID = false; + /** @var bool Whether MediaWiki is in a SkinTemplate output context */ + protected $mTemplated = false; - protected $mDBLockThreshold = 5.0; // float; seconds + /** @var float seconds */ + protected $mDBLockThreshold = 5.0; /** @var Array DB/server name => (active trx count,timestamp) */ protected $mDBTrxHoldingLocks = array(); - /** @var Array DB/server name => list of (method, elapsed time) */ + /** @var Array DB/server name => list of (function name, elapsed time) */ protected $mDBTrxMethodTimes = array(); /** @var Profiler */ public static $__instance = null; // do not call this outside Profiler and ProfileSection - function __construct( $params ) { + /** + * @param array $params + */ + public function __construct( array $params ) { if ( isset( $params['timeMetric'] ) ) { $this->mTimeMetric = $params['timeMetric']; } @@ -117,6 +137,8 @@ class Profiler { $this->mProfileID = $params['profileID']; } + $this->mCollateOnly = $this->collateOnly(); + $this->addInitialStack(); } @@ -167,13 +189,19 @@ class Profiler { * @return Boolean */ public function isPersistent() { - return true; + return false; } + /** + * @param string $id + */ public function setProfileID( $id ) { $this->mProfileID = $id; } + /** + * @return string + */ public function getProfileID() { if ( $this->mProfileID === false ) { return wfWikiID(); @@ -182,20 +210,101 @@ class Profiler { } } + /** + * Whether to internally just track aggregates and ignore the full stack trace + * + * @return boolean + */ + protected function collateOnly() { + return false; + } + /** * 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 ); + $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 integer $memChange + * @param integer $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() * @@ -203,11 +312,19 @@ class Profiler { */ public function profileIn( $functionname ) { global $wgDebugFunctionEntry; + if ( $wgDebugFunctionEntry ) { - $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Entering ' . $functionname . "\n" ); + $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) . + 'Entering ' . $functionname . "\n" ); } - $this->mWorkStack[] = array( $functionname, count( $this->mWorkStack ), $this->getTime(), memory_get_usage() ); + $this->mWorkStack[] = array( + $functionname, + count( $this->mWorkStack ), + $this->getTime( 'time' ), + $this->getTime( 'cpu' ), + memory_get_usage() + ); } /** @@ -217,33 +334,50 @@ class Profiler { */ 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" ); + $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . + 'Exiting ' . $functionname . "\n" ); } - $bit = array_pop( $this->mWorkStack ); + $item = array_pop( $this->mWorkStack ); + list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item; - if ( !$bit ) { - $this->debugGroup( 'profileerror', "Profiling error, !\$bit: $functionname" ); + if ( $item === null ) { + $this->debugGroup( 'profileerror', "Profiling error: $functionname" ); } else { - if ( $functionname == 'close' ) { - if ( $bit[0] != '-total' ) { - $message = "Profile section ended by close(): {$bit[0]}"; + if ( $functionname === 'close' ) { + if ( $ofname !== '-total' ) { + $message = "Profile section ended by close(): {$ofname}"; $this->debugGroup( 'profileerror', $message ); - $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 ); + if ( $this->mCollateOnly ) { + $this->mCollated[$message] = $this->mErrorEntry; + } else { + $this->mStack[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ); + } } - } elseif ( $bit[0] != $functionname ) { - $message = "Profiling error: in({$bit[0]}), out($functionname)"; + $functionname = $ofname; + } elseif ( $ofname !== $functionname ) { + $message = "Profiling error: in({$ofname}), out($functionname)"; $this->debugGroup( 'profileerror', $message ); - $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 ); + 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() ) ); } - $bit[] = $time; - $bit[] = $memory; - $this->mStack[] = $bit; - $this->updateTrxProfiling( $functionname, $time ); + $this->updateTrxProfiling( $functionname, $realTime - $ortime ); } } @@ -256,6 +390,13 @@ class Profiler { } } + /** + * Log the data to some store or even the page output + */ + public function logData() { + /* Implement in subclasses */ + } + /** * Mark a DB as in a transaction with one or more writes pending * @@ -338,7 +479,7 @@ class Profiler { * * @param $t Boolean */ - function setTemplated( $t ) { + public function setTemplated( $t ) { $this->mTemplated = $t; } @@ -349,7 +490,8 @@ class Profiler { */ public function getOutput() { global $wgDebugFunctionEntry, $wgProfileCallTree; - $wgDebugFunctionEntry = false; + + $wgDebugFunctionEntry = false; // hack if ( !count( $this->mStack ) && !count( $this->mCollated ) ) { return "No profiling output\n"; @@ -366,8 +508,10 @@ class Profiler { * Returns a tree of function call instead of a list of functions * @return string */ - function getCallTree() { - return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) ) ); + protected function getCallTree() { + return implode( '', array_map( + array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) + ) ); } /** @@ -376,7 +520,7 @@ class Profiler { * @param array $stack profiling array * @return array */ - function remapCallTree( $stack ) { + protected function remapCallTree( array $stack ) { if ( count( $stack ) < 2 ) { return $stack; } @@ -415,13 +559,14 @@ class Profiler { * Callback to get a formatted line for the call tree * @return string */ - function getCallTreeLine( $entry ) { - list( $fname, $level, $start, /* $x */, $end ) = $entry; - $delta = $end - $start; + 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 ); + return sprintf( "%10s %s %s\n", + trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname ); } /** @@ -435,7 +580,7 @@ class Profiler { * - false (default): will fall back to default metric * @return float|null */ - function getTime( $metric = false ) { + protected function getTime( $metric = false ) { if ( $metric === false ) { $metric = $this->mTimeMetric; } @@ -496,17 +641,21 @@ class Profiler { } } + /** + * Populate mCollated + */ protected function collateData() { if ( $this->mCollateDone ) { return; } $this->mCollateDone = true; + $this->close(); // set "-total" entry - $this->close(); + if ( $this->mCollateOnly ) { + return; // already collated as methods exited + } $this->mCollated = array(); - $this->mCalls = array(); - $this->mMemory = array(); # Estimate profiling overhead $profileCount = count( $this->mStack ); @@ -515,62 +664,49 @@ class Profiler { # 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]; - $start = $entry[2]; - $end = $entry[4]; - $elapsed = $end - $start; - $memory = $entry[5] - $entry[3]; + $elapsed = $entry[5] - $entry[2]; + $memchange = $entry[7] - $entry[4]; - if ( $fname == '-overhead-total' ) { + if ( $fname === '-overhead-total' ) { $overheadTotal[] = $elapsed; - $overheadMemory[] = $memory; - } elseif ( $fname == '-overhead-internal' ) { + $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; + $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]; - $start = $entry[2]; - $end = $entry[4]; - $elapsed = $end - $start; - - $memory = $entry[5] - $entry[3]; + $elapsedCpu = $entry[6] - $entry[3]; + $elapsedReal = $entry[5] - $entry[2]; + $memchange = $entry[7] - $entry[4]; $subcalls = $this->calltreeCount( $this->mStack, $index ); - if ( !preg_match( '/^-overhead/', $fname ) ) { + if ( substr( $fname, 0, 9 ) !== '-overhead' ) { # Adjust for profiling overhead (except special values with elapsed=0 if ( $elapsed ) { $elapsed -= $overheadInternal; $elapsed -= ( $subcalls * $overheadTotal ); - $memory -= ( $subcalls * $overheadMemory ); + $memchange -= ( $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->mPeriods[$fname] = array(); - } - - $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->mPeriods[$fname][] = compact( 'start', 'end', 'memory', 'subcalls' ); + $period = array( 'start' => $entry[2], 'end' => $entry[5], + 'memory' => $memchange, 'subcalls' => $subcalls ); + $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange, $subcalls, $period ); } - $this->mCalls['-overhead-total'] = $profileCount; + $this->mCollated['-overhead-total']['count'] = $profileCount; arsort( $this->mCollated, SORT_NUMERIC ); } @@ -579,7 +715,7 @@ class Profiler { * * @return string */ - function getFunctionReport() { + protected function getFunctionReport() { $this->collateData(); $width = 140; @@ -589,22 +725,24 @@ class Profiler { $prof = "\nProfiling data\n"; $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' ); - $total = isset( $this->mCollated['-total'] ) ? $this->mCollated['-total'] : 0; + $total = isset( $this->mCollated['-total'] ) + ? $this->mCollated['-total']['real'] + : 0; - foreach ( $this->mCollated as $fname => $elapsed ) { - $calls = $this->mCalls[$fname]; - $percent = $total ? 100. * $elapsed / $total : 0; - $memory = $this->mMemory[$fname]; + 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)( $elapsed * 1000 ), - (float)( $elapsed * 1000 ) / $calls, + (float)( $data['real'] * 1000 ), + (float)( $data['real'] * 1000 ) / $calls, $percent, $memory, - ( $this->mMin[$fname] * 1000.0 ), - ( $this->mMax[$fname] * 1000.0 ), - $this->mOverhead[$fname] + ( $data['min_real'] * 1000.0 ), + ( $data['max_real'] * 1000.0 ), + $data['overhead'] ); } $prof .= "\nTotal: $total\n\n"; @@ -616,27 +754,48 @@ class Profiler { * @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(); - $total = isset( $this->mCollated['-total'] ) ? $this->mCollated['-total'] : 0; - foreach ( $this->mCollated as $fname => $elapsed ) { + foreach ( $this->mCollated as $fname => $data ) { $periods = array(); - foreach ( $this->mPeriods[$fname] as $period ) { + foreach ( $data['periods'] as $period ) { $period['start'] *= 1000; $period['end'] *= 1000; $periods[] = $period; } $profile[] = array( 'name' => $fname, - 'calls' => $this->mCalls[$fname], - 'elapsed' => $elapsed * 1000, - 'percent' => $total ? 100. * $elapsed / $total : 0, - 'memory' => $this->mMemory[$fname], - 'min' => $this->mMin[$fname] * 1000, - 'max' => $this->mMax[$fname] * 1000, - 'overhead' => $this->mOverhead[$fname], - 'periods' => $periods, + '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 ); } @@ -662,9 +821,8 @@ class Profiler { * @param $stack Array: * @param $start Integer: * @return Integer - * @private */ - function calltreeCount( $stack, $start ) { + protected function calltreeCount( $stack, $start ) { $level = $stack[$start][1]; $count = 0; for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) { @@ -673,83 +831,12 @@ class Profiler { return $count; } - /** - * Log the whole profiling data into the database. - */ - 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; - } - - if ( $wgProfilePerHost ) { - $pfhost = wfHostname(); - } else { - $pfhost = ''; - } - - 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 * * @param string $s to output */ - function debug( $s ) { + protected function debug( $s ) { if ( function_exists( 'wfDebug' ) ) { wfDebug( $s ); } @@ -761,7 +848,7 @@ class Profiler { * @param string $group Group to send the message to * @param string $s to output */ - function debugGroup( $group, $s ) { + protected function debugGroup( $group, $s ) { if ( function_exists( 'wfDebugLog' ) ) { wfDebugLog( $group, $s ); } diff --git a/includes/profiler/ProfilerMwprof.php b/includes/profiler/ProfilerMwprof.php index e7ed6e35e5..67b6034b8c 100644 --- a/includes/profiler/ProfilerMwprof.php +++ b/includes/profiler/ProfilerMwprof.php @@ -33,12 +33,14 @@ * @since 1.23 */ class ProfilerMwprof extends Profiler { - // Message types - const TYPE_SINGLE = 1; const TYPE_RUNNING = 2; + protected function collateOnly() { + return false; + } + /** * Indicate that this Profiler subclass is persistent. * @@ -62,18 +64,7 @@ class ProfilerMwprof extends Profiler { */ public function profileIn( $inName ) { $this->mWorkStack[] = array( $inName, count( $this->mWorkStack ), - $this->getTime(), $this->getTime( 'cpu' ) ); - } - - /** - * Produce an empty function report. - * - * ProfileMwprof does not provide a function report. - * - * @return string Empty string. - */ - public function getFunctionReport() { - return ''; + $this->getTime(), $this->getTime( 'cpu' ), 0 ); } /** @@ -96,7 +87,7 @@ class ProfilerMwprof extends Profiler { $elapsedCpu = $this->getTime( 'cpu' ) - $inCpu; $elapsedWall = $this->getTime() - $inWall; - $this->updateEntry( $outName, $elapsedCpu, $elapsedWall ); + $this->updateRunningEntry( $outName, $elapsedCpu, $elapsedWall ); $this->updateTrxProfiling( $outName, $elapsedWall ); } @@ -107,7 +98,7 @@ class ProfilerMwprof extends Profiler { * @param float $elapsedCpu elapsed CPU time * @param float $elapsedWall elapsed wall-clock time */ - public function updateEntry( $name, $elapsedCpu, $elapsedWall ) { + 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] ) ) { @@ -138,6 +129,77 @@ class ProfilerMwprof extends Profiler { $entry['wall']->push( $elapsedWall ); } + /** + * Produce an empty function report. + * + * ProfileMwprof does not provide a function report. + * + * @return string Empty string. + */ + public function getFunctionReport() { + return ''; + } + + /** + * @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; + $z+= $item['percent']; + } + + return $profile; + } + /** * Serialize profiling data and send to a profiling data aggregator. * @@ -151,6 +213,11 @@ class ProfilerMwprof extends Profiler { $this->close(); + if ( !function_exists( 'socket_create' ) ) { + #trigger_error( __METHOD__ . ": function \"socket_create\" not found." ); + return; // avoid fatal + } + $sock = socket_create( AF_INET, SOCK_DGRAM, SOL_UDP ); socket_connect( $sock, $wgUDPProfilerHost, $wgUDPProfilerPort ); $bufferLength = 0; diff --git a/includes/profiler/ProfilerSimple.php b/includes/profiler/ProfilerSimple.php deleted file mode 100644 index 36f4bd45ec..0000000000 --- a/includes/profiler/ProfilerSimple.php +++ /dev/null @@ -1,140 +0,0 @@ - 0.0, - 'cpu_sq' => 0.0, - 'real' => 0.0, - 'real_sq' => 0.0, - 'count' => 0 - ); - } - - public function getErrorEntry() { - $entry = $this->getZeroEntry(); - $entry['count'] = 1; - return $entry; - } - - public function updateEntry( $name, $elapsedCpu, $elapsedReal ) { - $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['count']++; - } - - public function isPersistent() { - /* Implement in output subclasses */ - return false; - } - - protected function addInitialStack() { - $this->errorEntry = $this->getErrorEntry(); - - $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->debugGroup( 'profileerror', "Profiling error: $functionname" ); - } else { - if ( $functionname == 'close' ) { - if ( $ofname != '-total' ) { - $message = "Profile section ended by close(): {$ofname}"; - $this->debugGroup( 'profileerror', $message ); - $this->mCollated[$message] = $this->errorEntry; - } - $functionname = $ofname; - } elseif ( $ofname != $functionname ) { - $message = "Profiling error: in({$ofname}), out($functionname)"; - $this->debugGroup( 'profileerror', $message ); - $this->mCollated[$message] = $this->errorEntry; - } - $elapsedcpu = $this->getTime( 'cpu' ) - $octime; - $elapsedreal = $this->getTime() - $ortime; - $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal ); - $this->updateTrxProfiling( $functionname, $elapsedreal ); - } - } - - public function getRawData() { - // Calling the method of the parent class results in fatal error. - // @todo Implement this correctly. - return array(); - } - - public function getFunctionReport() { - /* Implement in output subclasses */ - return ''; - } - - public function logData() { - /* Implement in subclasses */ - } -} diff --git a/includes/profiler/ProfilerSimpleDB.php b/includes/profiler/ProfilerSimpleDB.php new file mode 100644 index 0000000000..e35eec1240 --- /dev/null +++ b/includes/profiler/ProfilerSimpleDB.php @@ -0,0 +1,110 @@ +collateData(); + + $dbw = wfGetDB( DB_MASTER ); + $useTrx = ( $dbw->getType() === 'sqlite' ); // much faster + if ( $useTrx ) { + $dbw->begin(); + } + 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->commit(); + } + } catch ( DBError $e ) {} + } +} diff --git a/includes/profiler/ProfilerSimpleText.php b/includes/profiler/ProfilerSimpleText.php index 1d57ea8d97..975d260af1 100644 --- a/includes/profiler/ProfilerSimpleText.php +++ b/includes/profiler/ProfilerSimpleText.php @@ -31,7 +31,7 @@ * * @ingroup Profiler */ -class ProfilerSimpleText extends ProfilerSimple { +class ProfilerSimpleText extends Profiler { public $visible = false; /* Show as 
 or ";
-		} elseif ( $this->getContentType() === 'text/html' ) {
-			print "";
-		} 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 "";
+			} elseif ( $this->getContentType() === 'text/html' ) {
+				print "";
+			} 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 982c6aec87..e9bcff6414 100644
--- a/includes/profiler/ProfilerSimpleUDP.php
+++ b/includes/profiler/ProfilerSimpleUDP.php
@@ -27,7 +27,11 @@
  *  http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile)
  * @ingroup Profiler
  */
-class ProfilerSimpleUDP extends ProfilerSimple {
+class ProfilerSimpleUDP extends Profiler {
+	protected function collateOnly() {
+		return true;
+	}
+
 	public function isPersistent() {
 		return true;
 	}
@@ -37,7 +41,7 @@ class ProfilerSimpleUDP extends ProfilerSimple {
 
 		$this->close();
 
-		if ( isset( $this->mCollated['-total'] ) && $this->mCollated['-total']['real'] < $this->mMinimumTime ) {
+		if ( isset( $this->mCollated['-total'] ) ) {
 			# Less than minimum, ignore
 			return;
 		}
-- 
2.20.1