| Index: trunk/phase3/includes/GlobalFunctions.php |
| — | — | @@ -342,43 +342,56 @@ |
| 343 | 343 | */ |
| 344 | 344 | function wfLogProfilingData() { |
| 345 | 345 | global $wgRequestTime, $wgDebugLogFile, $wgDebugRawPage, $wgRequest; |
| 346 | | - global $wgProfiler, $wgProfileLimit, $wgUser; |
| | 346 | + global $wgProfileLimit, $wgUser; |
| | 347 | + |
| | 348 | + $profiler = Profiler::instance(); |
| | 349 | + |
| 347 | 350 | # Profiling must actually be enabled... |
| 348 | | - if( is_null( $wgProfiler ) ) { |
| | 351 | + if ( $profiler->isStub() ) { |
| 349 | 352 | return; |
| 350 | 353 | } |
| 351 | | - # Get total page request time |
| | 354 | + |
| | 355 | + // Get total page request time and only show pages that longer than |
| | 356 | + // $wgProfileLimit time (default is 0) |
| 352 | 357 | $now = wfTime(); |
| 353 | 358 | $elapsed = $now - $wgRequestTime; |
| 354 | | - # Only show pages that longer than $wgProfileLimit time (default is 0) |
| 355 | | - if( $elapsed <= $wgProfileLimit ) { |
| | 359 | + if ( $elapsed <= $wgProfileLimit ) { |
| 356 | 360 | return; |
| 357 | 361 | } |
| 358 | | - $prof = wfGetProfilingOutput( $wgRequestTime, $elapsed ); |
| | 362 | + |
| | 363 | + $profiler->logData(); |
| | 364 | + |
| | 365 | + // Check whether this should be logged in the debug file. |
| | 366 | + // This have to be done after calling getOutput() since that call may log |
| | 367 | + // data in the database or send to a remote host and we want that even if |
| | 368 | + // it won't be send to the debug file. |
| | 369 | + if ( $wgDebugLogFile == '' || ( $wgRequest->getVal( 'action' ) == 'raw' && !$wgDebugRawPage ) ) { |
| | 370 | + return; |
| | 371 | + } |
| | 372 | + |
| 359 | 373 | $forward = ''; |
| 360 | | - if( !empty( $_SERVER['HTTP_X_FORWARDED_FOR'] ) ) { |
| | 374 | + if ( !empty( $_SERVER['HTTP_X_FORWARDED_FOR'] ) ) { |
| 361 | 375 | $forward = ' forwarded for ' . $_SERVER['HTTP_X_FORWARDED_FOR']; |
| 362 | 376 | } |
| 363 | | - if( !empty( $_SERVER['HTTP_CLIENT_IP'] ) ) { |
| | 377 | + if ( !empty( $_SERVER['HTTP_CLIENT_IP'] ) ) { |
| 364 | 378 | $forward .= ' client IP ' . $_SERVER['HTTP_CLIENT_IP']; |
| 365 | 379 | } |
| 366 | | - if( !empty( $_SERVER['HTTP_FROM'] ) ) { |
| | 380 | + if ( !empty( $_SERVER['HTTP_FROM'] ) ) { |
| 367 | 381 | $forward .= ' from ' . $_SERVER['HTTP_FROM']; |
| 368 | 382 | } |
| 369 | | - if( $forward ) { |
| | 383 | + if ( $forward ) { |
| 370 | 384 | $forward = "\t(proxied via {$_SERVER['REMOTE_ADDR']}{$forward})"; |
| 371 | 385 | } |
| 372 | 386 | // Don't unstub $wgUser at this late stage just for statistics purposes |
| 373 | 387 | // FIXME: We can detect some anons even if it is not loaded. See User::getId() |
| 374 | | - if( $wgUser->mDataLoaded && $wgUser->isAnon() ) { |
| | 388 | + if ( $wgUser->mDataLoaded && $wgUser->isAnon() ) { |
| 375 | 389 | $forward .= ' anon'; |
| 376 | 390 | } |
| 377 | 391 | $log = sprintf( "%s\t%04.3f\t%s\n", |
| 378 | 392 | gmdate( 'YmdHis' ), $elapsed, |
| 379 | 393 | urldecode( $wgRequest->getRequestURL() . $forward ) ); |
| 380 | | - if ( $wgDebugLogFile != '' && ( $wgRequest->getVal( 'action' ) != 'raw' || $wgDebugRawPage ) ) { |
| 381 | | - wfErrorLog( $log . $prof, $wgDebugLogFile ); |
| 382 | | - } |
| | 394 | + |
| | 395 | + wfErrorLog( $log . $profiler->getOutput(), $wgDebugLogFile ); |
| 383 | 396 | } |
| 384 | 397 | |
| 385 | 398 | /** |
| Index: trunk/phase3/includes/profiler/ProfilerSimple.php |
| — | — | @@ -86,10 +86,15 @@ |
| 87 | 87 | } |
| 88 | 88 | } |
| 89 | 89 | |
| 90 | | - function getFunctionReport() { |
| | 90 | + public function getFunctionReport() { |
| 91 | 91 | /* Implement in output subclasses */ |
| | 92 | + return ''; |
| 92 | 93 | } |
| 93 | 94 | |
| | 95 | + public function logData() { |
| | 96 | + /* Implement in subclasses */ |
| | 97 | + } |
| | 98 | + |
| 94 | 99 | function getCpuTime($ru=null) { |
| 95 | 100 | if ( function_exists( 'getrusage' ) ) { |
| 96 | 101 | if ( $ru == null ) { |
| Index: trunk/phase3/includes/profiler/ProfilerStub.php |
| — | — | @@ -20,6 +20,10 @@ |
| 21 | 21 | $this->haveProctitle = function_exists( 'setproctitle' ); |
| 22 | 22 | } |
| 23 | 23 | |
| | 24 | + public function isStub() { |
| | 25 | + return true; |
| | 26 | + } |
| | 27 | + |
| 24 | 28 | /** |
| 25 | 29 | * Begin profiling of a function |
| 26 | 30 | * @param $fn string |
| Index: trunk/phase3/includes/profiler/ProfilerSimpleText.php |
| — | — | @@ -25,8 +25,9 @@ |
| 26 | 26 | parent::__construct(); |
| 27 | 27 | } |
| 28 | 28 | |
| 29 | | - function getFunctionReport() { |
| | 29 | + public function logData() { |
| 30 | 30 | if($this->mTemplated) { |
| | 31 | + $this->collateData(); |
| 31 | 32 | uasort($this->mCollated,array('self','sort')); |
| 32 | 33 | array_walk($this->mCollated,array('self','format')); |
| 33 | 34 | if ($this->visible) { |
| Index: trunk/phase3/includes/profiler/Profiler.php |
| — | — | @@ -33,20 +33,6 @@ |
| 34 | 34 | } |
| 35 | 35 | |
| 36 | 36 | /** |
| 37 | | - * Returns a profiling output to be stored in debug file |
| 38 | | - */ |
| 39 | | -function wfGetProfilingOutput() { |
| 40 | | - Profiler::instance()->getOutput(); |
| 41 | | -} |
| 42 | | - |
| 43 | | -/** |
| 44 | | - * Close opened profiling sections |
| 45 | | - */ |
| 46 | | -function wfProfileClose() { |
| 47 | | - Profiler::instance()->close(); |
| 48 | | -} |
| 49 | | - |
| 50 | | -/** |
| 51 | 37 | * @ingroup Profiler |
| 52 | 38 | * @todo document |
| 53 | 39 | */ |
| — | — | @@ -54,6 +40,7 @@ |
| 55 | 41 | var $mStack = array (), $mWorkStack = array (), $mCollated = array (); |
| 56 | 42 | var $mCalls = array (), $mTotals = array (); |
| 57 | 43 | var $mTemplated = false; |
| | 44 | + private $mCollateDone = false; |
| 58 | 45 | protected $mProfileID = false; |
| 59 | 46 | private static $__instance = null; |
| 60 | 47 | |
| — | — | @@ -96,6 +83,15 @@ |
| 97 | 84 | self::$__instance = $p; |
| 98 | 85 | } |
| 99 | 86 | |
| | 87 | + /** |
| | 88 | + * Return whether this a stub profiler |
| | 89 | + * |
| | 90 | + * @return Boolean |
| | 91 | + */ |
| | 92 | + public function isStub() { |
| | 93 | + return false; |
| | 94 | + } |
| | 95 | + |
| 100 | 96 | public function setProfileID( $id ) { |
| 101 | 97 | $this->mProfileID = $id; |
| 102 | 98 | } |
| — | — | @@ -160,7 +156,7 @@ |
| 161 | 157 | } |
| 162 | 158 | |
| 163 | 159 | /** |
| 164 | | - * called by wfProfileClose() |
| | 160 | + * Close opened profiling sections |
| 165 | 161 | */ |
| 166 | 162 | public function close() { |
| 167 | 163 | while( count( $this->mWorkStack ) ){ |
| — | — | @@ -178,7 +174,9 @@ |
| 179 | 175 | } |
| 180 | 176 | |
| 181 | 177 | /** |
| 182 | | - * Called by wfGetProfilingOutput() |
| | 178 | + * Returns a profiling output to be stored in debug file |
| | 179 | + * |
| | 180 | + * @return String |
| 183 | 181 | */ |
| 184 | 182 | public function getOutput() { |
| 185 | 183 | global $wgDebugFunctionEntry, $wgProfileCallTree; |
| — | — | @@ -187,14 +185,8 @@ |
| 188 | 186 | if( !count( $this->mStack ) && !count( $this->mCollated ) ){ |
| 189 | 187 | return "No profiling output\n"; |
| 190 | 188 | } |
| 191 | | - $this->close(); |
| 192 | 189 | |
| 193 | 190 | if( $wgProfileCallTree ) { |
| 194 | | - global $wgProfileToDatabase; |
| 195 | | - # XXX: We must call $this->getFunctionReport() to log to the DB |
| 196 | | - if( $wgProfileToDatabase ) { |
| 197 | | - $this->getFunctionReport(); |
| 198 | | - } |
| 199 | 191 | return $this->getCallTree(); |
| 200 | 192 | } else { |
| 201 | 193 | return $this->getFunctionReport(); |
| — | — | @@ -270,23 +262,18 @@ |
| 271 | 263 | return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6; |
| 272 | 264 | } |
| 273 | 265 | |
| 274 | | - /** |
| 275 | | - * Returns a list of profiled functions. |
| 276 | | - * Also log it into the database if $wgProfileToDatabase is set to true. |
| 277 | | - */ |
| 278 | | - function getFunctionReport() { |
| 279 | | - global $wgProfileToDatabase; |
| | 266 | + protected function collateData() { |
| | 267 | + if ( $this->mCollateDone ) { |
| | 268 | + return; |
| | 269 | + } |
| | 270 | + $this->mCollateDone = true; |
| 280 | 271 | |
| 281 | | - $width = 140; |
| 282 | | - $nameWidth = $width - 65; |
| 283 | | - $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n"; |
| 284 | | - $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n"; |
| 285 | | - $prof = "\nProfiling data\n"; |
| 286 | | - $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' ); |
| 287 | | - $this->mCollated = array (); |
| 288 | | - $this->mCalls = array (); |
| 289 | | - $this->mMemory = array (); |
| | 272 | + $this->close(); |
| 290 | 273 | |
| | 274 | + $this->mCollated = array(); |
| | 275 | + $this->mCalls = array(); |
| | 276 | + $this->mMemory = array(); |
| | 277 | + |
| 291 | 278 | # Estimate profiling overhead |
| 292 | 279 | $profileCount = count($this->mStack); |
| 293 | 280 | self::calculateOverhead( $profileCount ); |
| — | — | @@ -348,20 +335,31 @@ |
| 349 | 336 | $this->mOverhead[$fname] += $subcalls; |
| 350 | 337 | } |
| 351 | 338 | |
| 352 | | - $total = @$this->mCollated['-total']; |
| 353 | 339 | $this->mCalls['-overhead-total'] = $profileCount; |
| 354 | | - |
| 355 | | - # Output |
| 356 | 340 | arsort( $this->mCollated, SORT_NUMERIC ); |
| | 341 | + } |
| | 342 | + |
| | 343 | + /** |
| | 344 | + * Returns a list of profiled functions. |
| | 345 | + * Also log it into the database if $wgProfileToDatabase is set to true. |
| | 346 | + */ |
| | 347 | + function getFunctionReport() { |
| | 348 | + $this->collateData(); |
| | 349 | + |
| | 350 | + $width = 140; |
| | 351 | + $nameWidth = $width - 65; |
| | 352 | + $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n"; |
| | 353 | + $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n"; |
| | 354 | + $prof = "\nProfiling data\n"; |
| | 355 | + $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' ); |
| | 356 | + |
| | 357 | + $total = @$this->mCollated['-total']; |
| | 358 | + |
| 357 | 359 | foreach( $this->mCollated as $fname => $elapsed ){ |
| 358 | 360 | $calls = $this->mCalls[$fname]; |
| 359 | 361 | $percent = $total ? 100. * $elapsed / $total : 0; |
| 360 | 362 | $memory = $this->mMemory[$fname]; |
| 361 | 363 | $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]); |
| 362 | | - # Log to the DB |
| 363 | | - if( $wgProfileToDatabase ) { |
| 364 | | - self::logToDB($fname, (float) ($elapsed * 1000), $calls, (float) ($memory) ); |
| 365 | | - } |
| 366 | 364 | } |
| 367 | 365 | $prof .= "\nTotal: $total\n\n"; |
| 368 | 366 | |
| — | — | @@ -399,60 +397,66 @@ |
| 400 | 398 | } |
| 401 | 399 | |
| 402 | 400 | /** |
| 403 | | - * Log a function into the database. |
| 404 | | - * |
| 405 | | - * @param $name String: function name |
| 406 | | - * @param $timeSum Float |
| 407 | | - * @param $eventCount Integer: number of times that function was called |
| 408 | | - * @param $memorySum Integer: memory used by the function |
| | 401 | + * Log the whole profiling data into the database. |
| 409 | 402 | */ |
| 410 | | - static function logToDB( $name, $timeSum, $eventCount, $memorySum ){ |
| | 403 | + public function logData(){ |
| | 404 | + global $wgProfilePerHost, $wgProfileToDatabase; |
| | 405 | + |
| 411 | 406 | # Do not log anything if database is readonly (bug 5375) |
| 412 | | - if( wfReadOnly() ) { return; } |
| | 407 | + if( wfReadOnly() || !$wgProfileToDatabase ) { |
| | 408 | + return; |
| | 409 | + } |
| 413 | 410 | |
| 414 | | - global $wgProfilePerHost; |
| 415 | | - |
| 416 | 411 | $dbw = wfGetDB( DB_MASTER ); |
| 417 | | - if( !is_object( $dbw ) ) |
| 418 | | - return false; |
| | 412 | + if( !is_object( $dbw ) ) { |
| | 413 | + return; |
| | 414 | + } |
| | 415 | + |
| 419 | 416 | $errorState = $dbw->ignoreErrors( true ); |
| 420 | 417 | |
| 421 | | - $name = substr($name, 0, 255); |
| 422 | | - |
| 423 | 418 | if( $wgProfilePerHost ){ |
| 424 | 419 | $pfhost = wfHostname(); |
| 425 | 420 | } else { |
| 426 | 421 | $pfhost = ''; |
| 427 | 422 | } |
| 428 | | - |
| 429 | | - // Kludge |
| 430 | | - $timeSum = ($timeSum >= 0) ? $timeSum : 0; |
| 431 | | - $memorySum = ($memorySum >= 0) ? $memorySum : 0; |
| 432 | 423 | |
| 433 | | - $dbw->update( 'profiling', |
| 434 | | - array( |
| 435 | | - "pf_count=pf_count+{$eventCount}", |
| 436 | | - "pf_time=pf_time+{$timeSum}", |
| 437 | | - "pf_memory=pf_memory+{$memorySum}", |
| 438 | | - ), |
| 439 | | - array( |
| 440 | | - 'pf_name' => $name, |
| 441 | | - 'pf_server' => $pfhost, |
| 442 | | - ), |
| 443 | | - __METHOD__ ); |
| 444 | | - |
| | 424 | + $this->collateData(); |
| 445 | 425 | |
| 446 | | - $rc = $dbw->affectedRows(); |
| 447 | | - if ($rc == 0) { |
| 448 | | - $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount, |
| 449 | | - 'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ), |
| 450 | | - __METHOD__, array ('IGNORE')); |
| | 426 | + foreach( $this->mCollated as $name => $elapsed ){ |
| | 427 | + $eventCount = $this->mCalls[$name]; |
| | 428 | + $timeSum = (float) ($elapsed * 1000); |
| | 429 | + $memorySum = (float)$this->mMemory[$name]; |
| | 430 | + $name = substr($name, 0, 255); |
| | 431 | + |
| | 432 | + // Kludge |
| | 433 | + $timeSum = ($timeSum >= 0) ? $timeSum : 0; |
| | 434 | + $memorySum = ($memorySum >= 0) ? $memorySum : 0; |
| | 435 | + |
| | 436 | + $dbw->update( 'profiling', |
| | 437 | + array( |
| | 438 | + "pf_count=pf_count+{$eventCount}", |
| | 439 | + "pf_time=pf_time+{$timeSum}", |
| | 440 | + "pf_memory=pf_memory+{$memorySum}", |
| | 441 | + ), |
| | 442 | + array( |
| | 443 | + 'pf_name' => $name, |
| | 444 | + 'pf_server' => $pfhost, |
| | 445 | + ), |
| | 446 | + __METHOD__ ); |
| | 447 | + |
| | 448 | + $rc = $dbw->affectedRows(); |
| | 449 | + if ( $rc == 0 ) { |
| | 450 | + $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount, |
| | 451 | + 'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ), |
| | 452 | + __METHOD__, array ('IGNORE')); |
| | 453 | + } |
| | 454 | + // When we upgrade to mysql 4.1, the insert+update |
| | 455 | + // can be merged into just a insert with this construct added: |
| | 456 | + // "ON DUPLICATE KEY UPDATE ". |
| | 457 | + // "pf_count=pf_count + VALUES(pf_count), ". |
| | 458 | + // "pf_time=pf_time + VALUES(pf_time)"; |
| 451 | 459 | } |
| 452 | | - // When we upgrade to mysql 4.1, the insert+update |
| 453 | | - // can be merged into just a insert with this construct added: |
| 454 | | - // "ON DUPLICATE KEY UPDATE ". |
| 455 | | - // "pf_count=pf_count + VALUES(pf_count), ". |
| 456 | | - // "pf_time=pf_time + VALUES(pf_time)"; |
| | 460 | + |
| 457 | 461 | $dbw->ignoreErrors( $errorState ); |
| 458 | 462 | } |
| 459 | 463 | |
| — | — | @@ -465,25 +469,6 @@ |
| 466 | 470 | } |
| 467 | 471 | |
| 468 | 472 | /** |
| 469 | | - * Get function caller |
| 470 | | - * |
| 471 | | - * @param $level Integer |
| 472 | | - */ |
| 473 | | - static function getCaller( $level ) { |
| 474 | | - $backtrace = wfDebugBacktrace(); |
| 475 | | - if ( isset( $backtrace[$level] ) ) { |
| 476 | | - if ( isset( $backtrace[$level]['class'] ) ) { |
| 477 | | - $caller = $backtrace[$level]['class'] . '::' . $backtrace[$level]['function']; |
| 478 | | - } else { |
| 479 | | - $caller = $backtrace[$level]['function']; |
| 480 | | - } |
| 481 | | - } else { |
| 482 | | - $caller = 'unknown'; |
| 483 | | - } |
| 484 | | - return $caller; |
| 485 | | - } |
| 486 | | - |
| 487 | | - /** |
| 488 | 473 | * Add an entry in the debug log file |
| 489 | 474 | * |
| 490 | 475 | * @param $s String to output |
| Index: trunk/phase3/includes/profiler/ProfilerSimpleUDP.php |
| — | — | @@ -10,10 +10,12 @@ |
| 11 | 11 | * @ingroup Profiler |
| 12 | 12 | */ |
| 13 | 13 | class ProfilerSimpleUDP extends ProfilerSimple { |
| 14 | | - function getFunctionReport() { |
| | 14 | + public function logData() { |
| 15 | 15 | global $wgUDPProfilerHost, $wgUDPProfilerPort; |
| 16 | 16 | |
| 17 | | - if ( $this->mCollated['-total']['real'] < $this->mMinimumTime ) { |
| | 17 | + $this->collateData(); |
| | 18 | + |
| | 19 | + if ( isset( $this->mCollated['-total'] ) && $this->mCollated['-total']['real'] < $this->mMinimumTime ) { |
| 18 | 20 | # Less than minimum, ignore |
| 19 | 21 | return; |
| 20 | 22 | } |
| Index: trunk/phase3/includes/db/Database.php |
| — | — | @@ -638,10 +638,8 @@ |
| 639 | 639 | * @throws DBQueryError Thrown when the database returns an error of any kind |
| 640 | 640 | */ |
| 641 | 641 | public function query( $sql, $fname = '', $tempIgnore = false ) { |
| 642 | | - global $wgProfiler; |
| 643 | | - |
| 644 | 642 | $isMaster = !is_null( $this->getLBInfo( 'master' ) ); |
| 645 | | - if ( isset( $wgProfiler ) ) { |
| | 643 | + if ( !Profiler::instance()->isStub() ) { |
| 646 | 644 | # generalizeSQL will probably cut down the query to reasonable |
| 647 | 645 | # logging size most of the time. The substr is really just a sanity check. |
| 648 | 646 | |
| — | — | @@ -742,7 +740,7 @@ |
| 743 | 741 | $this->reportQueryError( $this->lastError(), $this->lastErrno(), $sql, $fname, $tempIgnore ); |
| 744 | 742 | } |
| 745 | 743 | |
| 746 | | - if ( isset( $wgProfiler ) ) { |
| | 744 | + if ( !Profiler::instance()->isStub() ) { |
| 747 | 745 | wfProfileOut( $queryProf ); |
| 748 | 746 | wfProfileOut( $totalProf ); |
| 749 | 747 | } |
| Index: trunk/phase3/includes/api/ApiBase.php |
| — | — | @@ -946,7 +946,7 @@ |
| 947 | 947 | * @param $extradata array Data to add to the <error> element; array in ApiResult format |
| 948 | 948 | */ |
| 949 | 949 | public function dieUsage( $description, $errorCode, $httpRespCode = 0, $extradata = null ) { |
| 950 | | - wfProfileClose(); |
| | 950 | + Profiler::instance()->close(); |
| 951 | 951 | throw new UsageException( $description, $this->encodeParamName( $errorCode ), $httpRespCode, $extradata ); |
| 952 | 952 | } |
| 953 | 953 | |