23 use Wikimedia\ScopedCallback;
55 $this->collateOnly = empty(
$params[
'trace'] );
99 $totalCpu = max( $this->end[
'cpu'] - $this->start[
'cpu'], 0 );
100 $totalReal = max( $this->end[
'real'] - $this->start[
'real'], 0 );
101 $totalMem = max( $this->end[
'memory'] - $this->start[
'memory'], 0 );
107 'calls' =>
$data[
'count'],
108 'real' =>
$data[
'real'] * 1000,
109 '%real' => $totalReal ? 100 *
$data[
'real'] / $totalReal : 0,
110 'cpu' =>
$data[
'cpu'] * 1000,
111 '%cpu' => $totalCpu ? 100 *
$data[
'cpu'] / $totalCpu : 0,
112 'memory' =>
$data[
'memory'],
113 '%memory' => $totalMem ? 100 *
$data[
'memory'] / $totalMem : 0,
114 'min_real' => 1000 *
$data[
'min_real'],
115 'max_real' => 1000 *
$data[
'max_real']
122 'real' => 1000 * $totalReal,
124 'cpu' => 1000 * $totalCpu,
126 'memory' => $totalMem,
128 'min_real' => 1000 * $totalReal,
129 'max_real' => 1000 * $totalReal
142 $this->workStack = [];
143 $this->collated = [];
144 $this->collateDone =
false;
179 $entry =& $this->collated[
$name];
180 if ( !is_array( $entry ) ) {
182 $this->collated[
$name] =& $entry;
184 $entry[
'cpu'] += $elapsedCpu;
185 $entry[
'real'] += $elapsedReal;
186 $entry[
'memory'] += $memChange > 0 ? $memChange : 0;
188 $entry[
'min_real'] = min( $entry[
'min_real'], $elapsedReal );
189 $entry[
'max_real'] = max( $entry[
'max_real'], $elapsedReal );
201 $this->collateDone =
false;
203 $cpu = $this->
getTime(
'cpu' );
204 $real = $this->
getTime(
'wall' );
205 $memory = memory_get_usage();
207 if ( $this->start ===
null ) {
208 $this->start = [
'cpu' => $cpu,
'real' => $real,
'memory' => $memory ];
211 $this->workStack[] = [
213 count( $this->workStack ),
226 $item = array_pop( $this->workStack );
227 if ( $item ===
null ) {
228 $this->
debugGroup(
'profileerror',
"Profiling error: $functionname" );
231 list( $ofname, , $ortime, $octime, $omem ) = $item;
233 if ( $functionname ===
'close' ) {
234 $message =
"Profile section ended by close(): {$ofname}";
235 $this->
debugGroup(
'profileerror', $message );
236 if ( $this->collateOnly ) {
239 $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
241 $functionname = $ofname;
242 } elseif ( $ofname !== $functionname ) {
243 $message =
"Profiling error: in({$ofname}), out($functionname)";
244 $this->
debugGroup(
'profileerror', $message );
245 if ( $this->collateOnly ) {
248 $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
252 $realTime = $this->
getTime(
'wall' );
253 $cpuTime = $this->
getTime(
'cpu' );
254 $memUsage = memory_get_usage();
256 if ( $this->collateOnly ) {
257 $elapsedcpu = $cpuTime - $octime;
258 $elapsedreal = $realTime - $ortime;
259 $memchange = $memUsage - $omem;
260 $this->
updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
262 $this->stack[] = array_merge( $item, [ $realTime, $cpuTime, $memUsage ] );
268 'memory' => $memUsage
278 if ( $this->collateOnly ) {
279 throw new Exception(
"Tree is only available for trace profiling." );
281 return implode(
'', array_map(
282 [ $this,
'getCallTreeLine' ], $this->
remapCallTree( $this->stack )
301 for ( $i = $max - 1; $i >= 0; $i-- ) {
302 if (
$stack[$i][1] > $level ) {
308 $working = $this->
remapCallTree( array_reverse( $working ) );
310 foreach ( $working
as $item ) {
316 array_unshift( $outputs,
$output );
334 list(
$fname, $level, $startreal, , , $endreal ) = $entry;
335 $delta = $endreal - $startreal;
336 $space = str_repeat(
' ', $level );
337 # The ugly double sprintf is to work around a PHP bug,
338 # which has been fixed in recent releases.
339 return sprintf(
"%10s %s %s\n",
340 trim( sprintf(
"%7.3f", $delta * 1000.0 ) ), $space,
$fname );
347 if ( $this->collateDone ) {
350 $this->collateDone =
true;
352 while (
count( $this->workStack ) ) {
356 if ( $this->collateOnly ) {
360 $this->collated = [];
362 # Estimate profiling overhead
364 $profileCount =
count( $this->stack );
367 # First, subtract the overhead!
368 $overheadTotal = $overheadMemory = $overheadInternal = [];
369 foreach ( $this->stack
as $entry ) {
372 $elapsed = $entry[5] - $entry[2];
373 $memchange = $entry[7] - $entry[4];
375 if (
$fname ===
'-overhead-total' ) {
376 $overheadTotal[] = $elapsed;
377 $overheadMemory[] = max( 0, $memchange );
378 } elseif (
$fname ===
'-overhead-internal' ) {
379 $overheadInternal[] = $elapsed;
382 $overheadTotal = $overheadTotal ?
383 array_sum( $overheadTotal ) /
count( $overheadInternal ) : 0;
384 $overheadMemory = $overheadMemory ?
385 array_sum( $overheadMemory ) /
count( $overheadInternal ) : 0;
386 $overheadInternal = $overheadInternal ?
387 array_sum( $overheadInternal ) /
count( $overheadInternal ) : 0;
390 foreach ( $this->stack
as $index => $entry ) {
393 $elapsedCpu = $entry[6] - $entry[3];
394 $elapsedReal = $entry[5] - $entry[2];
395 $memchange = $entry[7] - $entry[4];
398 if ( substr(
$fname, 0, 9 ) !==
'-overhead' ) {
399 # Adjust for profiling overhead (except special values with elapsed=0)
401 $elapsed -= $overheadInternal;
402 $elapsed -= ( $subcalls * $overheadTotal );
403 $memchange -= ( $subcalls * $overheadMemory );
410 $this->collated[
'-overhead-total'][
'count'] = $profileCount;
411 arsort( $this->collated, SORT_NUMERIC );
414 $this->end = $oldEnd;
424 for ( $i = 0; $i < $profileCount; $i++ ) {
442 for ( $i =
$start - 1; $i >= 0 &&
$stack[$i][1] > $level; $i-- ) {
458 protected function getTime( $metric =
'wall' ) {
459 if ( $metric ===
'cpu' || $metric ===
'user' ) {
464 $time = $ru[
'ru_utime.tv_sec'] + $ru[
'ru_utime.tv_usec'] / 1e6;
465 if ( $metric ===
'cpu' ) {
466 # This is the time of system calls, added to the user time
467 # it gives the total CPU time
468 $time += $ru[
'ru_stime.tv_sec'] + $ru[
'ru_stime.tv_usec'] / 1e6;
472 return microtime(
true );
482 if ( function_exists(
'wfDebug' ) ) {
494 if ( function_exists(
'wfDebugLog' ) ) {
516 parent::__construct(
null );
522 $this->profiler->profileOutInternal( $this->section );