MediaWiki  master
SectionProfiler.php
Go to the documentation of this file.
1 <?php
22 use Psr\Log\LoggerInterface;
23 use Wikimedia\ScopedCallback;
24 
35  protected $start;
37  protected $end;
39  protected $stack = [];
41  protected $workStack = [];
42 
44  protected $collated = [];
46  protected $collateDone = false;
47 
49  protected $collateOnly = true;
51  protected $errorEntry;
53  protected $logger;
54 
58  public function __construct( array $params = [] ) {
59  $this->errorEntry = $this->getErrorEntry();
60  $this->collateOnly = empty( $params['trace'] );
61  $this->logger = LoggerFactory::getInstance( 'profiler' );
62  }
63 
68  public function scopedProfileIn( $section ) {
69  $this->profileInInternal( $section );
70 
71  return new SectionProfileCallback( $this, $section );
72  }
73 
77  public function scopedProfileOut( ScopedCallback &$section ) {
78  $section = null;
79  }
80 
102  public function getFunctionStats() {
103  $this->collateData();
104 
105  if ( is_array( $this->start ) && is_array( $this->end ) ) {
106  $totalCpu = max( $this->end['cpu'] - $this->start['cpu'], 0 );
107  $totalReal = max( $this->end['real'] - $this->start['real'], 0 );
108  $totalMem = max( $this->end['memory'] - $this->start['memory'], 0 );
109  } else {
110  $totalCpu = 0;
111  $totalReal = 0;
112  $totalMem = 0;
113  }
114 
115  $profile = [];
116  foreach ( $this->collated as $fname => $data ) {
117  $profile[] = [
118  'name' => $fname,
119  'calls' => $data['count'],
120  'real' => $data['real'] * 1000,
121  '%real' => $totalReal ? 100 * $data['real'] / $totalReal : 0,
122  'cpu' => $data['cpu'] * 1000,
123  '%cpu' => $totalCpu ? 100 * $data['cpu'] / $totalCpu : 0,
124  'memory' => $data['memory'],
125  '%memory' => $totalMem ? 100 * $data['memory'] / $totalMem : 0,
126  'min_real' => 1000 * $data['min_real'],
127  'max_real' => 1000 * $data['max_real']
128  ];
129  }
130 
131  $profile[] = [
132  'name' => '-total',
133  'calls' => 1,
134  'real' => 1000 * $totalReal,
135  '%real' => 100,
136  'cpu' => 1000 * $totalCpu,
137  '%cpu' => 100,
138  'memory' => $totalMem,
139  '%memory' => 100,
140  'min_real' => 1000 * $totalReal,
141  'max_real' => 1000 * $totalReal
142  ];
143 
144  return $profile;
145  }
146 
150  public function reset() {
151  $this->start = null;
152  $this->end = null;
153  $this->stack = [];
154  $this->workStack = [];
155  $this->collated = [];
156  $this->collateDone = false;
157  }
158 
162  protected function getZeroEntry() {
163  return [
164  'cpu' => 0.0,
165  'real' => 0.0,
166  'memory' => 0,
167  'count' => 0,
168  'min_real' => 0.0,
169  'max_real' => 0.0
170  ];
171  }
172 
176  protected function getErrorEntry() {
177  $entry = $this->getZeroEntry();
178  $entry['count'] = 1;
179  return $entry;
180  }
181 
190  protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) {
191  $entry =& $this->collated[$name];
192  if ( !is_array( $entry ) ) {
193  $entry = $this->getZeroEntry();
194  $this->collated[$name] =& $entry;
195  }
196  $entry['cpu'] += $elapsedCpu;
197  $entry['real'] += $elapsedReal;
198  $entry['memory'] += $memChange > 0 ? $memChange : 0;
199  $entry['count']++;
200  $entry['min_real'] = min( $entry['min_real'], $elapsedReal );
201  $entry['max_real'] = max( $entry['max_real'], $elapsedReal );
202  }
203 
209  public function profileInInternal( $functionname ) {
210  // Once the data is collated for reports, any future calls
211  // should clear the collation cache so the next report will
212  // reflect them. This matters when trace mode is used.
213  $this->collateDone = false;
214 
215  $cpu = $this->getTime( 'cpu' );
216  $real = $this->getTime( 'wall' );
217  $memory = memory_get_usage();
218 
219  if ( $this->start === null ) {
220  $this->start = [ 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ];
221  }
222 
223  $this->workStack[] = [
224  $functionname,
225  count( $this->workStack ),
226  $real,
227  $cpu,
228  $memory
229  ];
230  }
231 
237  public function profileOutInternal( $functionname ) {
238  $item = array_pop( $this->workStack );
239  if ( $item === null ) {
240  $this->logger->error( "Profiling error: $functionname" );
241  return;
242  }
243  list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item;
244 
245  if ( $functionname === 'close' ) {
246  $message = "Profile section ended by close(): {$ofname}";
247  $this->logger->error( $message );
248  if ( $this->collateOnly ) {
249  $this->collated[$message] = $this->errorEntry;
250  } else {
251  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
252  }
253  $functionname = $ofname;
254  } elseif ( $ofname !== $functionname ) {
255  $message = "Profiling error: in({$ofname}), out($functionname)";
256  $this->logger->error( $message );
257  if ( $this->collateOnly ) {
258  $this->collated[$message] = $this->errorEntry;
259  } else {
260  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
261  }
262  }
263 
264  $realTime = $this->getTime( 'wall' );
265  $cpuTime = $this->getTime( 'cpu' );
266  $memUsage = memory_get_usage();
267 
268  if ( $this->collateOnly ) {
269  $elapsedcpu = $cpuTime - $octime;
270  $elapsedreal = $realTime - $ortime;
271  $memchange = $memUsage - $omem;
272  $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
273  } else {
274  $this->stack[] = array_merge( $item, [ $realTime, $cpuTime, $memUsage ] );
275  }
276 
277  $this->end = [
278  'cpu' => $cpuTime,
279  'real' => $realTime,
280  'memory' => $memUsage
281  ];
282  }
283 
289  public function getCallTreeReport() {
290  if ( $this->collateOnly ) {
291  throw new Exception( "Tree is only available for trace profiling." );
292  }
293  return implode( '', array_map(
294  [ $this, 'getCallTreeLine' ], $this->remapCallTree( $this->stack )
295  ) );
296  }
297 
304  protected function remapCallTree( array $stack ) {
305  if ( count( $stack ) < 2 ) {
306  return $stack;
307  }
308  $outputs = [];
309  for ( $max = count( $stack ) - 1; $max > 0; ) {
310  /* Find all items under this entry */
311  $level = $stack[$max][1];
312  $working = [];
313  for ( $i = $max - 1; $i >= 0; $i-- ) {
314  if ( $stack[$i][1] > $level ) {
315  $working[] = $stack[$i];
316  } else {
317  break;
318  }
319  }
320  $working = $this->remapCallTree( array_reverse( $working ) );
321  $output = [];
322  foreach ( $working as $item ) {
323  array_push( $output, $item );
324  }
325  array_unshift( $output, $stack[$max] );
326  $max = $i;
327 
328  array_unshift( $outputs, $output );
329  }
330  $final = [];
331  foreach ( $outputs as $output ) {
332  foreach ( $output as $item ) {
333  $final[] = $item;
334  }
335  }
336  return $final;
337  }
338 
344  protected function getCallTreeLine( $entry ) {
345  // $entry has (name, level, stime, scpu, smem, etime, ecpu, emem)
346  list( $fname, $level, $startreal, , , $endreal ) = $entry;
347  $delta = $endreal - $startreal;
348  $space = str_repeat( ' ', $level );
349  # The ugly double sprintf is to work around a PHP bug,
350  # which has been fixed in recent releases.
351  return sprintf( "%10s %s %s\n",
352  trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
353  }
354 
358  protected function collateData() {
359  if ( $this->collateDone ) {
360  return;
361  }
362  $this->collateDone = true;
363  // Close opened profiling sections
364  while ( count( $this->workStack ) ) {
365  $this->profileOutInternal( 'close' );
366  }
367 
368  if ( $this->collateOnly ) {
369  return; // already collated as methods exited
370  }
371 
372  $this->collated = [];
373 
374  # Estimate profiling overhead
375  $oldEnd = $this->end;
376  $profileCount = count( $this->stack );
377  $this->calculateOverhead( $profileCount );
378 
379  # First, subtract the overhead!
380  $overheadTotal = $overheadMemory = $overheadInternal = [];
381  foreach ( $this->stack as $entry ) {
382  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
383  $fname = $entry[0];
384  $elapsed = $entry[5] - $entry[2];
385  $memchange = $entry[7] - $entry[4];
386 
387  if ( $fname === '-overhead-total' ) {
388  $overheadTotal[] = $elapsed;
389  $overheadMemory[] = max( 0, $memchange );
390  } elseif ( $fname === '-overhead-internal' ) {
391  $overheadInternal[] = $elapsed;
392  }
393  }
394  $overheadTotal = $overheadTotal ?
395  array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
396  $overheadMemory = $overheadMemory ?
397  array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
398  $overheadInternal = $overheadInternal ?
399  array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
400 
401  # Collate
402  foreach ( $this->stack as $index => $entry ) {
403  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
404  $fname = $entry[0];
405  $elapsedCpu = $entry[6] - $entry[3];
406  $elapsedReal = $entry[5] - $entry[2];
407  $memchange = $entry[7] - $entry[4];
408  $subcalls = $this->calltreeCount( $this->stack, $index );
409 
410  if ( substr( $fname, 0, 9 ) !== '-overhead' ) {
411  # Adjust for profiling overhead (except special values with elapsed=0)
412  if ( $elapsed ) {
413  $elapsed -= $overheadInternal;
414  $elapsed -= ( $subcalls * $overheadTotal );
415  $memchange -= ( $subcalls * $overheadMemory );
416  }
417  }
418 
419  $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange );
420  }
421 
422  $this->collated['-overhead-total']['count'] = $profileCount;
423  arsort( $this->collated, SORT_NUMERIC );
424 
425  // Unclobber the end info map (the overhead checking alters it)
426  $this->end = $oldEnd;
427  }
428 
434  protected function calculateOverhead( $profileCount ) {
435  $this->profileInInternal( '-overhead-total' );
436  for ( $i = 0; $i < $profileCount; $i++ ) {
437  $this->profileInInternal( '-overhead-internal' );
438  $this->profileOutInternal( '-overhead-internal' );
439  }
440  $this->profileOutInternal( '-overhead-total' );
441  }
442 
451  protected function calltreeCount( $stack, $start ) {
452  $level = $stack[$start][1];
453  $count = 0;
454  for ( $i = $start - 1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
455  $count++;
456  }
457  return $count;
458  }
459 
470  protected function getTime( $metric = 'wall' ) {
471  if ( $metric === 'cpu' || $metric === 'user' ) {
472  $ru = getrusage( 0 /* RUSAGE_SELF */ );
473  $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
474  if ( $metric === 'cpu' ) {
475  # This is the time of system calls, added to the user time
476  # it gives the total CPU time
477  $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
478  }
479  return $time;
480  } else {
481  return microtime( true );
482  }
483  }
484 }
SectionProfiler\$collated
array[] $collated
Map of (function name => aggregate data array)
Definition: SectionProfiler.php:44
SectionProfiler\calculateOverhead
calculateOverhead( $profileCount)
Dummy calls to calculate profiling overhead.
Definition: SectionProfiler.php:434
SectionProfiler\scopedProfileIn
scopedProfileIn( $section)
Definition: SectionProfiler.php:68
SectionProfiler\getFunctionStats
getFunctionStats()
Get the aggregated inclusive profiling data for each method.
Definition: SectionProfiler.php:102
SectionProfiler\calltreeCount
calltreeCount( $stack, $start)
Counts the number of profiled function calls sitting under the given point in the call graph.
Definition: SectionProfiler.php:451
SectionProfileCallback
Subclass ScopedCallback to avoid call_user_func_array(), which is slow.
Definition: SectionProfileCallback.php:28
MediaWiki\Logger\LoggerFactory
PSR-3 logger instance factory.
Definition: LoggerFactory.php:45
SectionProfiler\$end
array null $end
Map of (mem,real,cpu)
Definition: SectionProfiler.php:37
SectionProfiler\$workStack
array $workStack
Queue of open profile calls with start data.
Definition: SectionProfiler.php:41
SectionProfiler\$collateDone
bool $collateDone
Definition: SectionProfiler.php:46
SectionProfiler\$collateOnly
bool $collateOnly
Whether to collect the full stack trace or just aggregates.
Definition: SectionProfiler.php:49
SectionProfiler\$start
array null $start
Map of (mem,real,cpu)
Definition: SectionProfiler.php:35
SectionProfiler\getCallTreeLine
getCallTreeLine( $entry)
Callback to get a formatted line for the call tree.
Definition: SectionProfiler.php:344
SectionProfiler\__construct
__construct(array $params=[])
Definition: SectionProfiler.php:58
SectionProfiler
Arbitrary section name based PHP profiling.
Definition: SectionProfiler.php:33
SectionProfiler\$errorEntry
array $errorEntry
Cache of a standard broken collation entry.
Definition: SectionProfiler.php:51
SectionProfiler\remapCallTree
remapCallTree(array $stack)
Recursive function the format the current profiling array into a tree.
Definition: SectionProfiler.php:304
SectionProfiler\reset
reset()
Clear all of the profiling data for another run.
Definition: SectionProfiler.php:150
SectionProfiler\profileOutInternal
profileOutInternal( $functionname)
This method should not be called outside SectionProfiler.
Definition: SectionProfiler.php:237
SectionProfiler\getErrorEntry
getErrorEntry()
Definition: SectionProfiler.php:176
SectionProfiler\scopedProfileOut
scopedProfileOut(ScopedCallback &$section)
Definition: SectionProfiler.php:77
SectionProfiler\$stack
array[] $stack
List of resolved profile calls with start/end data.
Definition: SectionProfiler.php:39
SectionProfiler\$logger
LoggerInterface $logger
Definition: SectionProfiler.php:53
SectionProfiler\updateEntry
updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange)
Update the collation entry for a given method name.
Definition: SectionProfiler.php:190
SectionProfiler\getTime
getTime( $metric='wall')
Get the initial time of the request, based on getrusage()
Definition: SectionProfiler.php:470
SectionProfiler\getCallTreeReport
getCallTreeReport()
Returns a tree of function calls with their real times.
Definition: SectionProfiler.php:289
SectionProfiler\collateData
collateData()
Populate collated data.
Definition: SectionProfiler.php:358
SectionProfiler\profileInInternal
profileInInternal( $functionname)
This method should not be called outside SectionProfiler.
Definition: SectionProfiler.php:209
SectionProfiler\getZeroEntry
getZeroEntry()
Definition: SectionProfiler.php:162