3 * This file is only included if profiling is enabled
7 /** backward compatibility */
11 * Begin profiling of a function
12 * @param $functioname name of the function we will profile
14 function wfProfileIn( $functionname ) {
16 $wgProfiler->profileIn( $functionname );
20 * Stop profiling of a function
21 * @param $functioname name of the function we have profiled
23 function wfProfileOut( $functionname = 'missing' ) {
25 $wgProfiler->profileOut( $functionname );
29 * Returns a profiling output to be stored in debug file
32 * @param float $elapsed time elapsed since the beginning of the request
34 function wfGetProfilingOutput( $start, $elapsed ) {
36 return $wgProfiler->getOutput( $start, $elapsed );
40 * Close opened profiling sections
42 function wfProfileClose() {
47 if (!function_exists('memory_get_usage')) {
48 # Old PHP or --enable-memory-limit not compiled in
49 function memory_get_usage() {
56 * @addtogroup Profiler
59 var $mStack = array (), $mWorkStack = array (), $mCollated = array ();
60 var $mCalls = array (), $mTotals = array ();
62 function __construct() {
63 // Push an entry for the pre-profile setup time onto the stack
64 global $wgRequestTime;
65 if ( !empty( $wgRequestTime ) ) {
66 $this->mWorkStack
[] = array( '-total', 0, $wgRequestTime, 0 );
67 $this->mStack
[] = array( '-setup', 1, $wgRequestTime, 0, microtime(true), 0 );
69 $this->profileIn( '-total' );
74 * Called by wfProfieIn()
75 * @param string $functionname
77 function profileIn( $functionname ) {
78 global $wgDebugFunctionEntry;
80 if( $wgDebugFunctionEntry ){
81 $this->debug( str_repeat( ' ', count( $this->mWorkStack
) ) . 'Entering ' . $functionname . "\n" );
84 $this->mWorkStack
[] = array( $functionname, count( $this->mWorkStack
), $this->getTime(), memory_get_usage() );
88 * Called by wfProfieOut()
89 * @param string $functionname
91 function profileOut($functionname) {
92 global $wgDebugFunctionEntry;
94 $memory = memory_get_usage();
95 $time = $this->getTime();
97 if( $wgDebugFunctionEntry ){
98 $this->debug( str_repeat( ' ', count( $this->mWorkStack
) - 1 ) . 'Exiting ' . $functionname . "\n" );
101 $bit = array_pop($this->mWorkStack
);
104 $this->debug("Profiling error, !\$bit: $functionname\n");
106 //if( $wgDebugProfiling ){
107 if( $functionname == 'close' ){
108 $message = "Profile section ended by close(): {$bit[0]}";
109 $this->debug( "$message\n" );
110 $this->mStack
[] = array( $message, 0, '0 0', 0, '0 0', 0 );
112 elseif( $bit[0] != $functionname ){
113 $message = "Profiling error: in({$bit[0]}), out($functionname)";
114 $this->debug( "$message\n" );
115 $this->mStack
[] = array( $message, 0, '0 0', 0, '0 0', 0 );
120 $this->mStack
[] = $bit;
125 * called by wfProfileClose()
128 while( count( $this->mWorkStack
) ){
129 $this->profileOut( 'close' );
134 * called by wfGetProfilingOutput()
136 function getOutput() {
137 global $wgDebugFunctionEntry, $wgProfileCallTree;
138 $wgDebugFunctionEntry = false;
140 if( !count( $this->mStack
) && !count( $this->mCollated
) ){
141 return "No profiling output\n";
145 if( $wgProfileCallTree ){
146 return $this->getCallTree();
148 return $this->getFunctionReport();
153 * returns a tree of function call instead of a list of functions
155 function getCallTree() {
156 return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack
) ) );
160 * Recursive function the format the current profiling array into a tree
162 * @param array $stack profiling array
164 function remapCallTree( $stack ) {
165 if( count( $stack ) < 2 ){
169 for( $max = count( $stack ) - 1; $max > 0; ){
170 /* Find all items under this entry */
171 $level = $stack[$max][1];
173 for( $i = $max -1; $i >= 0; $i-- ){
174 if( $stack[$i][1] > $level ){
175 $working[] = $stack[$i];
180 $working = $this->remapCallTree( array_reverse( $working ) );
182 foreach( $working as $item ){
183 array_push( $output, $item );
185 array_unshift( $output, $stack[$max] );
188 array_unshift( $outputs, $output );
191 foreach( $outputs as $output ){
192 foreach( $output as $item ){
200 * Callback to get a formatted line for the call tree
202 function getCallTreeLine($entry) {
203 list( $fname, $level, $start, /* $x */, $end) = $entry;
204 $delta = $end - $start;
205 $space = str_repeat(' ', $level);
207 # The ugly double sprintf is to work around a PHP bug,
208 # which has been fixed in recent releases.
209 return sprintf( "%10s %s %s\n",
210 trim( sprintf( "%7.3f", $delta * 1000.0 ) ),
215 return microtime(true);
216 #return $this->getUserTime();
219 function getUserTime() {
221 return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6
;
225 * Returns a list of profiled functions.
226 * Also log it into the database if $wgProfileToDatabase is set to true.
228 function getFunctionReport() {
229 global $wgProfileToDatabase;
232 $nameWidth = $width - 65;
233 $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n";
234 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
235 $prof = "\nProfiling data\n";
236 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
237 $this->mCollated
= array ();
238 $this->mCalls
= array ();
239 $this->mMemory
= array ();
241 # Estimate profiling overhead
242 $profileCount = count($this->mStack
);
243 wfProfileIn( '-overhead-total' );
244 for( $i = 0; $i < $profileCount; $i ++
){
245 wfProfileIn( '-overhead-internal' );
246 wfProfileOut( '-overhead-internal' );
248 wfProfileOut( '-overhead-total' );
250 # First, subtract the overhead!
251 foreach( $this->mStack
as $entry ){
255 $elapsed = $end - $start;
256 $memory = $entry[5] - $entry[3];
258 if( $fname == '-overhead-total' ){
259 $overheadTotal[] = $elapsed;
260 $overheadMemory[] = $memory;
262 elseif( $fname == '-overhead-internal' ){
263 $overheadInternal[] = $elapsed;
266 $overheadTotal = array_sum( $overheadTotal ) / count( $overheadInternal );
267 $overheadMemory = array_sum( $overheadMemory ) / count( $overheadInternal );
268 $overheadInternal = array_sum( $overheadInternal ) / count( $overheadInternal );
271 foreach( $this->mStack
as $index => $entry ){
275 $elapsed = $end - $start;
277 $memory = $entry[5] - $entry[3];
278 $subcalls = $this->calltreeCount( $this->mStack
, $index );
280 if( !preg_match( '/^-overhead/', $fname ) ){
281 # Adjust for profiling overhead (except special values with elapsed=0
283 $elapsed -= $overheadInternal;
284 $elapsed -= ($subcalls * $overheadTotal);
285 $memory -= ($subcalls * $overheadMemory);
289 if( !array_key_exists( $fname, $this->mCollated
) ){
290 $this->mCollated
[$fname] = 0;
291 $this->mCalls
[$fname] = 0;
292 $this->mMemory
[$fname] = 0;
293 $this->mMin
[$fname] = 1 << 24;
294 $this->mMax
[$fname] = 0;
295 $this->mOverhead
[$fname] = 0;
298 $this->mCollated
[$fname] +
= $elapsed;
299 $this->mCalls
[$fname]++
;
300 $this->mMemory
[$fname] +
= $memory;
301 $this->mMin
[$fname] = min($this->mMin
[$fname], $elapsed);
302 $this->mMax
[$fname] = max($this->mMax
[$fname], $elapsed);
303 $this->mOverhead
[$fname] +
= $subcalls;
306 $total = @$this->mCollated
['-total'];
307 $this->mCalls
['-overhead-total'] = $profileCount;
310 arsort( $this->mCollated
, SORT_NUMERIC
);
311 foreach( $this->mCollated
as $fname => $elapsed ){
312 $calls = $this->mCalls
[$fname];
313 $percent = $total ?
100. * $elapsed / $total : 0;
314 $memory = $this->mMemory
[$fname];
315 $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]);
317 if( $wgProfileToDatabase ){
318 self
::logToDB($fname, (float) ($elapsed * 1000), $calls, (float) ($memory) );
321 $prof .= "\nTotal: $total\n\n";
327 * Counts the number of profiled function calls sitting under
328 * the given point in the call graph. Not the most efficient algo.
330 * @param $stack Array:
331 * @param $start Integer:
335 function calltreeCount($stack, $start) {
336 $level = $stack[$start][1];
338 for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) {
345 * Log a function into the database.
347 * @param string $name function name
348 * @param float $timeSum
349 * @param int $eventCount number of times that function was called
351 static function logToDB( $name, $timeSum, $eventCount, $memorySum ){
352 # Do not log anything if database is readonly (bug 5375)
353 if( wfReadOnly() ) { return; }
355 # Warning: $wguname is a live patch, it should be moved to Setup.php
356 global $wguname, $wgProfilePerHost;
358 $dbw = wfGetDB( DB_MASTER
);
359 if( !is_object( $dbw ) )
361 $errorState = $dbw->ignoreErrors( true );
363 $name = substr($name, 0, 255);
365 if( $wgProfilePerHost ){
366 $pfhost = $wguname['nodename'];
372 $timeSum = ($timeSum >= 0) ?
$timeSum : 0;
373 $memorySum = ($memorySum >= 0) ?
$memorySum : 0;
375 $dbw->update( 'profiling',
377 "pf_count=pf_count+{$eventCount}",
378 "pf_time=pf_time+{$timeSum}",
379 "pf_memory=pf_memory+{$memorySum}",
383 'pf_server' => $pfhost,
388 $rc = $dbw->affectedRows();
390 $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount,
391 'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ),
392 __METHOD__
, array ('IGNORE'));
394 // When we upgrade to mysql 4.1, the insert+update
395 // can be merged into just a insert with this construct added:
396 // "ON DUPLICATE KEY UPDATE ".
397 // "pf_count=pf_count + VALUES(pf_count), ".
398 // "pf_time=pf_time + VALUES(pf_time)";
399 $dbw->ignoreErrors( $errorState );
403 * Get the function name of the current profiling section
405 function getCurrentSection() {
406 $elt = end( $this->mWorkStack
);
411 * Get function caller
414 static function getCaller( $level ) {
415 $backtrace = wfDebugBacktrace();
416 if ( isset( $backtrace[$level] ) ) {
417 if ( isset( $backtrace[$level]['class'] ) ) {
418 $caller = $backtrace[$level]['class'] . '::' . $backtrace[$level]['function'];
420 $caller = $backtrace[$level]['function'];
429 * Add an entry in the debug log file
430 * @param string $s string to output
432 function debug( $s ) {
433 if( function_exists( 'wfDebug' ) ) {