MediaWiki  master
SectionProfiler.php
Go to the documentation of this file.
1 <?php
24 
32  protected $start;
34  protected $end;
36  protected $stack = [];
38  protected $workStack = [];
39 
41  protected $collated = [];
43  protected $collateDone = false;
44 
46  protected $collateOnly = true;
48  protected $errorEntry;
49 
53  public function __construct( array $params = [] ) {
54  $this->errorEntry = $this->getErrorEntry();
55  $this->collateOnly = empty( $params['trace'] );
56  }
57 
62  public function scopedProfileIn( $section ) {
63  $this->profileInInternal( $section );
64 
65  return new SectionProfileCallback( $this, $section );
66  }
67 
71  public function scopedProfileOut( ScopedCallback &$section ) {
72  $section = null;
73  }
74 
96  public function getFunctionStats() {
97  $this->collateData();
98 
99  if ( is_array( $this->start ) ) {
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 );
103  } else {
104  $totalCpu = 0;
105  $totalReal = 0;
106  $totalMem = 0;
107  }
108 
109  $profile = [];
110  foreach ( $this->collated as $fname => $data ) {
111  $profile[] = [
112  'name' => $fname,
113  'calls' => $data['count'],
114  'real' => $data['real'] * 1000,
115  '%real' => $totalReal ? 100 * $data['real'] / $totalReal : 0,
116  'cpu' => $data['cpu'] * 1000,
117  '%cpu' => $totalCpu ? 100 * $data['cpu'] / $totalCpu : 0,
118  'memory' => $data['memory'],
119  '%memory' => $totalMem ? 100 * $data['memory'] / $totalMem : 0,
120  'min_real' => 1000 * $data['min_real'],
121  'max_real' => 1000 * $data['max_real']
122  ];
123  }
124 
125  $profile[] = [
126  'name' => '-total',
127  'calls' => 1,
128  'real' => 1000 * $totalReal,
129  '%real' => 100,
130  'cpu' => 1000 * $totalCpu,
131  '%cpu' => 100,
132  'memory' => $totalMem,
133  '%memory' => 100,
134  'min_real' => 1000 * $totalReal,
135  'max_real' => 1000 * $totalReal
136  ];
137 
138  return $profile;
139  }
140 
144  public function reset() {
145  $this->start = null;
146  $this->end = null;
147  $this->stack = [];
148  $this->workStack = [];
149  $this->collated = [];
150  $this->collateDone = false;
151  }
152 
156  protected function getZeroEntry() {
157  return [
158  'cpu' => 0.0,
159  'real' => 0.0,
160  'memory' => 0,
161  'count' => 0,
162  'min_real' => 0.0,
163  'max_real' => 0.0
164  ];
165  }
166 
170  protected function getErrorEntry() {
171  $entry = $this->getZeroEntry();
172  $entry['count'] = 1;
173  return $entry;
174  }
175 
184  protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) {
185  $entry =& $this->collated[$name];
186  if ( !is_array( $entry ) ) {
187  $entry = $this->getZeroEntry();
188  $this->collated[$name] =& $entry;
189  }
190  $entry['cpu'] += $elapsedCpu;
191  $entry['real'] += $elapsedReal;
192  $entry['memory'] += $memChange > 0 ? $memChange : 0;
193  $entry['count']++;
194  $entry['min_real'] = min( $entry['min_real'], $elapsedReal );
195  $entry['max_real'] = max( $entry['max_real'], $elapsedReal );
196  }
197 
203  public function profileInInternal( $functionname ) {
204  // Once the data is collated for reports, any future calls
205  // should clear the collation cache so the next report will
206  // reflect them. This matters when trace mode is used.
207  $this->collateDone = false;
208 
209  $cpu = $this->getTime( 'cpu' );
210  $real = $this->getTime( 'wall' );
211  $memory = memory_get_usage();
212 
213  if ( $this->start === null ) {
214  $this->start = [ 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ];
215  }
216 
217  $this->workStack[] = [
218  $functionname,
219  count( $this->workStack ),
220  $real,
221  $cpu,
222  $memory
223  ];
224  }
225 
231  public function profileOutInternal( $functionname ) {
232  $item = array_pop( $this->workStack );
233  if ( $item === null ) {
234  $this->debugGroup( 'profileerror', "Profiling error: $functionname" );
235  return;
236  }
237  list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item;
238 
239  if ( $functionname === 'close' ) {
240  $message = "Profile section ended by close(): {$ofname}";
241  $this->debugGroup( 'profileerror', $message );
242  if ( $this->collateOnly ) {
243  $this->collated[$message] = $this->errorEntry;
244  } else {
245  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
246  }
247  $functionname = $ofname;
248  } elseif ( $ofname !== $functionname ) {
249  $message = "Profiling error: in({$ofname}), out($functionname)";
250  $this->debugGroup( 'profileerror', $message );
251  if ( $this->collateOnly ) {
252  $this->collated[$message] = $this->errorEntry;
253  } else {
254  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
255  }
256  }
257 
258  $realTime = $this->getTime( 'wall' );
259  $cpuTime = $this->getTime( 'cpu' );
260  $memUsage = memory_get_usage();
261 
262  if ( $this->collateOnly ) {
263  $elapsedcpu = $cpuTime - $octime;
264  $elapsedreal = $realTime - $ortime;
265  $memchange = $memUsage - $omem;
266  $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
267  } else {
268  $this->stack[] = array_merge( $item, [ $realTime, $cpuTime, $memUsage ] );
269  }
270 
271  $this->end = [
272  'cpu' => $cpuTime,
273  'real' => $realTime,
274  'memory' => $memUsage
275  ];
276  }
277 
283  public function getCallTreeReport() {
284  if ( $this->collateOnly ) {
285  throw new Exception( "Tree is only available for trace profiling." );
286  }
287  return implode( '', array_map(
288  [ $this, 'getCallTreeLine' ], $this->remapCallTree( $this->stack )
289  ) );
290  }
291 
298  protected function remapCallTree( array $stack ) {
299  if ( count( $stack ) < 2 ) {
300  return $stack;
301  }
302  $outputs = [];
303  for ( $max = count( $stack ) - 1; $max > 0; ) {
304  /* Find all items under this entry */
305  $level = $stack[$max][1];
306  $working = [];
307  for ( $i = $max - 1; $i >= 0; $i-- ) {
308  if ( $stack[$i][1] > $level ) {
309  $working[] = $stack[$i];
310  } else {
311  break;
312  }
313  }
314  $working = $this->remapCallTree( array_reverse( $working ) );
315  $output = [];
316  foreach ( $working as $item ) {
317  array_push( $output, $item );
318  }
319  array_unshift( $output, $stack[$max] );
320  $max = $i;
321 
322  array_unshift( $outputs, $output );
323  }
324  $final = [];
325  foreach ( $outputs as $output ) {
326  foreach ( $output as $item ) {
327  $final[] = $item;
328  }
329  }
330  return $final;
331  }
332 
338  protected function getCallTreeLine( $entry ) {
339  // $entry has (name, level, stime, scpu, smem, etime, ecpu, emem)
340  list( $fname, $level, $startreal, , , $endreal ) = $entry;
341  $delta = $endreal - $startreal;
342  $space = str_repeat( ' ', $level );
343  # The ugly double sprintf is to work around a PHP bug,
344  # which has been fixed in recent releases.
345  return sprintf( "%10s %s %s\n",
346  trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
347  }
348 
352  protected function collateData() {
353  if ( $this->collateDone ) {
354  return;
355  }
356  $this->collateDone = true;
357  // Close opened profiling sections
358  while ( count( $this->workStack ) ) {
359  $this->profileOutInternal( 'close' );
360  }
361 
362  if ( $this->collateOnly ) {
363  return; // already collated as methods exited
364  }
365 
366  $this->collated = [];
367 
368  # Estimate profiling overhead
369  $oldEnd = $this->end;
370  $profileCount = count( $this->stack );
371  $this->calculateOverhead( $profileCount );
372 
373  # First, subtract the overhead!
374  $overheadTotal = $overheadMemory = $overheadInternal = [];
375  foreach ( $this->stack as $entry ) {
376  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
377  $fname = $entry[0];
378  $elapsed = $entry[5] - $entry[2];
379  $memchange = $entry[7] - $entry[4];
380 
381  if ( $fname === '-overhead-total' ) {
382  $overheadTotal[] = $elapsed;
383  $overheadMemory[] = max( 0, $memchange );
384  } elseif ( $fname === '-overhead-internal' ) {
385  $overheadInternal[] = $elapsed;
386  }
387  }
388  $overheadTotal = $overheadTotal ?
389  array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
390  $overheadMemory = $overheadMemory ?
391  array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
392  $overheadInternal = $overheadInternal ?
393  array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
394 
395  # Collate
396  foreach ( $this->stack as $index => $entry ) {
397  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
398  $fname = $entry[0];
399  $elapsedCpu = $entry[6] - $entry[3];
400  $elapsedReal = $entry[5] - $entry[2];
401  $memchange = $entry[7] - $entry[4];
402  $subcalls = $this->calltreeCount( $this->stack, $index );
403 
404  if ( substr( $fname, 0, 9 ) !== '-overhead' ) {
405  # Adjust for profiling overhead (except special values with elapsed=0)
406  if ( $elapsed ) {
407  $elapsed -= $overheadInternal;
408  $elapsed -= ( $subcalls * $overheadTotal );
409  $memchange -= ( $subcalls * $overheadMemory );
410  }
411  }
412 
413  $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange );
414  }
415 
416  $this->collated['-overhead-total']['count'] = $profileCount;
417  arsort( $this->collated, SORT_NUMERIC );
418 
419  // Unclobber the end info map (the overhead checking alters it)
420  $this->end = $oldEnd;
421  }
422 
428  protected function calculateOverhead( $profileCount ) {
429  $this->profileInInternal( '-overhead-total' );
430  for ( $i = 0; $i < $profileCount; $i++ ) {
431  $this->profileInInternal( '-overhead-internal' );
432  $this->profileOutInternal( '-overhead-internal' );
433  }
434  $this->profileOutInternal( '-overhead-total' );
435  }
436 
445  protected function calltreeCount( $stack, $start ) {
446  $level = $stack[$start][1];
447  $count = 0;
448  for ( $i = $start - 1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
449  $count++;
450  }
451  return $count;
452  }
453 
464  protected function getTime( $metric = 'wall' ) {
465  if ( $metric === 'cpu' || $metric === 'user' ) {
466  $ru = wfGetRusage();
467  if ( !$ru ) {
468  return 0;
469  }
470  $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
471  if ( $metric === 'cpu' ) {
472  # This is the time of system calls, added to the user time
473  # it gives the total CPU time
474  $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
475  }
476  return $time;
477  } else {
478  return microtime( true );
479  }
480  }
481 
487  protected function debug( $s ) {
488  if ( function_exists( 'wfDebug' ) ) {
489  wfDebug( $s );
490  }
491  }
492 
499  protected function debugGroup( $group, $s ) {
500  if ( function_exists( 'wfDebugLog' ) ) {
501  wfDebugLog( $group, $s );
502  }
503  }
504 }
profileInInternal( $functionname)
This method should not be called outside SectionProfiler.
reset()
Clear all of the profiling data for another run.
array [] $collated
Map of (function name => aggregate data array)
getTime( $metric='wall')
Get the initial time of the request, based on getrusage()
array $start
Map of (mem,real,cpu)
wfGetRusage()
Get system resource usage of current request context.
collateData()
Populate collated data.
scopedProfileOut(ScopedCallback &$section)
getCallTreeReport()
Returns a tree of function calls with their real times.
calltreeCount( $stack, $start)
Counts the number of profiled function calls sitting under the given point in the call graph...
Custom PHP profiler for parser/DB type section names that xhprof/xdebug can&#39;t handle.
array $workStack
Queue of open profile calls with start data.
calculateOverhead( $profileCount)
Dummy calls to calculate profiling overhead.
getCallTreeLine( $entry)
Callback to get a formatted line for the call tree.
debug( $s)
Add an entry in the debug log file.
__construct(array $params=[])
getFunctionStats()
Get the aggregated inclusive profiling data for each method.
wfDebug( $text, $dest='all', array $context=[])
Sends a line to the debug log if enabled or, optionally, to a comment in output.
profileOutInternal( $functionname)
This method should not be called outside SectionProfiler.
array $end
Map of (mem,real,cpu)
array [] $stack
List of resolved profile calls with start/end data.
Subclass ScopedCallback to avoid call_user_func_array(), which is slow.
wfDebugLog( $logGroup, $text, $dest='all', array $context=[])
Send a line to a supplementary debug log file, if configured, or main debug log if not...
updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange)
Update the collation entry for a given method name.
bool $collateOnly
Whether to collect the full stack trace or just aggregates.
remapCallTree(array $stack)
Recursive function the format the current profiling array into a tree.
array $errorEntry
Cache of a standard broken collation entry.
scopedProfileIn( $section)
debugGroup( $group, $s)
Add an entry in the debug log group.