X-Git-Url: http://git.heureux-cyclage.org/?a=blobdiff_plain;f=includes%2FProfiling.php;h=c077f2ce3e30d8500ec51324d59f7fdea16798b8;hb=54215e07632518a9a08e066eb61c9af77c4fa918;hp=6d97f97749ccad52406269d3c14466ff39ed6d74;hpb=96f02ac694f75c01afd79b40cd1648d4f9624f96;p=lhc%2Fweb%2Fwiklou.git diff --git a/includes/Profiling.php b/includes/Profiling.php index 6d97f97749..c077f2ce3e 100755 --- a/includes/Profiling.php +++ b/includes/Profiling.php @@ -1,32 +1,49 @@ -profileIn( $functionname ); + $wgProfiler->profileIn($functionname); } -function wfProfileOut( $functionname = "missing" ) -{ +/** + * @param $functioname name of the function we have profiled + */ +function wfProfileOut($functionname = 'missing') { global $wgProfiler; - $wgProfiler->profileOut( $functionname ); + $wgProfiler->profileOut($functionname); } -function wfGetProfilingOutput( $start, $elapsed ) { +function wfGetProfilingOutput($start, $elapsed) { global $wgProfiler; - return $wgProfiler->getOutput( $start, $elapsed ); + return $wgProfiler->getOutput($start, $elapsed); } -function wfProfileClose() -{ +function wfProfileClose() { global $wgProfiler; $wgProfiler->close(); } -class Profiler -{ - var $mStack = array(), $mWorkStack = array(), $mCollated = array(); - var $mCalls = array(), $mTotals = array(); +if (!function_exists('memory_get_usage')) { + # Old PHP or --enable-memory-limit not compiled in + function memory_get_usage() { + return 0; + } +} + +/** + * @todo document + * @package MediaWiki + */ +class Profiler { + var $mStack = array (), $mWorkStack = array (), $mCollated = array (); + var $mCalls = array (), $mTotals = array (); /* function Profiler() { @@ -35,108 +52,217 @@ class Profiler $this->mCollated = array(); } */ - - function profileIn( $functionname ) - { + + function profileIn($functionname) { global $wgDebugFunctionEntry; - if ( $wgDebugFunctionEntry && function_exists( "wfDebug" ) ) { - wfDebug( "Entering $functionname\n" ); + if ($wgDebugFunctionEntry && function_exists('wfDebug')) { + wfDebug(str_repeat(' ', count($this->mWorkStack)).'Entering '.$functionname."\n"); } - array_push( $this->mWorkStack, array($functionname, count( $this->mWorkStack ), microtime() ) ); + $this->mWorkStack[] = array ($functionname, count($this->mWorkStack), microtime(), memory_get_usage()); } - function profileOut( $functionname) - { + function profileOut($functionname) { + $memory = memory_get_usage(); + $time = microtime(); global $wgDebugProfiling, $wgDebugFunctionEntry; - if ( $wgDebugFunctionEntry && function_exists( "wfDebug" ) ) { - wfDebug( "Exiting $functionname\n" ); + if ($wgDebugFunctionEntry && function_exists('wfDebug')) { + wfDebug(str_repeat(' ', count($this->mWorkStack)).'Exiting '.$functionname."\n"); } - - $bit = array_pop( $this->mWorkStack ); - - if ( !$bit ) { - wfDebug( "Profiling error, !\$bit: $functionname\n" ); + + $bit = array_pop($this->mWorkStack); + + if (!$bit) { + wfDebug("Profiling error, !\$bit: $functionname\n"); } else { - if ( $wgDebugProfiling ) { - if ( $functionname == "close" ) { - wfDebug( "Profile section ended by close(): {$bit[0]}\n" ); - } elseif ( $bit[0] != $functionname ) { - wfDebug( "Profiling error: in({$bit[0]}), out($functionname)\n" ); + if ($wgDebugProfiling) { + if ($functionname == 'close') { + wfDebug("Profile section ended by close(): {$bit[0]}\n"); + } + elseif ($bit[0] != $functionname) { + wfDebug("Profiling error: in({$bit[0]}), out($functionname)\n"); } } - array_push( $bit, microtime() ); - array_push( $this->mStack, $bit ); + $bit[] = $time; + $bit[] = $memory; + $this->mStack[] = $bit; } } - - function close() - { - while ( count( $this->mWorkStack ) ) { - $this->profileOut( "close" ); + + function close() { + while (count($this->mWorkStack)) { + $this->profileOut('close'); } } - function getOutput( $scriptStart, $scriptElapsed ) - { - if( !count( $this->mStack ) ) { + function getOutput() { + global $wgDebugFunctionEntry; + $wgDebugFunctionEntry = false; + + if (!count($this->mStack)) { return "No profiling output\n"; } + $this->close(); + + global $wgProfileCallTree; + if ($wgProfileCallTree) { + return $this->getCallTree(); + } else { + return $this->getFunctionReport(); + } + } + + function getCallTree($start = 0) { + return implode('', array_map(array (& $this, 'getCallTreeLine'), $this->remapCallTree($this->mStack))); + } + + 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; + } + + function getCallTreeLine($entry) { + list ($fname, $level, $start, $x, $end) = $entry; + $delta = $this->microDelta($start, $end); + $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); + } + + function micro2Float($micro) { + list ($whole, $fractional) = explode(' ', $micro); + return (float) $whole + (float) $fractional; + } + + function microDelta($start, $end) { + return $this->micro2Float($end) - $this->micro2Float($start); + } + + function getFunctionReport() { $width = 125; - $format = "%-" . ($width - 28) . "s %6d %6.3f %6.3f %6.3f%%\n"; - $titleFormat = "%-" . ($width - 28) . "s %9s %9s %9s %9s\n"; + $format = "%-". ($width -34)."s %6d %6.3f %6.3f %7.3f%% %6d (%6.3f-%6.3f) [%d]\n"; + $titleFormat = "%-". ($width -34)."s %9s %9s %9s %9s %6s\n"; $prof = "\nProfiling data\n"; - $prof .= sprintf( $titleFormat, "Name", "Calls", "Total", "Each", "%" ); - $this->mCollated = array(); - $this->mCalls = array(); - + $prof .= sprintf($titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem'); + $this->mCollated = array (); + $this->mCalls = array (); + $this->mMemory = array (); + # Estimate profiling overhead - $profileCount = count( $this->mStack ); - wfProfileIn( "-overhead-total" ); - for ($i=0; $i<$profileCount ; $i++) { - wfProfileIn( "-overhead-internal" ); - wfProfileOut( "-overhead-internal" ); + $profileCount = count($this->mStack); + wfProfileIn('-overhead-total'); + for ($i = 0; $i < $profileCount; $i ++) { + wfProfileIn('-overhead-internal'); + wfProfileOut('-overhead-internal'); } - wfProfileOut( "-overhead-total" ); - + wfProfileOut('-overhead-total'); + + # First, subtract the overhead! + foreach ($this->mStack as $entry) { + $fname = $entry[0]; + $thislevel = $entry[1]; + $start = explode(' ', $entry[2]); + $start = (float) $start[0] + (float) $start[1]; + $end = explode(' ', $entry[4]); + $end = (float) $end[0] + (float) $end[1]; + $elapsed = $end - $start; + $memory = $entry[5] - $entry[3]; + + if ($fname == '-overhead-total') { + $overheadTotal[] = $elapsed; + $overheadMemory[] = $memory; + } + elseif ($fname == '-overhead-internal') { + $overheadInternal[] = $elapsed; + } + } + $overheadTotal = array_sum($overheadTotal) / count($overheadInternal); + $overheadMemory = array_sum($overheadMemory) / count($overheadInternal); + $overheadInternal = array_sum($overheadInternal) / count($overheadInternal); + # Collate - foreach ( $this->mStack as $entry ) { + foreach ($this->mStack as $index => $entry) { $fname = $entry[0]; $thislevel = $entry[1]; - $start = explode( " ", $entry[2]); - $start = (float)$start[0] + (float)$start[1]; - $end = explode( " ", $entry[3]); - $end = (float)$end[0] + (float)$end[1]; + $start = explode(' ', $entry[2]); + $start = (float) $start[0] + (float) $start[1]; + $end = explode(' ', $entry[4]); + $end = (float) $end[0] + (float) $end[1]; $elapsed = $end - $start; - - if ( !array_key_exists( $fname, $this->mCollated ) ) { + + $memory = $entry[5] - $entry[3]; + $subcalls = $this->calltreeCount($this->mStack, $index); + + if (!preg_match('/^-overhead/', $fname)) { + # Adjust for profiling overhead + $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->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; } - $total = $this->mCollated["-total"]; - $overhead = $this->mCollated["-overhead-internal"] / $profileCount; - $this->mCalls["-overhead-total"] = $profileCount; + $total = @ $this->mCollated['-total']; + $this->mCalls['-overhead-total'] = $profileCount; # Output - foreach ( $this->mCollated as $fname => $elapsed ) { + asort($this->mCollated, SORT_NUMERIC); + foreach ($this->mCollated as $fname => $elapsed) { $calls = $this->mCalls[$fname]; - # Adjust for overhead - if ( $fname[0] != "-" ) { - $elapsed -= $overhead * $calls; - } - $percent = $total ? 100. * $elapsed / $total : 0; - $prof .= sprintf( $format, $fname, $calls, (float)($elapsed * 1000), - (float)($elapsed * 1000) / $calls, $percent ); + $memory = $this->mMemory[$fname]; + $prof .= sprintf($format, $fname, $calls, (float) ($elapsed * 1000), (float) ($elapsed * 1000) / $calls, $percent, $memory, ($this->mMin[$fname] * 1000.0), ($this->mMax[$fname] * 1000.0), $this->mOverhead[$fname]); global $wgProfileToDatabase; - if( $wgProfileToDatabase ) { - Profiler::logToDB( $fname, (float)($elapsed * 1000), $calls ); + if ($wgProfileToDatabase) { + Profiler :: logToDB($fname, (float) ($elapsed * 1000), $calls); } } $prof .= "\nTotal: $total\n\n"; @@ -144,22 +270,40 @@ class Profiler return $prof; } + /** + * 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 + * @access private + */ + function calltreeCount(& $stack, $start) { + $level = $stack[$start][1]; + $count = 0; + for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) { + $count ++; + } + return $count; + } - /* static */ function logToDB($name, $timeSum, $eventCount) - { - $name = wfStrencode( $name ); - $sql = "UPDATE profiling ". - "SET pf_count=pf_count+{$eventCount}, ". - "pf_time=pf_time + {$timeSum} ". - "WHERE pf_name='{$name}'"; - wfQuery($sql , DB_WRITE); - - $rc = wfAffectedRows(); - if( $rc == 0) { - $sql = "INSERT IGNORE INTO profiling (pf_name,pf_count,pf_time) ". - "VALUES ('{$name}', {$eventCount}, {$timeSum}) "; - wfQuery($sql , DB_WRITE); - $rc = wfAffectedRows(); + /** + * @static + */ + function logToDB($name, $timeSum, $eventCount) { + $fname = 'Profiler::logToDB'; + $dbw = & wfGetDB(DB_MASTER); + $profiling = $dbw->tableName('profiling'); + + $name = substr($name, 0, 255); + $encname = $dbw->strencode($name); + $sql = "UPDATE $profiling "."SET pf_count=pf_count+{$eventCount}, "."pf_time=pf_time + {$timeSum} "."WHERE pf_name='{$encname}'"; + $dbw->query($sql); + + $rc = $dbw->affectedRows(); + if ($rc == 0) { + $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount, 'pf_time' => $timeSum), $fname, array ('IGNORE')); } // When we upgrade to mysql 4.1, the insert+update // can be merged into just a insert with this construct added: @@ -170,8 +314,6 @@ class Profiler } - $wgProfiler = new Profiler(); -$wgProfiler->profileIn( "-total" ); - +$wgProfiler->profileIn('-total'); ?>