From: Alexandre Emsenhuber Date: Thu, 21 Apr 2011 16:31:02 +0000 (+0000) Subject: * Added Profiler::isStub() to check if we are using a stub profiler, instead of check... X-Git-Tag: 1.31.0-rc.0~30647 X-Git-Url: http://git.cyclocoop.org/%7B%24www_url%7Dadmin/compta/pie.php?a=commitdiff_plain;h=21e53d35908782d3f467658ce69abd20ae7c8237;p=lhc%2Fweb%2Fwiklou.git * Added Profiler::isStub() to check if we are using a stub profiler, instead of checking whether $wgProfiler is set * Replaced wfProfileClose() and wfGetProfilingOutput() by direct calls to the Profiler instance and removed them, no uses in extensions * Also removed useless params from Profiler::getOutput() call in wfLogProfilingData() * Only generate profiling output if it'll be used; introduced Profiler::logData() that saves profiling data (database, udp, ...) to separate it from output generation * Removed unused Profiler::getCaller(), not used at all, and we have wfGetCaller() that does the same thing --- diff --git a/includes/GlobalFunctions.php b/includes/GlobalFunctions.php index e93cc02dbf..357a64bf1b 100644 --- a/includes/GlobalFunctions.php +++ b/includes/GlobalFunctions.php @@ -342,43 +342,56 @@ function wfErrorLog( $text, $file ) { */ function wfLogProfilingData() { global $wgRequestTime, $wgDebugLogFile, $wgDebugRawPage, $wgRequest; - global $wgProfiler, $wgProfileLimit, $wgUser; + global $wgProfileLimit, $wgUser; + + $profiler = Profiler::instance(); + # Profiling must actually be enabled... - if( is_null( $wgProfiler ) ) { + if ( $profiler->isStub() ) { return; } - # Get total page request time + + // Get total page request time and only show pages that longer than + // $wgProfileLimit time (default is 0) $now = wfTime(); $elapsed = $now - $wgRequestTime; - # Only show pages that longer than $wgProfileLimit time (default is 0) - if( $elapsed <= $wgProfileLimit ) { + if ( $elapsed <= $wgProfileLimit ) { + return; + } + + $profiler->logData(); + + // Check whether this should be logged in the debug file. + // This have to be done after calling getOutput() since that call may log + // data in the database or send to a remote host and we want that even if + // it won't be send to the debug file. + if ( $wgDebugLogFile == '' || ( $wgRequest->getVal( 'action' ) == 'raw' && !$wgDebugRawPage ) ) { return; } - $prof = wfGetProfilingOutput( $wgRequestTime, $elapsed ); + $forward = ''; - if( !empty( $_SERVER['HTTP_X_FORWARDED_FOR'] ) ) { + if ( !empty( $_SERVER['HTTP_X_FORWARDED_FOR'] ) ) { $forward = ' forwarded for ' . $_SERVER['HTTP_X_FORWARDED_FOR']; } - if( !empty( $_SERVER['HTTP_CLIENT_IP'] ) ) { + if ( !empty( $_SERVER['HTTP_CLIENT_IP'] ) ) { $forward .= ' client IP ' . $_SERVER['HTTP_CLIENT_IP']; } - if( !empty( $_SERVER['HTTP_FROM'] ) ) { + if ( !empty( $_SERVER['HTTP_FROM'] ) ) { $forward .= ' from ' . $_SERVER['HTTP_FROM']; } - if( $forward ) { + if ( $forward ) { $forward = "\t(proxied via {$_SERVER['REMOTE_ADDR']}{$forward})"; } // Don't unstub $wgUser at this late stage just for statistics purposes // FIXME: We can detect some anons even if it is not loaded. See User::getId() - if( $wgUser->mDataLoaded && $wgUser->isAnon() ) { + if ( $wgUser->mDataLoaded && $wgUser->isAnon() ) { $forward .= ' anon'; } $log = sprintf( "%s\t%04.3f\t%s\n", gmdate( 'YmdHis' ), $elapsed, urldecode( $wgRequest->getRequestURL() . $forward ) ); - if ( $wgDebugLogFile != '' && ( $wgRequest->getVal( 'action' ) != 'raw' || $wgDebugRawPage ) ) { - wfErrorLog( $log . $prof, $wgDebugLogFile ); - } + + wfErrorLog( $log . $profiler->getOutput(), $wgDebugLogFile ); } /** diff --git a/includes/api/ApiBase.php b/includes/api/ApiBase.php index fe6ce54645..5e9419f848 100644 --- a/includes/api/ApiBase.php +++ b/includes/api/ApiBase.php @@ -946,7 +946,7 @@ abstract class ApiBase { * @param $extradata array Data to add to the element; array in ApiResult format */ public function dieUsage( $description, $errorCode, $httpRespCode = 0, $extradata = null ) { - wfProfileClose(); + Profiler::instance()->close(); throw new UsageException( $description, $this->encodeParamName( $errorCode ), $httpRespCode, $extradata ); } diff --git a/includes/db/Database.php b/includes/db/Database.php index 70e513c6ac..53e358583d 100644 --- a/includes/db/Database.php +++ b/includes/db/Database.php @@ -638,10 +638,8 @@ abstract class DatabaseBase implements DatabaseType { * @throws DBQueryError Thrown when the database returns an error of any kind */ public function query( $sql, $fname = '', $tempIgnore = false ) { - global $wgProfiler; - $isMaster = !is_null( $this->getLBInfo( 'master' ) ); - if ( isset( $wgProfiler ) ) { + if ( !Profiler::instance()->isStub() ) { # generalizeSQL will probably cut down the query to reasonable # logging size most of the time. The substr is really just a sanity check. @@ -742,7 +740,7 @@ abstract class DatabaseBase implements DatabaseType { $this->reportQueryError( $this->lastError(), $this->lastErrno(), $sql, $fname, $tempIgnore ); } - if ( isset( $wgProfiler ) ) { + if ( !Profiler::instance()->isStub() ) { wfProfileOut( $queryProf ); wfProfileOut( $totalProf ); } diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index 043da15a10..4ad0d2a600 100644 --- a/includes/profiler/Profiler.php +++ b/includes/profiler/Profiler.php @@ -32,20 +32,6 @@ function wfProfileOut( $functionname = 'missing' ) { Profiler::instance()->profileOut( $functionname ); } -/** - * Returns a profiling output to be stored in debug file - */ -function wfGetProfilingOutput() { - Profiler::instance()->getOutput(); -} - -/** - * Close opened profiling sections - */ -function wfProfileClose() { - Profiler::instance()->close(); -} - /** * @ingroup Profiler * @todo document @@ -54,6 +40,7 @@ class Profiler { var $mStack = array (), $mWorkStack = array (), $mCollated = array (); var $mCalls = array (), $mTotals = array (); var $mTemplated = false; + private $mCollateDone = false; protected $mProfileID = false; private static $__instance = null; @@ -96,6 +83,15 @@ class Profiler { self::$__instance = $p; } + /** + * Return whether this a stub profiler + * + * @return Boolean + */ + public function isStub() { + return false; + } + public function setProfileID( $id ) { $this->mProfileID = $id; } @@ -160,7 +156,7 @@ class Profiler { } /** - * called by wfProfileClose() + * Close opened profiling sections */ public function close() { while( count( $this->mWorkStack ) ){ @@ -178,7 +174,9 @@ class Profiler { } /** - * Called by wfGetProfilingOutput() + * Returns a profiling output to be stored in debug file + * + * @return String */ public function getOutput() { global $wgDebugFunctionEntry, $wgProfileCallTree; @@ -187,14 +185,8 @@ class Profiler { if( !count( $this->mStack ) && !count( $this->mCollated ) ){ return "No profiling output\n"; } - $this->close(); if( $wgProfileCallTree ) { - global $wgProfileToDatabase; - # XXX: We must call $this->getFunctionReport() to log to the DB - if( $wgProfileToDatabase ) { - $this->getFunctionReport(); - } return $this->getCallTree(); } else { return $this->getFunctionReport(); @@ -270,22 +262,17 @@ class Profiler { return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6; } - /** - * Returns a list of profiled functions. - * Also log it into the database if $wgProfileToDatabase is set to true. - */ - function getFunctionReport() { - global $wgProfileToDatabase; + protected function collateData() { + if ( $this->mCollateDone ) { + return; + } + $this->mCollateDone = true; - $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' ); - $this->mCollated = array (); - $this->mCalls = array (); - $this->mMemory = array (); + $this->close(); + + $this->mCollated = array(); + $this->mCalls = array(); + $this->mMemory = array(); # Estimate profiling overhead $profileCount = count($this->mStack); @@ -348,20 +335,31 @@ class Profiler { $this->mOverhead[$fname] += $subcalls; } - $total = @$this->mCollated['-total']; $this->mCalls['-overhead-total'] = $profileCount; - - # Output arsort( $this->mCollated, SORT_NUMERIC ); + } + + /** + * Returns a list of profiled functions. + * Also log it into the database if $wgProfileToDatabase is set to true. + */ + 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 = @$this->mCollated['-total']; + 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]); - # Log to the DB - if( $wgProfileToDatabase ) { - self::logToDB($fname, (float) ($elapsed * 1000), $calls, (float) ($memory) ); - } } $prof .= "\nTotal: $total\n\n"; @@ -399,60 +397,66 @@ class Profiler { } /** - * Log a function into the database. - * - * @param $name String: function name - * @param $timeSum Float - * @param $eventCount Integer: number of times that function was called - * @param $memorySum Integer: memory used by the function + * Log the whole profiling data into the database. */ - static function logToDB( $name, $timeSum, $eventCount, $memorySum ){ - # Do not log anything if database is readonly (bug 5375) - if( wfReadOnly() ) { return; } + public function logData(){ + global $wgProfilePerHost, $wgProfileToDatabase; - global $wgProfilePerHost; + # Do not log anything if database is readonly (bug 5375) + if( wfReadOnly() || !$wgProfileToDatabase ) { + return; + } $dbw = wfGetDB( DB_MASTER ); - if( !is_object( $dbw ) ) - return false; - $errorState = $dbw->ignoreErrors( true ); + if( !is_object( $dbw ) ) { + return; + } - $name = substr($name, 0, 255); + $errorState = $dbw->ignoreErrors( true ); if( $wgProfilePerHost ){ $pfhost = wfHostname(); } else { $pfhost = ''; } - - // 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')); + + $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)"; } - // 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)"; + $dbw->ignoreErrors( $errorState ); } @@ -464,25 +468,6 @@ class Profiler { return $elt[0]; } - /** - * Get function caller - * - * @param $level Integer - */ - static function getCaller( $level ) { - $backtrace = wfDebugBacktrace(); - if ( isset( $backtrace[$level] ) ) { - if ( isset( $backtrace[$level]['class'] ) ) { - $caller = $backtrace[$level]['class'] . '::' . $backtrace[$level]['function']; - } else { - $caller = $backtrace[$level]['function']; - } - } else { - $caller = 'unknown'; - } - return $caller; - } - /** * Add an entry in the debug log file * diff --git a/includes/profiler/ProfilerSimple.php b/includes/profiler/ProfilerSimple.php index 35cbae0f32..8f1c621519 100644 --- a/includes/profiler/ProfilerSimple.php +++ b/includes/profiler/ProfilerSimple.php @@ -86,8 +86,13 @@ class ProfilerSimple extends Profiler { } } - function getFunctionReport() { + public function getFunctionReport() { /* Implement in output subclasses */ + return ''; + } + + public function logData() { + /* Implement in subclasses */ } function getCpuTime($ru=null) { diff --git a/includes/profiler/ProfilerSimpleText.php b/includes/profiler/ProfilerSimpleText.php index 5bdc0e3862..1165f24b0f 100644 --- a/includes/profiler/ProfilerSimpleText.php +++ b/includes/profiler/ProfilerSimpleText.php @@ -25,8 +25,9 @@ class ProfilerSimpleText extends ProfilerSimple { parent::__construct(); } - function getFunctionReport() { + public function logData() { if($this->mTemplated) { + $this->collateData(); uasort($this->mCollated,array('self','sort')); array_walk($this->mCollated,array('self','format')); if ($this->visible) { diff --git a/includes/profiler/ProfilerSimpleUDP.php b/includes/profiler/ProfilerSimpleUDP.php index 45166ca501..c11c3205f0 100644 --- a/includes/profiler/ProfilerSimpleUDP.php +++ b/includes/profiler/ProfilerSimpleUDP.php @@ -10,10 +10,12 @@ * @ingroup Profiler */ class ProfilerSimpleUDP extends ProfilerSimple { - function getFunctionReport() { + public function logData() { global $wgUDPProfilerHost, $wgUDPProfilerPort; - if ( $this->mCollated['-total']['real'] < $this->mMinimumTime ) { + $this->collateData(); + + if ( isset( $this->mCollated['-total'] ) && $this->mCollated['-total']['real'] < $this->mMinimumTime ) { # Less than minimum, ignore return; } diff --git a/includes/profiler/ProfilerStub.php b/includes/profiler/ProfilerStub.php index b17e81aa4a..5c826090e0 100644 --- a/includes/profiler/ProfilerStub.php +++ b/includes/profiler/ProfilerStub.php @@ -20,6 +20,10 @@ class ProfilerStub extends Profiler { $this->haveProctitle = function_exists( 'setproctitle' ); } + public function isStub() { + return true; + } + /** * Begin profiling of a function * @param $fn string