24 use Wikimedia\ScopedCallback;
56 $this->collateOnly = empty(
$params[
'trace'] );
100 $totalCpu = max( $this->end[
'cpu'] - $this->start[
'cpu'], 0 );
101 $totalReal = max( $this->end[
'real'] - $this->start[
'real'], 0 );
102 $totalMem = max( $this->end[
'memory'] - $this->start[
'memory'], 0 );
105 foreach ( $this->collated
as $fname => $data ) {
108 'calls' => $data[
'count'],
109 'real' => $data[
'real'] * 1000,
110 '%real' => $totalReal ? 100 * $data[
'real'] / $totalReal : 0,
111 'cpu' => $data[
'cpu'] * 1000,
112 '%cpu' => $totalCpu ? 100 * $data[
'cpu'] / $totalCpu : 0,
113 'memory' => $data[
'memory'],
114 '%memory' => $totalMem ? 100 * $data[
'memory'] / $totalMem : 0,
115 'min_real' => 1000 * $data[
'min_real'],
116 'max_real' => 1000 * $data[
'max_real']
123 'real' => 1000 * $totalReal,
125 'cpu' => 1000 * $totalCpu,
127 'memory' => $totalMem,
129 'min_real' => 1000 * $totalReal,
130 'max_real' => 1000 * $totalReal
143 $this->workStack = [];
144 $this->collated = [];
145 $this->collateDone =
false;
180 $entry =& $this->collated[
$name];
181 if ( !is_array( $entry ) ) {
183 $this->collated[
$name] =& $entry;
185 $entry[
'cpu'] += $elapsedCpu;
186 $entry[
'real'] += $elapsedReal;
187 $entry[
'memory'] += $memChange > 0 ? $memChange : 0;
189 $entry[
'min_real'] = min( $entry[
'min_real'], $elapsedReal );
190 $entry[
'max_real'] = max( $entry[
'max_real'], $elapsedReal );
202 $this->collateDone =
false;
204 $cpu = $this->
getTime(
'cpu' );
205 $real = $this->
getTime(
'wall' );
206 $memory = memory_get_usage();
208 if ( $this->start ===
null ) {
209 $this->start = [
'cpu' => $cpu,
'real' => $real,
'memory' => $memory ];
212 $this->workStack[] = [
214 count( $this->workStack ),
227 $item = array_pop( $this->workStack );
228 if ( $item ===
null ) {
229 $this->
debugGroup(
'profileerror',
"Profiling error: $functionname" );
232 list( $ofname, , $ortime, $octime, $omem ) = $item;
234 if ( $functionname ===
'close' ) {
235 $message =
"Profile section ended by close(): {$ofname}";
236 $this->
debugGroup(
'profileerror', $message );
237 if ( $this->collateOnly ) {
240 $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
242 $functionname = $ofname;
243 } elseif ( $ofname !== $functionname ) {
244 $message =
"Profiling error: in({$ofname}), out($functionname)";
245 $this->
debugGroup(
'profileerror', $message );
246 if ( $this->collateOnly ) {
249 $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
253 $realTime = $this->
getTime(
'wall' );
254 $cpuTime = $this->
getTime(
'cpu' );
255 $memUsage = memory_get_usage();
257 if ( $this->collateOnly ) {
258 $elapsedcpu = $cpuTime - $octime;
259 $elapsedreal = $realTime - $ortime;
260 $memchange = $memUsage - $omem;
261 $this->
updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
263 $this->stack[] = array_merge( $item, [ $realTime, $cpuTime, $memUsage ] );
269 'memory' => $memUsage
279 if ( $this->collateOnly ) {
280 throw new Exception(
"Tree is only available for trace profiling." );
282 return implode(
'', array_map(
283 [ $this,
'getCallTreeLine' ], $this->
remapCallTree( $this->stack )
302 for ( $i = $max -1; $i >= 0; $i-- ) {
303 if (
$stack[$i][1] > $level ) {
309 $working = $this->
remapCallTree( array_reverse( $working ) );
311 foreach ( $working
as $item ) {
317 array_unshift( $outputs,
$output );
335 list(
$fname, $level, $startreal, , , $endreal ) = $entry;
336 $delta = $endreal - $startreal;
337 $space = str_repeat(
' ', $level );
338 # The ugly double sprintf is to work around a PHP bug,
339 # which has been fixed in recent releases.
340 return sprintf(
"%10s %s %s\n",
341 trim( sprintf(
"%7.3f", $delta * 1000.0 ) ), $space,
$fname );
348 if ( $this->collateDone ) {
351 $this->collateDone =
true;
353 while (
count( $this->workStack ) ) {
357 if ( $this->collateOnly ) {
361 $this->collated = [];
363 # Estimate profiling overhead
365 $profileCount =
count( $this->stack );
368 # First, subtract the overhead!
369 $overheadTotal = $overheadMemory = $overheadInternal = [];
370 foreach ( $this->stack
as $entry ) {
373 $elapsed = $entry[5] - $entry[2];
374 $memchange = $entry[7] - $entry[4];
376 if (
$fname ===
'-overhead-total' ) {
377 $overheadTotal[] = $elapsed;
378 $overheadMemory[] = max( 0, $memchange );
379 } elseif (
$fname ===
'-overhead-internal' ) {
380 $overheadInternal[] = $elapsed;
383 $overheadTotal = $overheadTotal ?
384 array_sum( $overheadTotal ) /
count( $overheadInternal ) : 0;
385 $overheadMemory = $overheadMemory ?
386 array_sum( $overheadMemory ) /
count( $overheadInternal ) : 0;
387 $overheadInternal = $overheadInternal ?
388 array_sum( $overheadInternal ) /
count( $overheadInternal ) : 0;
391 foreach ( $this->stack
as $index => $entry ) {
394 $elapsedCpu = $entry[6] - $entry[3];
395 $elapsedReal = $entry[5] - $entry[2];
396 $memchange = $entry[7] - $entry[4];
399 if ( substr(
$fname, 0, 9 ) !==
'-overhead' ) {
400 # Adjust for profiling overhead (except special values with elapsed=0)
402 $elapsed -= $overheadInternal;
403 $elapsed -= ( $subcalls * $overheadTotal );
404 $memchange -= ( $subcalls * $overheadMemory );
411 $this->collated[
'-overhead-total'][
'count'] = $profileCount;
412 arsort( $this->collated, SORT_NUMERIC );
415 $this->end = $oldEnd;
425 for ( $i = 0; $i < $profileCount; $i++ ) {
443 for ( $i =
$start -1; $i >= 0 &&
$stack[$i][1] > $level; $i-- ) {
459 protected function getTime( $metric =
'wall' ) {
460 if ( $metric ===
'cpu' || $metric ===
'user' ) {
465 $time = $ru[
'ru_utime.tv_sec'] + $ru[
'ru_utime.tv_usec'] / 1e6;
466 if ( $metric ===
'cpu' ) {
467 # This is the time of system calls, added to the user time
468 # it gives the total CPU time
469 $time += $ru[
'ru_stime.tv_sec'] + $ru[
'ru_stime.tv_usec'] / 1e6;
473 return microtime(
true );
483 if ( function_exists(
'wfDebug' ) ) {
495 if ( function_exists(
'wfDebugLog' ) ) {
517 parent::__construct(
null );
523 $this->profiler->profileOutInternal( $this->section );