3 * This file is only included if profiling is enabled
8 * @param $functioname name of the function we will profile
10 function wfProfileIn( $functionname ) {
12 $wgProfiler->profileIn( $functionname );
16 * @param $functioname name of the function we have profiled
18 function wfProfileOut( $functionname = 'missing' ) {
20 $wgProfiler->profileOut( $functionname );
23 function wfGetProfilingOutput( $start, $elapsed ) {
25 return $wgProfiler->getOutput( $start, $elapsed );
28 function wfProfileClose() {
33 if( !function_exists( 'memory_get_usage' ) ) {
34 # Old PHP or --enable-memory-limit not compiled in
35 function memory_get_usage() {
46 var $mStack = array(), $mWorkStack = array(), $mCollated = array();
47 var $mCalls = array(), $mTotals = array();
51 $this->mProfileStack = array();
52 $this->mWorkStack = array();
53 $this->mCollated = array();
57 function profileIn( $functionname ) {
58 global $wgDebugFunctionEntry;
59 if ( $wgDebugFunctionEntry && function_exists( 'wfDebug' ) ) {
60 wfDebug( str_repeat( ' ', count( $this->mWorkStack
) ) . 'Entering '.$functionname."\n" );
62 $this->mWorkStack
[] = array($functionname, count( $this->mWorkStack
), microtime(), memory_get_usage() );
65 function profileOut( $functionname ) {
66 $memory = memory_get_usage();
68 global $wgDebugProfiling, $wgDebugFunctionEntry;
70 if ( $wgDebugFunctionEntry && function_exists( 'wfDebug' ) ) {
71 wfDebug( str_repeat( ' ', count( $this->mWorkStack
) ) . 'Exiting '.$functionname."\n" );
74 $bit = array_pop( $this->mWorkStack
);
77 wfDebug( "Profiling error, !\$bit: $functionname\n" );
79 if ( $wgDebugProfiling ) {
80 if ( $functionname == 'close' ) {
81 wfDebug( "Profile section ended by close(): {$bit[0]}\n" );
82 } elseif ( $bit[0] != $functionname ) {
83 wfDebug( "Profiling error: in({$bit[0]}), out($functionname)\n" );
88 $this->mStack
[] = $bit;
93 while ( count( $this->mWorkStack
) ) {
94 $this->profileOut( 'close' );
98 function getOutput() {
99 global $wgDebugFunctionEntry;
100 $wgDebugFunctionEntry = false;
102 if( !count( $this->mStack
) ) {
103 return "No profiling output\n";
107 global $wgProfileCallTree;
108 if( $wgProfileCallTree ) {
109 return $this->getCallTree();
111 return $this->getFunctionReport();
115 function getCallTree( $start = 0 ) {
118 array( &$this, 'getCallTreeLine' ),
119 $this->remapCallTree( $this->mStack
) ) );
122 function remapCallTree( $stack ) {
123 if( count( $stack ) < 2 ) {
127 for( $max = count( $stack ) - 1; $max > 0; ) {
128 /* Find all items under this entry */
129 $level = $stack[$max][1];
131 for( $i = $max - 1; $i >= 0; $i-- ) {
132 if( $stack[$i][1] > $level ) {
133 $working[] = $stack[$i];
138 $working = $this->remapCallTree( array_reverse( $working ) );
140 foreach( $working as $item ) {
141 array_push( $output, $item );
143 array_unshift( $output, $stack[$max] );
146 array_unshift( $outputs, $output );
149 foreach( $outputs as $output ) {
150 foreach( $output as $item ) {
157 function getCallTreeLine( $entry ) {
158 list( $fname, $level, $start, $x, $end ) = $entry;
159 $delta = $this->microDelta( $start, $end );
160 $space = str_repeat( ' ', $level );
162 # The ugly double sprintf is to work around a PHP bug,
163 # which has been fixed in recent releases.
164 return sprintf( "%10s %s %s\n",
165 trim( sprintf( "%7.3f", $delta * 1000.0 ) ),
169 function micro2Float( $micro ) {
170 list( $whole, $fractional ) = explode( ' ', $micro );
171 return (float)$whole +
(float)$fractional;
174 function microDelta( $start, $end ) {
175 return $this->micro2Float( $end ) -
176 $this->micro2Float( $start );
179 function getFunctionReport() {
181 $format = "%-" . ($width - 34) . "s %6d %6.3f %6.3f %7.3f%% %6d (%6.3f-%6.3f) [%d]\n";
182 $titleFormat = "%-" . ($width - 34) . "s %9s %9s %9s %9s %6s\n";
183 $prof = "\nProfiling data\n";
184 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
185 $this->mCollated
= array();
186 $this->mCalls
= array();
187 $this->mMemory
= array();
189 # Estimate profiling overhead
190 $profileCount = count( $this->mStack
);
191 wfProfileIn( '-overhead-total' );
192 for ($i=0; $i<$profileCount ; $i++
) {
193 wfProfileIn( '-overhead-internal' );
194 wfProfileOut( '-overhead-internal' );
196 wfProfileOut( '-overhead-total' );
198 # First, subtract the overhead!
199 foreach( $this->mStack
as $entry ) {
201 $thislevel = $entry[1];
202 $start = explode( ' ', $entry[2]);
203 $start = (float)$start[0] +
(float)$start[1];
204 $end = explode( ' ', $entry[4]);
205 $end = (float)$end[0] +
(float)$end[1];
206 $elapsed = $end - $start;
207 $memory = $entry[5] - $entry[3];
209 if( $fname == '-overhead-total' ) {
210 $overheadTotal[] = $elapsed;
211 $overheadMemory[] = $memory;
212 } elseif( $fname == '-overhead-internal' ) {
213 $overheadInternal[] = $elapsed;
216 $overheadTotal = array_sum( $overheadTotal ) / count( $overheadInternal );
217 $overheadMemory = array_sum( $overheadMemory ) / count( $overheadInternal );
218 $overheadInternal = array_sum( $overheadInternal ) / count( $overheadInternal );
221 foreach ( $this->mStack
as $index => $entry ) {
223 $thislevel = $entry[1];
224 $start = explode( ' ', $entry[2]);
225 $start = (float)$start[0] +
(float)$start[1];
226 $end = explode( ' ', $entry[4]);
227 $end = (float)$end[0] +
(float)$end[1];
228 $elapsed = $end - $start;
230 $memory = $entry[5] - $entry[3];
231 $subcalls = $this->calltreeCount( $this->mStack
, $index );
233 if( !preg_match( '/^-overhead/', $fname ) ) {
234 # Adjust for profiling overhead
235 $elapsed -= $overheadInternal;
236 $elapsed -= ($subcalls * $overheadTotal);
237 $memory -= ($subcalls * $overheadMemory);
240 if ( !array_key_exists( $fname, $this->mCollated
) ) {
241 $this->mCollated
[$fname] = 0;
242 $this->mCalls
[$fname] = 0;
243 $this->mMemory
[$fname] = 0;
244 $this->mMin
[$fname] = 1 << 24;
245 $this->mMax
[$fname] = 0;
246 $this->mOverhead
[$fname] = 0;
249 $this->mCollated
[$fname] +
= $elapsed;
250 $this->mCalls
[$fname] ++
;
251 $this->mMemory
[$fname] +
= $memory;
252 $this->mMin
[$fname] = min( $this->mMin
[$fname], $elapsed );
253 $this->mMax
[$fname] = max( $this->mMax
[$fname], $elapsed );
254 $this->mOverhead
[$fname] +
= $subcalls;
257 $total = @$this->mCollated
['-total'];
258 $this->mCalls
['-overhead-total'] = $profileCount;
261 asort( $this->mCollated
, SORT_NUMERIC
);
262 foreach ( $this->mCollated
as $fname => $elapsed ) {
263 $calls = $this->mCalls
[$fname];
264 $percent = $total ?
100. * $elapsed / $total : 0;
265 $memory = $this->mMemory
[$fname];
266 $prof .= sprintf( $format, $fname, $calls, (float)($elapsed * 1000),
267 (float)($elapsed * 1000) / $calls, $percent, $memory,
268 ($this->mMin
[$fname] * 1000.0),
269 ($this->mMax
[$fname] * 1000.0),
270 $this->mOverhead
[$fname] );
272 global $wgProfileToDatabase;
273 if( $wgProfileToDatabase ) {
274 Profiler
::logToDB( $fname, (float)($elapsed * 1000), $calls );
277 $prof .= "\nTotal: $total\n\n";
283 * Counts the number of profiled function calls sitting under
284 * the given point in the call graph. Not the most efficient algo.
286 * @param array $stack
291 function calltreeCount( &$stack, $start ) {
292 $level = $stack[$start][1];
294 for( $i = $start - 1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
303 function logToDB($name, $timeSum, $eventCount) {
304 $fname = 'Profiler::logToDB';
305 $dbw =& wfGetDB( DB_MASTER
);
306 $profiling = $dbw->tableName( 'profiling' );
308 $name = substr($name,0,255);
309 $encname = $dbw->strencode($name);
310 $sql = "UPDATE $profiling ".
311 "SET pf_count=pf_count+{$eventCount}, ".
312 "pf_time=pf_time + {$timeSum} ".
313 "WHERE pf_name='{$encname}'";
316 $rc = $dbw->affectedRows();
318 $dbw->insert('profiling',array(
320 'pf_count'=>$eventCount,
321 'pf_time'=>$timeSum),
322 $fname,array('IGNORE'));
324 // When we upgrade to mysql 4.1, the insert+update
325 // can be merged into just a insert with this construct added:
326 // "ON DUPLICATE KEY UPDATE ".
327 // "pf_count=pf_count + VALUES(pf_count), ".
328 // "pf_time=pf_time + VALUES(pf_time)";
334 $wgProfiler = new Profiler();
335 $wgProfiler->profileIn( '-total' );