3 * @defgroup Profiler Profiler
7 * This file is only included if profiling is enabled
10 /** backward compatibility */
14 * Begin profiling of a function
15 * @param $functionname name of the function we will profile
17 function wfProfileIn( $functionname ) {
19 $wgProfiler->profileIn( $functionname );
23 * Stop profiling of a function
24 * @param $functionname name of the function we have profiled
26 function wfProfileOut( $functionname = 'missing' ) {
28 $wgProfiler->profileOut( $functionname );
32 * Returns a profiling output to be stored in debug file
35 * @param $elapsed Float: time elapsed since the beginning of the request
37 function wfGetProfilingOutput( $start, $elapsed ) {
39 return $wgProfiler->getOutput( $start, $elapsed );
43 * Close opened profiling sections
45 function wfProfileClose() {
50 if (!function_exists('memory_get_usage')) {
51 # Old PHP or --enable-memory-limit not compiled in
52 function memory_get_usage() {
62 var $mStack = array (), $mWorkStack = array (), $mCollated = array ();
63 var $mCalls = array (), $mTotals = array ();
64 var $mTemplated = false;
66 function __construct() {
67 // Push an entry for the pre-profile setup time onto the stack
68 global $wgRequestTime;
69 if ( !empty( $wgRequestTime ) ) {
70 $this->mWorkStack
[] = array( '-total', 0, $wgRequestTime, 0 );
71 $this->mStack
[] = array( '-setup', 1, $wgRequestTime, 0, microtime(true), 0 );
73 $this->profileIn( '-total' );
78 * Called by wfProfieIn()
79 * @param $functionname string
81 function profileIn( $functionname ) {
82 global $wgDebugFunctionEntry, $wgProfiling;
83 if( !$wgProfiling ) return;
84 if( $wgDebugFunctionEntry ){
85 $this->debug( str_repeat( ' ', count( $this->mWorkStack
) ) . 'Entering ' . $functionname . "\n" );
88 $this->mWorkStack
[] = array( $functionname, count( $this->mWorkStack
), $this->getTime(), memory_get_usage() );
92 * Called by wfProfieOut()
93 * @param $functionname string
95 function profileOut($functionname) {
96 global $wgDebugFunctionEntry, $wgProfiling;
97 if( !$wgProfiling ) return;
98 $memory = memory_get_usage();
99 $time = $this->getTime();
101 if( $wgDebugFunctionEntry ){
102 $this->debug( str_repeat( ' ', count( $this->mWorkStack
) - 1 ) . 'Exiting ' . $functionname . "\n" );
105 $bit = array_pop($this->mWorkStack
);
108 $this->debug("Profiling error, !\$bit: $functionname\n");
110 //if( $wgDebugProfiling ){
111 if( $functionname == 'close' ){
112 $message = "Profile section ended by close(): {$bit[0]}";
113 $this->debug( "$message\n" );
114 $this->mStack
[] = array( $message, 0, '0 0', 0, '0 0', 0 );
116 elseif( $bit[0] != $functionname ){
117 $message = "Profiling error: in({$bit[0]}), out($functionname)";
118 $this->debug( "$message\n" );
119 $this->mStack
[] = array( $message, 0, '0 0', 0, '0 0', 0 );
124 $this->mStack
[] = $bit;
129 * called by wfProfileClose()
134 # Avoid infinite loop
138 while( count( $this->mWorkStack
) ){
139 $this->profileOut( 'close' );
144 * Mark this call as templated or not
147 function setTemplated( $t ) {
148 $this->mTemplated
= $t;
152 * called by wfGetProfilingOutput()
154 function getOutput() {
155 global $wgDebugFunctionEntry, $wgProfileCallTree;
156 $wgDebugFunctionEntry = false;
158 if( !count( $this->mStack
) && !count( $this->mCollated
) ){
159 return "No profiling output\n";
163 if( $wgProfileCallTree ) {
164 global $wgProfileToDatabase;
165 # XXX: We must call $this->getFunctionReport() to log to the DB
166 if( $wgProfileToDatabase ) {
167 $this->getFunctionReport();
169 return $this->getCallTree();
171 return $this->getFunctionReport();
176 * returns a tree of function call instead of a list of functions
178 function getCallTree() {
179 return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack
) ) );
183 * Recursive function the format the current profiling array into a tree
185 * @param $stack profiling array
187 function remapCallTree( $stack ) {
188 if( count( $stack ) < 2 ){
192 for( $max = count( $stack ) - 1; $max > 0; ){
193 /* Find all items under this entry */
194 $level = $stack[$max][1];
196 for( $i = $max -1; $i >= 0; $i-- ){
197 if( $stack[$i][1] > $level ){
198 $working[] = $stack[$i];
203 $working = $this->remapCallTree( array_reverse( $working ) );
205 foreach( $working as $item ){
206 array_push( $output, $item );
208 array_unshift( $output, $stack[$max] );
211 array_unshift( $outputs, $output );
214 foreach( $outputs as $output ){
215 foreach( $output as $item ){
223 * Callback to get a formatted line for the call tree
225 function getCallTreeLine( $entry ) {
226 list( $fname, $level, $start, /* $x */, $end) = $entry;
227 $delta = $end - $start;
228 $space = str_repeat(' ', $level);
229 # The ugly double sprintf is to work around a PHP bug,
230 # which has been fixed in recent releases.
231 return sprintf( "%10s %s %s\n", trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
235 return microtime(true);
236 #return $this->getUserTime();
239 function getUserTime() {
241 return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6
;
245 * Returns a list of profiled functions.
246 * Also log it into the database if $wgProfileToDatabase is set to true.
248 function getFunctionReport() {
249 global $wgProfileToDatabase;
252 $nameWidth = $width - 65;
253 $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n";
254 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
255 $prof = "\nProfiling data\n";
256 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
257 $this->mCollated
= array ();
258 $this->mCalls
= array ();
259 $this->mMemory
= array ();
261 # Estimate profiling overhead
262 $profileCount = count($this->mStack
);
263 wfProfileIn( '-overhead-total' );
264 for( $i = 0; $i < $profileCount; $i ++
){
265 wfProfileIn( '-overhead-internal' );
266 wfProfileOut( '-overhead-internal' );
268 wfProfileOut( '-overhead-total' );
270 # First, subtract the overhead!
271 $overheadTotal = $overheadMemory = $overheadInternal = array();
272 foreach( $this->mStack
as $entry ){
276 $elapsed = $end - $start;
277 $memory = $entry[5] - $entry[3];
279 if( $fname == '-overhead-total' ){
280 $overheadTotal[] = $elapsed;
281 $overheadMemory[] = $memory;
283 elseif( $fname == '-overhead-internal' ){
284 $overheadInternal[] = $elapsed;
287 $overheadTotal = $overheadTotal ?
array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
288 $overheadMemory = $overheadMemory ?
array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
289 $overheadInternal = $overheadInternal ?
array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
292 foreach( $this->mStack
as $index => $entry ){
296 $elapsed = $end - $start;
298 $memory = $entry[5] - $entry[3];
299 $subcalls = $this->calltreeCount( $this->mStack
, $index );
301 if( !preg_match( '/^-overhead/', $fname ) ){
302 # Adjust for profiling overhead (except special values with elapsed=0
304 $elapsed -= $overheadInternal;
305 $elapsed -= ($subcalls * $overheadTotal);
306 $memory -= ($subcalls * $overheadMemory);
310 if( !array_key_exists( $fname, $this->mCollated
) ){
311 $this->mCollated
[$fname] = 0;
312 $this->mCalls
[$fname] = 0;
313 $this->mMemory
[$fname] = 0;
314 $this->mMin
[$fname] = 1 << 24;
315 $this->mMax
[$fname] = 0;
316 $this->mOverhead
[$fname] = 0;
319 $this->mCollated
[$fname] +
= $elapsed;
320 $this->mCalls
[$fname]++
;
321 $this->mMemory
[$fname] +
= $memory;
322 $this->mMin
[$fname] = min($this->mMin
[$fname], $elapsed);
323 $this->mMax
[$fname] = max($this->mMax
[$fname], $elapsed);
324 $this->mOverhead
[$fname] +
= $subcalls;
327 $total = @$this->mCollated
['-total'];
328 $this->mCalls
['-overhead-total'] = $profileCount;
331 arsort( $this->mCollated
, SORT_NUMERIC
);
332 foreach( $this->mCollated
as $fname => $elapsed ){
333 $calls = $this->mCalls
[$fname];
334 $percent = $total ?
100. * $elapsed / $total : 0;
335 $memory = $this->mMemory
[$fname];
336 $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]);
338 if( $wgProfileToDatabase ) {
339 self
::logToDB($fname, (float) ($elapsed * 1000), $calls, (float) ($memory) );
342 $prof .= "\nTotal: $total\n\n";
348 * Counts the number of profiled function calls sitting under
349 * the given point in the call graph. Not the most efficient algo.
351 * @param $stack Array:
352 * @param $start Integer:
356 function calltreeCount($stack, $start) {
357 $level = $stack[$start][1];
359 for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) {
366 * Log a function into the database.
368 * @param $name string: function name
369 * @param $timeSum float
370 * @param $eventCount int: number of times that function was called
372 static function logToDB( $name, $timeSum, $eventCount, $memorySum ){
373 # Do not log anything if database is readonly (bug 5375)
374 if( wfReadOnly() ) { return; }
376 global $wgProfilePerHost;
378 $dbw = wfGetDB( DB_MASTER
);
379 if( !is_object( $dbw ) )
381 $errorState = $dbw->ignoreErrors( true );
383 $name = substr($name, 0, 255);
385 if( $wgProfilePerHost ){
386 $pfhost = wfHostname();
392 $timeSum = ($timeSum >= 0) ?
$timeSum : 0;
393 $memorySum = ($memorySum >= 0) ?
$memorySum : 0;
395 $dbw->update( 'profiling',
397 "pf_count=pf_count+{$eventCount}",
398 "pf_time=pf_time+{$timeSum}",
399 "pf_memory=pf_memory+{$memorySum}",
403 'pf_server' => $pfhost,
408 $rc = $dbw->affectedRows();
410 $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount,
411 'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ),
412 __METHOD__
, array ('IGNORE'));
414 // When we upgrade to mysql 4.1, the insert+update
415 // can be merged into just a insert with this construct added:
416 // "ON DUPLICATE KEY UPDATE ".
417 // "pf_count=pf_count + VALUES(pf_count), ".
418 // "pf_time=pf_time + VALUES(pf_time)";
419 $dbw->ignoreErrors( $errorState );
423 * Get the function name of the current profiling section
425 function getCurrentSection() {
426 $elt = end( $this->mWorkStack
);
431 * Get function caller
434 static function getCaller( $level ) {
435 $backtrace = wfDebugBacktrace();
436 if ( isset( $backtrace[$level] ) ) {
437 if ( isset( $backtrace[$level]['class'] ) ) {
438 $caller = $backtrace[$level]['class'] . '::' . $backtrace[$level]['function'];
440 $caller = $backtrace[$level]['function'];
449 * Add an entry in the debug log file
450 * @param $s string to output
452 function debug( $s ) {
453 if( function_exists( 'wfDebug' ) ) {