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 ();
50 function __construct() {
51 // Push an entry for the pre-profile setup time onto the stack
52 global $wgRequestTime;
53 if ( !empty( $wgRequestTime ) ) {
54 $this->mWorkStack
[] = array( '-total', 0, $wgRequestTime, 0 );
55 $this->mStack
[] = array( '-setup', 1, $wgRequestTime, 0, microtime(true), 0 );
57 $this->profileIn( '-total' );
61 function profileIn($functionname) {
62 global $wgDebugFunctionEntry;
63 if ($wgDebugFunctionEntry && function_exists('wfDebug')) {
64 wfDebug(str_repeat(' ', count($this->mWorkStack
)).'Entering '.$functionname."\n");
66 $this->mWorkStack
[] = array($functionname, count( $this->mWorkStack
), $this->getTime(), memory_get_usage());
69 function profileOut($functionname) {
70 $memory = memory_get_usage();
71 $time = $this->getTime();
73 global $wgDebugFunctionEntry;
75 if ($wgDebugFunctionEntry && function_exists('wfDebug')) {
76 wfDebug(str_repeat(' ', count($this->mWorkStack
) - 1).'Exiting '.$functionname."\n");
79 $bit = array_pop($this->mWorkStack
);
82 wfDebug("Profiling error, !\$bit: $functionname\n");
84 //if ($wgDebugProfiling) {
85 if ($functionname == 'close') {
86 $message = "Profile section ended by close(): {$bit[0]}";
87 wfDebug( "$message\n" );
88 $this->mStack
[] = array( $message, 0, '0 0', 0, '0 0', 0 );
90 elseif ($bit[0] != $functionname) {
91 $message = "Profiling error: in({$bit[0]}), out($functionname)";
92 wfDebug( "$message\n" );
93 $this->mStack
[] = array( $message, 0, '0 0', 0, '0 0', 0 );
98 $this->mStack
[] = $bit;
103 while (count($this->mWorkStack
)) {
104 $this->profileOut('close');
108 function getOutput() {
109 global $wgDebugFunctionEntry;
110 $wgDebugFunctionEntry = false;
112 if (!count($this->mStack
) && !count($this->mCollated
)) {
113 return "No profiling output\n";
117 global $wgProfileCallTree;
118 if ($wgProfileCallTree) {
119 return $this->getCallTree();
121 return $this->getFunctionReport();
125 function getCallTree($start = 0) {
126 return implode('', array_map(array (& $this, 'getCallTreeLine'), $this->remapCallTree($this->mStack
)));
129 function remapCallTree($stack) {
130 if (count($stack) < 2) {
134 for ($max = count($stack) - 1; $max > 0;) {
135 /* Find all items under this entry */
136 $level = $stack[$max][1];
138 for ($i = $max -1; $i >= 0; $i --) {
139 if ($stack[$i][1] > $level) {
140 $working[] = $stack[$i];
145 $working = $this->remapCallTree(array_reverse($working));
147 foreach ($working as $item) {
148 array_push($output, $item);
150 array_unshift($output, $stack[$max]);
153 array_unshift($outputs, $output);
156 foreach ($outputs as $output) {
157 foreach ($output as $item) {
164 function getCallTreeLine($entry) {
165 list ($fname, $level, $start, /* $x */, $end) = $entry;
166 $delta = $end - $start;
167 $space = str_repeat(' ', $level);
169 # The ugly double sprintf is to work around a PHP bug,
170 # which has been fixed in recent releases.
171 return sprintf( "%10s %s %s\n",
172 trim( sprintf( "%7.3f", $delta * 1000.0 ) ),
177 return microtime(true);
178 #return $this->getUserTime();
181 function getUserTime() {
183 return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6
;
186 function getFunctionReport() {
188 $nameWidth = $width - 65;
189 $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n";
190 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
191 $prof = "\nProfiling data\n";
192 $prof .= sprintf($titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem');
193 $this->mCollated
= array ();
194 $this->mCalls
= array ();
195 $this->mMemory
= array ();
197 # Estimate profiling overhead
198 $profileCount = count($this->mStack
);
199 wfProfileIn('-overhead-total');
200 for ($i = 0; $i < $profileCount; $i ++
) {
201 wfProfileIn('-overhead-internal');
202 wfProfileOut('-overhead-internal');
204 wfProfileOut('-overhead-total');
206 # First, subtract the overhead!
207 foreach ($this->mStack
as $entry) {
211 $elapsed = $end - $start;
212 $memory = $entry[5] - $entry[3];
214 if ($fname == '-overhead-total') {
215 $overheadTotal[] = $elapsed;
216 $overheadMemory[] = $memory;
218 elseif ($fname == '-overhead-internal') {
219 $overheadInternal[] = $elapsed;
222 $overheadTotal = array_sum($overheadTotal) / count($overheadInternal);
223 $overheadMemory = array_sum($overheadMemory) / count($overheadInternal);
224 $overheadInternal = array_sum($overheadInternal) / count($overheadInternal);
227 foreach ($this->mStack
as $index => $entry) {
231 $elapsed = $end - $start;
233 $memory = $entry[5] - $entry[3];
234 $subcalls = $this->calltreeCount($this->mStack
, $index);
236 if (!preg_match('/^-overhead/', $fname)) {
237 # Adjust for profiling overhead (except special values with elapsed=0
239 $elapsed -= $overheadInternal;
240 $elapsed -= ($subcalls * $overheadTotal);
241 $memory -= ($subcalls * $overheadMemory);
245 if (!array_key_exists($fname, $this->mCollated
)) {
246 $this->mCollated
[$fname] = 0;
247 $this->mCalls
[$fname] = 0;
248 $this->mMemory
[$fname] = 0;
249 $this->mMin
[$fname] = 1 << 24;
250 $this->mMax
[$fname] = 0;
251 $this->mOverhead
[$fname] = 0;
254 $this->mCollated
[$fname] +
= $elapsed;
255 $this->mCalls
[$fname]++
;
256 $this->mMemory
[$fname] +
= $memory;
257 $this->mMin
[$fname] = min($this->mMin
[$fname], $elapsed);
258 $this->mMax
[$fname] = max($this->mMax
[$fname], $elapsed);
259 $this->mOverhead
[$fname] +
= $subcalls;
262 $total = @ $this->mCollated
['-total'];
263 $this->mCalls
['-overhead-total'] = $profileCount;
266 arsort($this->mCollated
, SORT_NUMERIC
);
267 foreach ($this->mCollated
as $fname => $elapsed) {
268 $calls = $this->mCalls
[$fname];
269 $percent = $total ?
100. * $elapsed / $total : 0;
270 $memory = $this->mMemory
[$fname];
271 $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]);
273 global $wgProfileToDatabase;
274 if ($wgProfileToDatabase) {
275 Profiler
:: logToDB($fname, (float) ($elapsed * 1000), $calls);
278 $prof .= "\nTotal: $total\n\n";
284 * Counts the number of profiled function calls sitting under
285 * the given point in the call graph. Not the most efficient algo.
287 * @param $stack Array:
288 * @param $start Integer:
292 function calltreeCount(& $stack, $start) {
293 $level = $stack[$start][1];
295 for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) {
304 function logToDB($name, $timeSum, $eventCount) {
305 # Warning: $wguname is a live patch, it should be moved to Setup.php
306 global $wguname, $wgProfilePerHost;
308 $fname = 'Profiler::logToDB';
309 $dbw = & wfGetDB(DB_MASTER
);
310 if (!is_object($dbw))
312 $errorState = $dbw->ignoreErrors( true );
313 $profiling = $dbw->tableName('profiling');
315 $name = substr($name, 0, 255);
316 $encname = $dbw->strencode($name);
318 if ($wgProfilePerHost) {
319 $pfhost = $wguname['nodename'];
324 $sql = "UPDATE $profiling "."SET pf_count=pf_count+{$eventCount}, "."pf_time=pf_time + {$timeSum} ".
325 "WHERE pf_name='{$encname}' AND pf_server='{$pfhost}'";
328 $rc = $dbw->affectedRows();
330 $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount,
331 'pf_time' => $timeSum, 'pf_server' => $pfhost ), $fname, array ('IGNORE'));
333 // When we upgrade to mysql 4.1, the insert+update
334 // can be merged into just a insert with this construct added:
335 // "ON DUPLICATE KEY UPDATE ".
336 // "pf_count=pf_count + VALUES(pf_count), ".
337 // "pf_time=pf_time + VALUES(pf_time)";
338 $dbw->ignoreErrors( $errorState );
342 * Get the function name of the current profiling section
344 function getCurrentSection() {
345 $elt = end($this->mWorkStack
);
349 static function getCaller( $level ) {
350 $backtrace = wfDebugBacktrace();
351 if ( isset( $backtrace[$level] ) ) {
352 if ( isset( $backtrace[$level]['class'] ) ) {
353 $caller = $backtrace[$level]['class'] . '::' . $backtrace[$level]['function'];
355 $caller = $backtrace[$level]['function'];