MediaWiki
REL1_22
|
00001 <?php 00033 function wfProfileIn( $functionname ) { 00034 if ( Profiler::$__instance === null ) { // use this directly to reduce overhead 00035 Profiler::instance(); 00036 } 00037 if ( !( Profiler::$__instance instanceof ProfilerStub ) ) { 00038 Profiler::$__instance->profileIn( $functionname ); 00039 } 00040 } 00041 00046 function wfProfileOut( $functionname = 'missing' ) { 00047 if ( Profiler::$__instance === null ) { // use this directly to reduce overhead 00048 Profiler::instance(); 00049 } 00050 if ( !( Profiler::$__instance instanceof ProfilerStub ) ) { 00051 Profiler::$__instance->profileOut( $functionname ); 00052 } 00053 } 00054 00060 class ProfileSection { 00061 protected $name; // string; method name 00062 protected $enabled = false; // boolean; whether profiling is enabled 00063 00075 public function __construct( $name ) { 00076 $this->name = $name; 00077 if ( Profiler::$__instance === null ) { // use this directly to reduce overhead 00078 Profiler::instance(); 00079 } 00080 if ( !( Profiler::$__instance instanceof ProfilerStub ) ) { 00081 $this->enabled = true; 00082 Profiler::$__instance->profileIn( $this->name ); 00083 } 00084 } 00085 00086 function __destruct() { 00087 if ( $this->enabled ) { 00088 Profiler::$__instance->profileOut( $this->name ); 00089 } 00090 } 00091 } 00092 00097 class Profiler { 00098 protected $mStack = array(), $mWorkStack = array(), $mCollated = array(), 00099 $mCalls = array(), $mTotals = array(); 00100 protected $mTimeMetric = 'wall'; 00101 protected $mProfileID = false, $mCollateDone = false, $mTemplated = false; 00102 00103 protected $mDBLockThreshold = 5.0; // float; seconds 00105 protected $mDBTrxHoldingLocks = array(); 00107 protected $mDBTrxMethodTimes = array(); 00108 00110 public static $__instance = null; // do not call this outside Profiler and ProfileSection 00111 00112 function __construct( $params ) { 00113 if ( isset( $params['timeMetric'] ) ) { 00114 $this->mTimeMetric = $params['timeMetric']; 00115 } 00116 if ( isset( $params['profileID'] ) ) { 00117 $this->mProfileID = $params['profileID']; 00118 } 00119 00120 $this->addInitialStack(); 00121 } 00122 00127 public static function instance() { 00128 if ( self::$__instance === null ) { 00129 global $wgProfiler; 00130 if ( is_array( $wgProfiler ) ) { 00131 if ( !isset( $wgProfiler['class'] ) ) { 00132 $class = 'ProfilerStub'; 00133 } else { 00134 $class = $wgProfiler['class']; 00135 } 00136 self::$__instance = new $class( $wgProfiler ); 00137 } elseif ( $wgProfiler instanceof Profiler ) { 00138 self::$__instance = $wgProfiler; // back-compat 00139 } else { 00140 self::$__instance = new ProfilerStub( $wgProfiler ); 00141 } 00142 } 00143 return self::$__instance; 00144 } 00145 00150 public static function setInstance( Profiler $p ) { 00151 self::$__instance = $p; 00152 } 00153 00159 public function isStub() { 00160 return false; 00161 } 00162 00169 public function isPersistent() { 00170 return true; 00171 } 00172 00173 public function setProfileID( $id ) { 00174 $this->mProfileID = $id; 00175 } 00176 00177 public function getProfileID() { 00178 if ( $this->mProfileID === false ) { 00179 return wfWikiID(); 00180 } else { 00181 return $this->mProfileID; 00182 } 00183 } 00184 00188 protected function addInitialStack() { 00189 // Push an entry for the pre-profile setup time onto the stack 00190 $initial = $this->getInitialTime(); 00191 if ( $initial !== null ) { 00192 $this->mWorkStack[] = array( '-total', 0, $initial, 0 ); 00193 $this->mStack[] = array( '-setup', 1, $initial, 0, $this->getTime(), 0 ); 00194 } else { 00195 $this->profileIn( '-total' ); 00196 } 00197 } 00198 00204 public function profileIn( $functionname ) { 00205 global $wgDebugFunctionEntry; 00206 if ( $wgDebugFunctionEntry ) { 00207 $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Entering ' . $functionname . "\n" ); 00208 } 00209 00210 $this->mWorkStack[] = array( $functionname, count( $this->mWorkStack ), $this->getTime(), memory_get_usage() ); 00211 } 00212 00218 public function profileOut( $functionname ) { 00219 global $wgDebugFunctionEntry; 00220 $memory = memory_get_usage(); 00221 $time = $this->getTime(); 00222 00223 if ( $wgDebugFunctionEntry ) { 00224 $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . 'Exiting ' . $functionname . "\n" ); 00225 } 00226 00227 $bit = array_pop( $this->mWorkStack ); 00228 00229 if ( !$bit ) { 00230 $this->debug( "Profiling error, !\$bit: $functionname\n" ); 00231 } else { 00232 if ( $functionname == 'close' ) { 00233 $message = "Profile section ended by close(): {$bit[0]}"; 00234 $this->debug( "$message\n" ); 00235 $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 ); 00236 } elseif ( $bit[0] != $functionname ) { 00237 $message = "Profiling error: in({$bit[0]}), out($functionname)"; 00238 $this->debug( "$message\n" ); 00239 $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 ); 00240 } 00241 $bit[] = $time; 00242 $bit[] = $memory; 00243 $this->mStack[] = $bit; 00244 $this->updateTrxProfiling( $functionname, $time ); 00245 } 00246 } 00247 00251 public function close() { 00252 while ( count( $this->mWorkStack ) ) { 00253 $this->profileOut( 'close' ); 00254 } 00255 } 00256 00265 public function transactionWritingIn( $server, $db ) { 00266 $name = "{$server} ({$db})"; 00267 if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) { 00268 ++$this->mDBTrxHoldingLocks[$name]['refs']; 00269 } else { 00270 $this->mDBTrxHoldingLocks[$name] = array( 'refs' => 1, 'start' => microtime( true ) ); 00271 $this->mDBTrxMethodTimes[$name] = array(); 00272 } 00273 } 00274 00281 protected function updateTrxProfiling( $method, $realtime ) { 00282 if ( !$this->mDBTrxHoldingLocks ) { 00283 return; // short-circuit 00284 // @TODO: hardcoded check is a tad janky (what about FOR UPDATE?) 00285 } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method ) 00286 && $realtime < $this->mDBLockThreshold ) 00287 { 00288 return; // not a DB master query nor slow enough 00289 } 00290 $now = microtime( true ); 00291 foreach ( $this->mDBTrxHoldingLocks as $name => $info ) { 00292 // Hacky check to exclude entries from before the first TRX write 00293 if ( ( $now - $realtime ) >= $info['start'] ) { 00294 $this->mDBTrxMethodTimes[$name][] = array( $method, $realtime ); 00295 } 00296 } 00297 } 00298 00309 public function transactionWritingOut( $server, $db ) { 00310 $name = "{$server} ({$db})"; 00311 if ( --$this->mDBTrxHoldingLocks[$name]['refs'] <= 0 ) { 00312 $slow = false; 00313 foreach ( $this->mDBTrxMethodTimes[$name] as $info ) { 00314 list( $method, $realtime ) = $info; 00315 if ( $realtime >= $this->mDBLockThreshold ) { 00316 $slow = true; 00317 break; 00318 } 00319 } 00320 if ( $slow ) { 00321 $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks ) ); 00322 $msg = "Sub-optimal transaction on DB(s) {$dbs}:\n"; 00323 foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) { 00324 list( $method, $realtime ) = $info; 00325 $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method ); 00326 } 00327 wfDebugLog( 'DBPerformance', $msg ); 00328 } 00329 unset( $this->mDBTrxHoldingLocks[$name] ); 00330 unset( $this->mDBTrxMethodTimes[$name] ); 00331 } 00332 } 00333 00339 function setTemplated( $t ) { 00340 $this->mTemplated = $t; 00341 } 00342 00348 public function getOutput() { 00349 global $wgDebugFunctionEntry, $wgProfileCallTree; 00350 $wgDebugFunctionEntry = false; 00351 00352 if ( !count( $this->mStack ) && !count( $this->mCollated ) ) { 00353 return "No profiling output\n"; 00354 } 00355 00356 if ( $wgProfileCallTree ) { 00357 return $this->getCallTree(); 00358 } else { 00359 return $this->getFunctionReport(); 00360 } 00361 } 00362 00367 function getCallTree() { 00368 return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) ) ); 00369 } 00370 00377 function remapCallTree( $stack ) { 00378 if ( count( $stack ) < 2 ) { 00379 return $stack; 00380 } 00381 $outputs = array(); 00382 for ( $max = count( $stack ) - 1; $max > 0; ) { 00383 /* Find all items under this entry */ 00384 $level = $stack[$max][1]; 00385 $working = array(); 00386 for ( $i = $max -1; $i >= 0; $i-- ) { 00387 if ( $stack[$i][1] > $level ) { 00388 $working[] = $stack[$i]; 00389 } else { 00390 break; 00391 } 00392 } 00393 $working = $this->remapCallTree( array_reverse( $working ) ); 00394 $output = array(); 00395 foreach ( $working as $item ) { 00396 array_push( $output, $item ); 00397 } 00398 array_unshift( $output, $stack[$max] ); 00399 $max = $i; 00400 00401 array_unshift( $outputs, $output ); 00402 } 00403 $final = array(); 00404 foreach ( $outputs as $output ) { 00405 foreach ( $output as $item ) { 00406 $final[] = $item; 00407 } 00408 } 00409 return $final; 00410 } 00411 00416 function getCallTreeLine( $entry ) { 00417 list( $fname, $level, $start, /* $x */, $end ) = $entry; 00418 $delta = $end - $start; 00419 $space = str_repeat( ' ', $level ); 00420 # The ugly double sprintf is to work around a PHP bug, 00421 # which has been fixed in recent releases. 00422 return sprintf( "%10s %s %s\n", trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname ); 00423 } 00424 00436 function getTime( $metric = false ) { 00437 if ( $metric === false ) { 00438 $metric = $this->mTimeMetric; 00439 } 00440 00441 if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) { 00442 if ( !function_exists( 'getrusage' ) ) { 00443 return 0; 00444 } 00445 $ru = getrusage(); 00446 $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6; 00447 if ( $metric === 'cpu' ) { 00448 # This is the time of system calls, added to the user time 00449 # it gives the total CPU time 00450 $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6; 00451 } 00452 return $time; 00453 } else { 00454 return microtime( true ); 00455 } 00456 } 00457 00469 protected function getInitialTime( $metric = false ) { 00470 global $wgRequestTime, $wgRUstart; 00471 00472 if ( $metric === false ) { 00473 $metric = $this->mTimeMetric; 00474 } 00475 00476 if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) { 00477 if ( !count( $wgRUstart ) ) { 00478 return null; 00479 } 00480 00481 $time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6; 00482 if ( $metric === 'cpu' ) { 00483 # This is the time of system calls, added to the user time 00484 # it gives the total CPU time 00485 $time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6; 00486 } 00487 return $time; 00488 } else { 00489 if ( empty( $wgRequestTime ) ) { 00490 return null; 00491 } else { 00492 return $wgRequestTime; 00493 } 00494 } 00495 } 00496 00497 protected function collateData() { 00498 if ( $this->mCollateDone ) { 00499 return; 00500 } 00501 $this->mCollateDone = true; 00502 00503 $this->close(); 00504 00505 $this->mCollated = array(); 00506 $this->mCalls = array(); 00507 $this->mMemory = array(); 00508 00509 # Estimate profiling overhead 00510 $profileCount = count( $this->mStack ); 00511 self::calculateOverhead( $profileCount ); 00512 00513 # First, subtract the overhead! 00514 $overheadTotal = $overheadMemory = $overheadInternal = array(); 00515 foreach ( $this->mStack as $entry ) { 00516 $fname = $entry[0]; 00517 $start = $entry[2]; 00518 $end = $entry[4]; 00519 $elapsed = $end - $start; 00520 $memory = $entry[5] - $entry[3]; 00521 00522 if ( $fname == '-overhead-total' ) { 00523 $overheadTotal[] = $elapsed; 00524 $overheadMemory[] = $memory; 00525 } elseif ( $fname == '-overhead-internal' ) { 00526 $overheadInternal[] = $elapsed; 00527 } 00528 } 00529 $overheadTotal = $overheadTotal ? array_sum( $overheadTotal ) / count( $overheadInternal ) : 0; 00530 $overheadMemory = $overheadMemory ? array_sum( $overheadMemory ) / count( $overheadInternal ) : 0; 00531 $overheadInternal = $overheadInternal ? array_sum( $overheadInternal ) / count( $overheadInternal ) : 0; 00532 00533 # Collate 00534 foreach ( $this->mStack as $index => $entry ) { 00535 $fname = $entry[0]; 00536 $start = $entry[2]; 00537 $end = $entry[4]; 00538 $elapsed = $end - $start; 00539 00540 $memory = $entry[5] - $entry[3]; 00541 $subcalls = $this->calltreeCount( $this->mStack, $index ); 00542 00543 if ( !preg_match( '/^-overhead/', $fname ) ) { 00544 # Adjust for profiling overhead (except special values with elapsed=0 00545 if ( $elapsed ) { 00546 $elapsed -= $overheadInternal; 00547 $elapsed -= ( $subcalls * $overheadTotal ); 00548 $memory -= ( $subcalls * $overheadMemory ); 00549 } 00550 } 00551 00552 if ( !array_key_exists( $fname, $this->mCollated ) ) { 00553 $this->mCollated[$fname] = 0; 00554 $this->mCalls[$fname] = 0; 00555 $this->mMemory[$fname] = 0; 00556 $this->mMin[$fname] = 1 << 24; 00557 $this->mMax[$fname] = 0; 00558 $this->mOverhead[$fname] = 0; 00559 } 00560 00561 $this->mCollated[$fname] += $elapsed; 00562 $this->mCalls[$fname]++; 00563 $this->mMemory[$fname] += $memory; 00564 $this->mMin[$fname] = min( $this->mMin[$fname], $elapsed ); 00565 $this->mMax[$fname] = max( $this->mMax[$fname], $elapsed ); 00566 $this->mOverhead[$fname] += $subcalls; 00567 } 00568 00569 $this->mCalls['-overhead-total'] = $profileCount; 00570 arsort( $this->mCollated, SORT_NUMERIC ); 00571 } 00572 00578 function getFunctionReport() { 00579 $this->collateData(); 00580 00581 $width = 140; 00582 $nameWidth = $width - 65; 00583 $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n"; 00584 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n"; 00585 $prof = "\nProfiling data\n"; 00586 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' ); 00587 00588 $total = isset( $this->mCollated['-total'] ) ? $this->mCollated['-total'] : 0; 00589 00590 foreach ( $this->mCollated as $fname => $elapsed ) { 00591 $calls = $this->mCalls[$fname]; 00592 $percent = $total ? 100. * $elapsed / $total : 0; 00593 $memory = $this->mMemory[$fname]; 00594 $prof .= sprintf( $format, 00595 substr( $fname, 0, $nameWidth ), 00596 $calls, 00597 (float)( $elapsed * 1000 ), 00598 (float)( $elapsed * 1000 ) / $calls, 00599 $percent, 00600 $memory, 00601 ( $this->mMin[$fname] * 1000.0 ), 00602 ( $this->mMax[$fname] * 1000.0 ), 00603 $this->mOverhead[$fname] 00604 ); 00605 } 00606 $prof .= "\nTotal: $total\n\n"; 00607 00608 return $prof; 00609 } 00610 00614 protected static function calculateOverhead( $profileCount ) { 00615 wfProfileIn( '-overhead-total' ); 00616 for ( $i = 0; $i < $profileCount; $i++ ) { 00617 wfProfileIn( '-overhead-internal' ); 00618 wfProfileOut( '-overhead-internal' ); 00619 } 00620 wfProfileOut( '-overhead-total' ); 00621 } 00622 00632 function calltreeCount( $stack, $start ) { 00633 $level = $stack[$start][1]; 00634 $count = 0; 00635 for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) { 00636 $count ++; 00637 } 00638 return $count; 00639 } 00640 00644 public function logData() { 00645 global $wgProfilePerHost, $wgProfileToDatabase; 00646 00647 # Do not log anything if database is readonly (bug 5375) 00648 if ( wfReadOnly() || !$wgProfileToDatabase ) { 00649 return; 00650 } 00651 00652 $dbw = wfGetDB( DB_MASTER ); 00653 if ( !is_object( $dbw ) ) { 00654 return; 00655 } 00656 00657 if ( $wgProfilePerHost ) { 00658 $pfhost = wfHostname(); 00659 } else { 00660 $pfhost = ''; 00661 } 00662 00663 try { 00664 $this->collateData(); 00665 00666 foreach ( $this->mCollated as $name => $elapsed ) { 00667 $eventCount = $this->mCalls[$name]; 00668 $timeSum = (float)( $elapsed * 1000 ); 00669 $memorySum = (float)$this->mMemory[$name]; 00670 $name = substr( $name, 0, 255 ); 00671 00672 // Kludge 00673 $timeSum = $timeSum >= 0 ? $timeSum : 0; 00674 $memorySum = $memorySum >= 0 ? $memorySum : 0; 00675 00676 $dbw->update( 'profiling', 00677 array( 00678 "pf_count=pf_count+{$eventCount}", 00679 "pf_time=pf_time+{$timeSum}", 00680 "pf_memory=pf_memory+{$memorySum}", 00681 ), 00682 array( 00683 'pf_name' => $name, 00684 'pf_server' => $pfhost, 00685 ), 00686 __METHOD__ ); 00687 00688 $rc = $dbw->affectedRows(); 00689 if ( $rc == 0 ) { 00690 $dbw->insert( 'profiling', array( 'pf_name' => $name, 'pf_count' => $eventCount, 00691 'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ), 00692 __METHOD__, array( 'IGNORE' ) ); 00693 } 00694 // When we upgrade to mysql 4.1, the insert+update 00695 // can be merged into just a insert with this construct added: 00696 // "ON DUPLICATE KEY UPDATE ". 00697 // "pf_count=pf_count + VALUES(pf_count), ". 00698 // "pf_time=pf_time + VALUES(pf_time)"; 00699 } 00700 } catch ( DBError $e ) {} 00701 } 00702 00707 function getCurrentSection() { 00708 $elt = end( $this->mWorkStack ); 00709 return $elt[0]; 00710 } 00711 00717 function debug( $s ) { 00718 if ( function_exists( 'wfDebug' ) ) { 00719 wfDebug( $s ); 00720 } 00721 } 00722 00728 protected function getContentType() { 00729 foreach ( headers_list() as $header ) { 00730 if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) { 00731 return $m[1]; 00732 } 00733 } 00734 return null; 00735 } 00736 }