3 * This file is only included if profiling is enabled
10 * @param $functioname name of the function we will profile
12 function wfProfileIn($functionname) {
14 $wgProfiler->profileIn($functionname);
18 * @param $functioname name of the function we have profiled
20 function wfProfileOut($functionname = 'missing') {
22 $wgProfiler->profileOut($functionname);
25 function wfGetProfilingOutput($start, $elapsed) {
27 return $wgProfiler->getOutput($start, $elapsed);
30 function wfProfileClose() {
35 if (!function_exists('memory_get_usage')) {
36 # Old PHP or --enable-memory-limit not compiled in
37 function memory_get_usage() {
47 var $mStack = array (), $mWorkStack = array (), $mCollated = array ();
48 var $mCalls = array (), $mTotals = array ();
52 // Push an entry for the pre-profile setup time onto the stack
53 global $wgRequestTime;
54 if ( !empty( $wgRequestTime ) ) {
55 $this->mWorkStack
[] = array( '-total', 0, $wgRequestTime, 0 );
56 $this->mStack
[] = array( '-setup', 1, $wgRequestTime, 0, microtime(true), 0 );
58 $this->profileIn( '-total' );
63 function profileIn($functionname) {
64 global $wgDebugFunctionEntry;
65 if ($wgDebugFunctionEntry && function_exists('wfDebug')) {
66 wfDebug(str_repeat(' ', count($this->mWorkStack
)).'Entering '.$functionname."\n");
68 $this->mWorkStack
[] = array($functionname, count( $this->mWorkStack
), $this->getTime(), memory_get_usage());
71 function profileOut($functionname) {
72 $memory = memory_get_usage();
73 $time = $this->getTime();
75 global $wgDebugFunctionEntry;
77 if ($wgDebugFunctionEntry && function_exists('wfDebug')) {
78 wfDebug(str_repeat(' ', count($this->mWorkStack
) - 1).'Exiting '.$functionname."\n");
81 $bit = array_pop($this->mWorkStack
);
84 wfDebug("Profiling error, !\$bit: $functionname\n");
86 //if ($wgDebugProfiling) {
87 if ($functionname == 'close') {
88 $message = "Profile section ended by close(): {$bit[0]}";
89 wfDebug( "$message\n" );
90 $this->mStack
[] = array( $message, 0, '0 0', 0, '0 0', 0 );
92 elseif ($bit[0] != $functionname) {
93 $message = "Profiling error: in({$bit[0]}), out($functionname)";
94 wfDebug( "$message\n" );
95 $this->mStack
[] = array( $message, 0, '0 0', 0, '0 0', 0 );
100 $this->mStack
[] = $bit;
105 while (count($this->mWorkStack
)) {
106 $this->profileOut('close');
110 function getOutput() {
111 global $wgDebugFunctionEntry;
112 $wgDebugFunctionEntry = false;
114 if (!count($this->mStack
) && !count($this->mCollated
)) {
115 return "No profiling output\n";
119 global $wgProfileCallTree;
120 if ($wgProfileCallTree) {
121 return $this->getCallTree();
123 return $this->getFunctionReport();
127 function getCallTree($start = 0) {
128 return implode('', array_map(array (& $this, 'getCallTreeLine'), $this->remapCallTree($this->mStack
)));
131 function remapCallTree($stack) {
132 if (count($stack) < 2) {
136 for ($max = count($stack) - 1; $max > 0;) {
137 /* Find all items under this entry */
138 $level = $stack[$max][1];
140 for ($i = $max -1; $i >= 0; $i --) {
141 if ($stack[$i][1] > $level) {
142 $working[] = $stack[$i];
147 $working = $this->remapCallTree(array_reverse($working));
149 foreach ($working as $item) {
150 array_push($output, $item);
152 array_unshift($output, $stack[$max]);
155 array_unshift($outputs, $output);
158 foreach ($outputs as $output) {
159 foreach ($output as $item) {
166 function getCallTreeLine($entry) {
167 list ($fname, $level, $start, /* $x */, $end) = $entry;
168 $delta = $end - $start;
169 $space = str_repeat(' ', $level);
171 # The ugly double sprintf is to work around a PHP bug,
172 # which has been fixed in recent releases.
173 return sprintf( "%10s %s %s\n",
174 trim( sprintf( "%7.3f", $delta * 1000.0 ) ),
179 return microtime(true);
180 #return $this->getUserTime();
183 function getUserTime() {
185 return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6
;
188 function getFunctionReport() {
190 $nameWidth = $width - 65;
191 $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n";
192 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
193 $prof = "\nProfiling data\n";
194 $prof .= sprintf($titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem');
195 $this->mCollated
= array ();
196 $this->mCalls
= array ();
197 $this->mMemory
= array ();
199 # Estimate profiling overhead
200 $profileCount = count($this->mStack
);
201 wfProfileIn('-overhead-total');
202 for ($i = 0; $i < $profileCount; $i ++
) {
203 wfProfileIn('-overhead-internal');
204 wfProfileOut('-overhead-internal');
206 wfProfileOut('-overhead-total');
208 # First, subtract the overhead!
209 foreach ($this->mStack
as $entry) {
213 $elapsed = $end - $start;
214 $memory = $entry[5] - $entry[3];
216 if ($fname == '-overhead-total') {
217 $overheadTotal[] = $elapsed;
218 $overheadMemory[] = $memory;
220 elseif ($fname == '-overhead-internal') {
221 $overheadInternal[] = $elapsed;
224 $overheadTotal = array_sum($overheadTotal) / count($overheadInternal);
225 $overheadMemory = array_sum($overheadMemory) / count($overheadInternal);
226 $overheadInternal = array_sum($overheadInternal) / count($overheadInternal);
229 foreach ($this->mStack
as $index => $entry) {
233 $elapsed = $end - $start;
235 $memory = $entry[5] - $entry[3];
236 $subcalls = $this->calltreeCount($this->mStack
, $index);
238 if (!preg_match('/^-overhead/', $fname)) {
239 # Adjust for profiling overhead (except special values with elapsed=0
241 $elapsed -= $overheadInternal;
242 $elapsed -= ($subcalls * $overheadTotal);
243 $memory -= ($subcalls * $overheadMemory);
247 if (!array_key_exists($fname, $this->mCollated
)) {
248 $this->mCollated
[$fname] = 0;
249 $this->mCalls
[$fname] = 0;
250 $this->mMemory
[$fname] = 0;
251 $this->mMin
[$fname] = 1 << 24;
252 $this->mMax
[$fname] = 0;
253 $this->mOverhead
[$fname] = 0;
256 $this->mCollated
[$fname] +
= $elapsed;
257 $this->mCalls
[$fname]++
;
258 $this->mMemory
[$fname] +
= $memory;
259 $this->mMin
[$fname] = min($this->mMin
[$fname], $elapsed);
260 $this->mMax
[$fname] = max($this->mMax
[$fname], $elapsed);
261 $this->mOverhead
[$fname] +
= $subcalls;
264 $total = @ $this->mCollated
['-total'];
265 $this->mCalls
['-overhead-total'] = $profileCount;
268 arsort($this->mCollated
, SORT_NUMERIC
);
269 foreach ($this->mCollated
as $fname => $elapsed) {
270 $calls = $this->mCalls
[$fname];
271 $percent = $total ?
100. * $elapsed / $total : 0;
272 $memory = $this->mMemory
[$fname];
273 $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]);
275 global $wgProfileToDatabase;
276 if ($wgProfileToDatabase) {
277 Profiler
:: logToDB($fname, (float) ($elapsed * 1000), $calls);
280 $prof .= "\nTotal: $total\n\n";
286 * Counts the number of profiled function calls sitting under
287 * the given point in the call graph. Not the most efficient algo.
289 * @param $stack Array:
290 * @param $start Integer:
294 function calltreeCount(& $stack, $start) {
295 $level = $stack[$start][1];
297 for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) {
306 function logToDB($name, $timeSum, $eventCount) {
307 # Warning: $wguname is a live patch, it should be moved to Setup.php
308 global $wguname, $wgProfilePerHost;
310 $fname = 'Profiler::logToDB';
311 $dbw = & wfGetDB(DB_MASTER
);
312 if (!is_object($dbw))
314 $errorState = $dbw->ignoreErrors( true );
315 $profiling = $dbw->tableName('profiling');
317 $name = substr($name, 0, 255);
318 $encname = $dbw->strencode($name);
320 if ($wgProfilePerHost) {
321 $pfhost = $wguname['nodename'];
326 $sql = "UPDATE $profiling "."SET pf_count=pf_count+{$eventCount}, "."pf_time=pf_time + {$timeSum} ".
327 "WHERE pf_name='{$encname}' AND pf_server='{$pfhost}'";
330 $rc = $dbw->affectedRows();
332 $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount,
333 'pf_time' => $timeSum, 'pf_server' => $pfhost ), $fname, array ('IGNORE'));
335 // When we upgrade to mysql 4.1, the insert+update
336 // can be merged into just a insert with this construct added:
337 // "ON DUPLICATE KEY UPDATE ".
338 // "pf_count=pf_count + VALUES(pf_count), ".
339 // "pf_time=pf_time + VALUES(pf_time)";
340 $dbw->ignoreErrors( $errorState );
344 * Get the function name of the current profiling section
346 function getCurrentSection() {
347 $elt = end($this->mWorkStack
);
351 static function getCaller( $level ) {
352 $backtrace = debug_backtrace();
353 if ( isset( $backtrace[$level] ) ) {
354 if ( isset( $backtrace[$level]['class'] ) ) {
355 $caller = $backtrace[$level]['class'] . '::' . $backtrace[$level]['function'];
357 $caller = $backtrace[$level]['function'];