MediaWiki  1.27.1
SectionProfiler.php
Go to the documentation of this file.
1 <?php
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;
51 
55  public function __construct( array $params = [] ) {
56  $this->errorEntry = $this->getErrorEntry();
57  $this->collateOnly = empty( $params['trace'] );
58  $this->profileOutCallback = function ( $profiler, $section ) {
59  $profiler->profileOutInternal( $section );
60  };
61  }
62 
67  public function scopedProfileIn( $section ) {
68  $this->profileInInternal( $section );
69 
70  return new SectionProfileCallback( $this, $section );
71  }
72 
77  $section = null;
78  }
79 
101  public function getFunctionStats() {
102  $this->collateData();
103 
104  $totalCpu = max( $this->end['cpu'] - $this->start['cpu'], 0 );
105  $totalReal = max( $this->end['real'] - $this->start['real'], 0 );
106  $totalMem = max( $this->end['memory'] - $this->start['memory'], 0 );
107 
108  $profile = [];
109  foreach ( $this->collated as $fname => $data ) {
110  $profile[] = [
111  'name' => $fname,
112  'calls' => $data['count'],
113  'real' => $data['real'] * 1000,
114  '%real' => $totalReal ? 100 * $data['real'] / $totalReal : 0,
115  'cpu' => $data['cpu'] * 1000,
116  '%cpu' => $totalCpu ? 100 * $data['cpu'] / $totalCpu : 0,
117  'memory' => $data['memory'],
118  '%memory' => $totalMem ? 100 * $data['memory'] / $totalMem : 0,
119  'min_real' => 1000 * $data['min_real'],
120  'max_real' => 1000 * $data['max_real']
121  ];
122  }
123 
124  $profile[] = [
125  'name' => '-total',
126  'calls' => 1,
127  'real' => 1000 * $totalReal,
128  '%real' => 100,
129  'cpu' => 1000 * $totalCpu,
130  '%cpu' => 100,
131  'memory' => $totalMem,
132  '%memory' => 100,
133  'min_real' => 1000 * $totalReal,
134  'max_real' => 1000 * $totalReal
135  ];
136 
137  return $profile;
138  }
139 
143  public function reset() {
144  $this->start = null;
145  $this->end = null;
146  $this->stack = [];
147  $this->workStack = [];
148  $this->collated = [];
149  $this->collateDone = false;
150  }
151 
155  protected function getZeroEntry() {
156  return [
157  'cpu' => 0.0,
158  'real' => 0.0,
159  'memory' => 0,
160  'count' => 0,
161  'min_real' => 0.0,
162  'max_real' => 0.0
163  ];
164  }
165 
169  protected function getErrorEntry() {
170  $entry = $this->getZeroEntry();
171  $entry['count'] = 1;
172  return $entry;
173  }
174 
183  protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) {
184  $entry =& $this->collated[$name];
185  if ( !is_array( $entry ) ) {
186  $entry = $this->getZeroEntry();
187  $this->collated[$name] =& $entry;
188  }
189  $entry['cpu'] += $elapsedCpu;
190  $entry['real'] += $elapsedReal;
191  $entry['memory'] += $memChange > 0 ? $memChange : 0;
192  $entry['count']++;
193  $entry['min_real'] = min( $entry['min_real'], $elapsedReal );
194  $entry['max_real'] = max( $entry['max_real'], $elapsedReal );
195  }
196 
202  public function profileInInternal( $functionname ) {
203  // Once the data is collated for reports, any future calls
204  // should clear the collation cache so the next report will
205  // reflect them. This matters when trace mode is used.
206  $this->collateDone = false;
207 
208  $cpu = $this->getTime( 'cpu' );
209  $real = $this->getTime( 'wall' );
210  $memory = memory_get_usage();
211 
212  if ( $this->start === null ) {
213  $this->start = [ 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ];
214  }
215 
216  $this->workStack[] = [
217  $functionname,
218  count( $this->workStack ),
219  $real,
220  $cpu,
221  $memory
222  ];
223  }
224 
230  public function profileOutInternal( $functionname ) {
231  $item = array_pop( $this->workStack );
232  if ( $item === null ) {
233  $this->debugGroup( 'profileerror', "Profiling error: $functionname" );
234  return;
235  }
236  list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item;
237 
238  if ( $functionname === 'close' ) {
239  $message = "Profile section ended by close(): {$ofname}";
240  $this->debugGroup( 'profileerror', $message );
241  if ( $this->collateOnly ) {
242  $this->collated[$message] = $this->errorEntry;
243  } else {
244  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
245  }
246  $functionname = $ofname;
247  } elseif ( $ofname !== $functionname ) {
248  $message = "Profiling error: in({$ofname}), out($functionname)";
249  $this->debugGroup( 'profileerror', $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  }
256 
257  $realTime = $this->getTime( 'wall' );
258  $cpuTime = $this->getTime( 'cpu' );
259  $memUsage = memory_get_usage();
260 
261  if ( $this->collateOnly ) {
262  $elapsedcpu = $cpuTime - $octime;
263  $elapsedreal = $realTime - $ortime;
264  $memchange = $memUsage - $omem;
265  $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
266  } else {
267  $this->stack[] = array_merge( $item, [ $realTime, $cpuTime, $memUsage ] );
268  }
269 
270  $this->end = [
271  'cpu' => $cpuTime,
272  'real' => $realTime,
273  'memory' => $memUsage
274  ];
275  }
276 
282  public function getCallTreeReport() {
283  if ( $this->collateOnly ) {
284  throw new Exception( "Tree is only available for trace profiling." );
285  }
286  return implode( '', array_map(
287  [ $this, 'getCallTreeLine' ], $this->remapCallTree( $this->stack )
288  ) );
289  }
290 
297  protected function remapCallTree( array $stack ) {
298  if ( count( $stack ) < 2 ) {
299  return $stack;
300  }
301  $outputs = [];
302  for ( $max = count( $stack ) - 1; $max > 0; ) {
303  /* Find all items under this entry */
304  $level = $stack[$max][1];
305  $working = [];
306  for ( $i = $max -1; $i >= 0; $i-- ) {
307  if ( $stack[$i][1] > $level ) {
308  $working[] = $stack[$i];
309  } else {
310  break;
311  }
312  }
313  $working = $this->remapCallTree( array_reverse( $working ) );
314  $output = [];
315  foreach ( $working as $item ) {
316  array_push( $output, $item );
317  }
318  array_unshift( $output, $stack[$max] );
319  $max = $i;
320 
321  array_unshift( $outputs, $output );
322  }
323  $final = [];
324  foreach ( $outputs as $output ) {
325  foreach ( $output as $item ) {
326  $final[] = $item;
327  }
328  }
329  return $final;
330  }
331 
337  protected function getCallTreeLine( $entry ) {
338  // $entry has (name, level, stime, scpu, smem, etime, ecpu, emem)
339  list( $fname, $level, $startreal, , , $endreal ) = $entry;
340  $delta = $endreal - $startreal;
341  $space = str_repeat( ' ', $level );
342  # The ugly double sprintf is to work around a PHP bug,
343  # which has been fixed in recent releases.
344  return sprintf( "%10s %s %s\n",
345  trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
346  }
347 
351  protected function collateData() {
352  if ( $this->collateDone ) {
353  return;
354  }
355  $this->collateDone = true;
356  // Close opened profiling sections
357  while ( count( $this->workStack ) ) {
358  $this->profileOutInternal( 'close' );
359  }
360 
361  if ( $this->collateOnly ) {
362  return; // already collated as methods exited
363  }
364 
365  $this->collated = [];
366 
367  # Estimate profiling overhead
368  $oldEnd = $this->end;
369  $profileCount = count( $this->stack );
370  $this->calculateOverhead( $profileCount );
371 
372  # First, subtract the overhead!
373  $overheadTotal = $overheadMemory = $overheadInternal = [];
374  foreach ( $this->stack as $entry ) {
375  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
376  $fname = $entry[0];
377  $elapsed = $entry[5] - $entry[2];
378  $memchange = $entry[7] - $entry[4];
379 
380  if ( $fname === '-overhead-total' ) {
381  $overheadTotal[] = $elapsed;
382  $overheadMemory[] = max( 0, $memchange );
383  } elseif ( $fname === '-overhead-internal' ) {
384  $overheadInternal[] = $elapsed;
385  }
386  }
387  $overheadTotal = $overheadTotal ?
388  array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
389  $overheadMemory = $overheadMemory ?
390  array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
391  $overheadInternal = $overheadInternal ?
392  array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
393 
394  # Collate
395  foreach ( $this->stack as $index => $entry ) {
396  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
397  $fname = $entry[0];
398  $elapsedCpu = $entry[6] - $entry[3];
399  $elapsedReal = $entry[5] - $entry[2];
400  $memchange = $entry[7] - $entry[4];
401  $subcalls = $this->calltreeCount( $this->stack, $index );
402 
403  if ( substr( $fname, 0, 9 ) !== '-overhead' ) {
404  # Adjust for profiling overhead (except special values with elapsed=0)
405  if ( $elapsed ) {
406  $elapsed -= $overheadInternal;
407  $elapsed -= ( $subcalls * $overheadTotal );
408  $memchange -= ( $subcalls * $overheadMemory );
409  }
410  }
411 
412  $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange );
413  }
414 
415  $this->collated['-overhead-total']['count'] = $profileCount;
416  arsort( $this->collated, SORT_NUMERIC );
417 
418  // Unclobber the end info map (the overhead checking alters it)
419  $this->end = $oldEnd;
420  }
421 
427  protected function calculateOverhead( $profileCount ) {
428  $this->profileInInternal( '-overhead-total' );
429  for ( $i = 0; $i < $profileCount; $i++ ) {
430  $this->profileInInternal( '-overhead-internal' );
431  $this->profileOutInternal( '-overhead-internal' );
432  }
433  $this->profileOutInternal( '-overhead-total' );
434  }
435 
444  protected function calltreeCount( $stack, $start ) {
445  $level = $stack[$start][1];
446  $count = 0;
447  for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
448  $count ++;
449  }
450  return $count;
451  }
452 
463  protected function getTime( $metric = 'wall' ) {
464  if ( $metric === 'cpu' || $metric === 'user' ) {
465  $ru = wfGetRusage();
466  if ( !$ru ) {
467  return 0;
468  }
469  $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
470  if ( $metric === 'cpu' ) {
471  # This is the time of system calls, added to the user time
472  # it gives the total CPU time
473  $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
474  }
475  return $time;
476  } else {
477  return microtime( true );
478  }
479  }
480 
486  protected function debug( $s ) {
487  if ( function_exists( 'wfDebug' ) ) {
488  wfDebug( $s );
489  }
490  }
491 
498  protected function debugGroup( $group, $s ) {
499  if ( function_exists( 'wfDebugLog' ) ) {
500  wfDebugLog( $group, $s );
501  }
502  }
503 }
504 
512  protected $profiler;
514  protected $section;
515 
521  parent::__construct( null );
522  $this->profiler = $profiler;
523  $this->section = $section;
524  }
525 
526  function __destruct() {
527  $this->profiler->profileOutInternal( $this->section );
528  }
529 }
array $collated
Map of (function name => aggregate data array)
reset()
Clear all of the profiling data for another run.
deferred txt A few of the database updates required by various functions here can be deferred until after the result page is displayed to the user For updating the view updating the linked to tables after a etc PHP does not yet have any way to tell the server to actually return and disconnect while still running these but it might have such a feature in the future We handle these by creating a deferred update object and putting those objects on a global list
Definition: deferred.txt:11
the array() calling protocol came about after MediaWiki 1.4rc1.
array $start
Map of (mem,real,cpu)
profileOutInternal($functionname)
This method should not be called outside SectionProfiler.
profileInInternal($functionname)
This method should not be called outside SectionProfiler.
wfGetRusage()
Get system resource usage of current request context.
collateData()
Populate collated data.
array $stack
List of resolved profile calls with start/end data.
scopedProfileOut(ScopedCallback &$section)
getCallTreeReport()
Returns a tree of function calls with their real times.
see documentation in includes Linker php for Linker::makeImageLink & $time
Definition: hooks.txt:1612
wfDebug($text, $dest= 'all', array $context=[])
Sends a line to the debug log if enabled or, optionally, to a comment in output.
Custom PHP profiler for parser/DB type section names that xhprof/xdebug can't handle.
Class for asserting that a callback happens when an dummy object leaves scope.
wfDebugLog($logGroup, $text, $dest= 'all', array $context=[])
Send a line to a supplementary debug log file, if configured, or main debug log if not...
calltreeCount($stack, $start)
Counts the number of profiled function calls sitting under the given point in the call graph...
array $workStack
Queue of open profile calls with start data.
__construct(array $params=[])
getFunctionStats()
Get the aggregated inclusive profiling data for each method.
getCallTreeLine($entry)
Callback to get a formatted line for the call tree.
debug($s)
Add an entry in the debug log file.
$params
This document is intended to provide useful advice for parties seeking to redistribute MediaWiki to end users It s targeted particularly at maintainers for Linux since it s been observed that distribution packages of MediaWiki often break We ve consistently had to recommend that users seeking support use official tarballs instead of their distribution s and this often solves whatever problem the user is having It would be nice if this could such as
Definition: distributors.txt:9
array $end
Map of (mem,real,cpu)
usually copyright or history_copyright This message must be in HTML not wikitext if the section is included from a template $section
Definition: hooks.txt:2715
this hook is for auditing only RecentChangesLinked and Watchlist RecentChangesLinked and Watchlist e g Watchlist removed from all revisions and log entries to which it was applied This gives extensions a chance to take it off their books as the deletion has already been partly carried out by this point or something similar the user will be unable to create the tag set and then return false from the hook function Ensure you consume the ChangeTagAfterDelete hook to carry out custom deletion actions as context called by AbstractContent::getParserOutput May be used to override the normal model specific rendering of page content as context as context the output can only depend on parameters provided to this hook not on global state indicating whether full HTML should be generated If generation of HTML may be but other information should still be present in the ParserOutput object & $output
Definition: hooks.txt:1004
__construct(SectionProfiler $profiler, $section)
injection txt This is an overview of how MediaWiki makes use of dependency injection The design described here grew from the discussion of RFC T384 The term dependency this means that anything an object needs to operate should be injected from the the object itself should only know narrow no concrete implementation of the logic it relies on The requirement to inject everything typically results in an architecture that based on two main types of and essentially stateless service objects that use other service objects to operate on the value objects As of the beginning MediaWiki is only starting to use the DI approach Much of the code still relies on global state or direct resulting in a highly cyclical dependency which acts as the top level factory for services in MediaWiki which can be used to gain access to default instances of various services MediaWikiServices however also allows new services to be defined and default services to be redefined Services are defined or redefined by providing a callback the instantiator that will return a new instance of the service When it will create an instance of MediaWikiServices and populate it with the services defined in the files listed by thereby bootstrapping the DI framework Per $wgServiceWiringFiles lists includes ServiceWiring php
Definition: injection.txt:35
if(!defined( 'MEDIAWIKI')) $fname
This file is not a valid entry point, perform no further processing unless MEDIAWIKI is defined...
Definition: Setup.php:35
Subclass ScopedCallback to avoid call_user_func_array(), which is slow.
getTime($metric= 'wall')
Get the initial time of the request, based on getrusage()
scopedProfileIn($section)
updateEntry($name, $elapsedCpu, $elapsedReal, $memChange)
Update the collation entry for a given method name.
SectionProfiler $profiler
$count
debugGroup($group, $s)
Add an entry in the debug log group.
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.
callable $profileOutCallback
Cache of a profile out callback.
calculateOverhead($profileCount)
Dummy calls to calculate profiling overhead.
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:310