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