MediaWiki  1.28.0
SectionProfiler.php
Go to the documentation of this file.
1 <?php
25 
33  protected $start;
35  protected $end;
37  protected $stack = [];
39  protected $workStack = [];
40 
42  protected $collated = [];
44  protected $collateDone = false;
45 
47  protected $collateOnly = true;
49  protected $errorEntry;
50 
54  public function __construct( array $params = [] ) {
55  $this->errorEntry = $this->getErrorEntry();
56  $this->collateOnly = empty( $params['trace'] );
57  }
58 
63  public function scopedProfileIn( $section ) {
64  $this->profileInInternal( $section );
65 
66  return new SectionProfileCallback( $this, $section );
67  }
68 
72  public function scopedProfileOut( ScopedCallback &$section ) {
73  $section = null;
74  }
75 
97  public function getFunctionStats() {
98  $this->collateData();
99 
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 
104  $profile = [];
105  foreach ( $this->collated as $fname => $data ) {
106  $profile[] = [
107  'name' => $fname,
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']
117  ];
118  }
119 
120  $profile[] = [
121  'name' => '-total',
122  'calls' => 1,
123  'real' => 1000 * $totalReal,
124  '%real' => 100,
125  'cpu' => 1000 * $totalCpu,
126  '%cpu' => 100,
127  'memory' => $totalMem,
128  '%memory' => 100,
129  'min_real' => 1000 * $totalReal,
130  'max_real' => 1000 * $totalReal
131  ];
132 
133  return $profile;
134  }
135 
139  public function reset() {
140  $this->start = null;
141  $this->end = null;
142  $this->stack = [];
143  $this->workStack = [];
144  $this->collated = [];
145  $this->collateDone = false;
146  }
147 
151  protected function getZeroEntry() {
152  return [
153  'cpu' => 0.0,
154  'real' => 0.0,
155  'memory' => 0,
156  'count' => 0,
157  'min_real' => 0.0,
158  'max_real' => 0.0
159  ];
160  }
161 
165  protected function getErrorEntry() {
166  $entry = $this->getZeroEntry();
167  $entry['count'] = 1;
168  return $entry;
169  }
170 
179  protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) {
180  $entry =& $this->collated[$name];
181  if ( !is_array( $entry ) ) {
182  $entry = $this->getZeroEntry();
183  $this->collated[$name] =& $entry;
184  }
185  $entry['cpu'] += $elapsedCpu;
186  $entry['real'] += $elapsedReal;
187  $entry['memory'] += $memChange > 0 ? $memChange : 0;
188  $entry['count']++;
189  $entry['min_real'] = min( $entry['min_real'], $elapsedReal );
190  $entry['max_real'] = max( $entry['max_real'], $elapsedReal );
191  }
192 
198  public function profileInInternal( $functionname ) {
199  // Once the data is collated for reports, any future calls
200  // should clear the collation cache so the next report will
201  // reflect them. This matters when trace mode is used.
202  $this->collateDone = false;
203 
204  $cpu = $this->getTime( 'cpu' );
205  $real = $this->getTime( 'wall' );
206  $memory = memory_get_usage();
207 
208  if ( $this->start === null ) {
209  $this->start = [ 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ];
210  }
211 
212  $this->workStack[] = [
213  $functionname,
214  count( $this->workStack ),
215  $real,
216  $cpu,
217  $memory
218  ];
219  }
220 
226  public function profileOutInternal( $functionname ) {
227  $item = array_pop( $this->workStack );
228  if ( $item === null ) {
229  $this->debugGroup( 'profileerror', "Profiling error: $functionname" );
230  return;
231  }
232  list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item;
233 
234  if ( $functionname === 'close' ) {
235  $message = "Profile section ended by close(): {$ofname}";
236  $this->debugGroup( 'profileerror', $message );
237  if ( $this->collateOnly ) {
238  $this->collated[$message] = $this->errorEntry;
239  } else {
240  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
241  }
242  $functionname = $ofname;
243  } elseif ( $ofname !== $functionname ) {
244  $message = "Profiling error: in({$ofname}), out($functionname)";
245  $this->debugGroup( 'profileerror', $message );
246  if ( $this->collateOnly ) {
247  $this->collated[$message] = $this->errorEntry;
248  } else {
249  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
250  }
251  }
252 
253  $realTime = $this->getTime( 'wall' );
254  $cpuTime = $this->getTime( 'cpu' );
255  $memUsage = memory_get_usage();
256 
257  if ( $this->collateOnly ) {
258  $elapsedcpu = $cpuTime - $octime;
259  $elapsedreal = $realTime - $ortime;
260  $memchange = $memUsage - $omem;
261  $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
262  } else {
263  $this->stack[] = array_merge( $item, [ $realTime, $cpuTime, $memUsage ] );
264  }
265 
266  $this->end = [
267  'cpu' => $cpuTime,
268  'real' => $realTime,
269  'memory' => $memUsage
270  ];
271  }
272 
278  public function getCallTreeReport() {
279  if ( $this->collateOnly ) {
280  throw new Exception( "Tree is only available for trace profiling." );
281  }
282  return implode( '', array_map(
283  [ $this, 'getCallTreeLine' ], $this->remapCallTree( $this->stack )
284  ) );
285  }
286 
293  protected function remapCallTree( array $stack ) {
294  if ( count( $stack ) < 2 ) {
295  return $stack;
296  }
297  $outputs = [];
298  for ( $max = count( $stack ) - 1; $max > 0; ) {
299  /* Find all items under this entry */
300  $level = $stack[$max][1];
301  $working = [];
302  for ( $i = $max -1; $i >= 0; $i-- ) {
303  if ( $stack[$i][1] > $level ) {
304  $working[] = $stack[$i];
305  } else {
306  break;
307  }
308  }
309  $working = $this->remapCallTree( array_reverse( $working ) );
310  $output = [];
311  foreach ( $working as $item ) {
312  array_push( $output, $item );
313  }
314  array_unshift( $output, $stack[$max] );
315  $max = $i;
316 
317  array_unshift( $outputs, $output );
318  }
319  $final = [];
320  foreach ( $outputs as $output ) {
321  foreach ( $output as $item ) {
322  $final[] = $item;
323  }
324  }
325  return $final;
326  }
327 
333  protected function getCallTreeLine( $entry ) {
334  // $entry has (name, level, stime, scpu, smem, etime, ecpu, emem)
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 );
342  }
343 
347  protected function collateData() {
348  if ( $this->collateDone ) {
349  return;
350  }
351  $this->collateDone = true;
352  // Close opened profiling sections
353  while ( count( $this->workStack ) ) {
354  $this->profileOutInternal( 'close' );
355  }
356 
357  if ( $this->collateOnly ) {
358  return; // already collated as methods exited
359  }
360 
361  $this->collated = [];
362 
363  # Estimate profiling overhead
364  $oldEnd = $this->end;
365  $profileCount = count( $this->stack );
366  $this->calculateOverhead( $profileCount );
367 
368  # First, subtract the overhead!
369  $overheadTotal = $overheadMemory = $overheadInternal = [];
370  foreach ( $this->stack as $entry ) {
371  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
372  $fname = $entry[0];
373  $elapsed = $entry[5] - $entry[2];
374  $memchange = $entry[7] - $entry[4];
375 
376  if ( $fname === '-overhead-total' ) {
377  $overheadTotal[] = $elapsed;
378  $overheadMemory[] = max( 0, $memchange );
379  } elseif ( $fname === '-overhead-internal' ) {
380  $overheadInternal[] = $elapsed;
381  }
382  }
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;
389 
390  # Collate
391  foreach ( $this->stack as $index => $entry ) {
392  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
393  $fname = $entry[0];
394  $elapsedCpu = $entry[6] - $entry[3];
395  $elapsedReal = $entry[5] - $entry[2];
396  $memchange = $entry[7] - $entry[4];
397  $subcalls = $this->calltreeCount( $this->stack, $index );
398 
399  if ( substr( $fname, 0, 9 ) !== '-overhead' ) {
400  # Adjust for profiling overhead (except special values with elapsed=0)
401  if ( $elapsed ) {
402  $elapsed -= $overheadInternal;
403  $elapsed -= ( $subcalls * $overheadTotal );
404  $memchange -= ( $subcalls * $overheadMemory );
405  }
406  }
407 
408  $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange );
409  }
410 
411  $this->collated['-overhead-total']['count'] = $profileCount;
412  arsort( $this->collated, SORT_NUMERIC );
413 
414  // Unclobber the end info map (the overhead checking alters it)
415  $this->end = $oldEnd;
416  }
417 
423  protected function calculateOverhead( $profileCount ) {
424  $this->profileInInternal( '-overhead-total' );
425  for ( $i = 0; $i < $profileCount; $i++ ) {
426  $this->profileInInternal( '-overhead-internal' );
427  $this->profileOutInternal( '-overhead-internal' );
428  }
429  $this->profileOutInternal( '-overhead-total' );
430  }
431 
440  protected function calltreeCount( $stack, $start ) {
441  $level = $stack[$start][1];
442  $count = 0;
443  for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
444  $count ++;
445  }
446  return $count;
447  }
448 
459  protected function getTime( $metric = 'wall' ) {
460  if ( $metric === 'cpu' || $metric === 'user' ) {
461  $ru = wfGetRusage();
462  if ( !$ru ) {
463  return 0;
464  }
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;
470  }
471  return $time;
472  } else {
473  return microtime( true );
474  }
475  }
476 
482  protected function debug( $s ) {
483  if ( function_exists( 'wfDebug' ) ) {
484  wfDebug( $s );
485  }
486  }
487 
494  protected function debugGroup( $group, $s ) {
495  if ( function_exists( 'wfDebugLog' ) ) {
496  wfDebugLog( $group, $s );
497  }
498  }
499 }
500 
506 class SectionProfileCallback extends ScopedCallback {
508  protected $profiler;
510  protected $section;
511 
517  parent::__construct( null );
518  $this->profiler = $profiler;
519  $this->section = $section;
520  }
521 
522  function __destruct() {
523  $this->profiler->profileOutInternal( $this->section );
524  }
525 }
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.
Apache License January AND DISTRIBUTION Definitions License shall mean the terms and conditions for use
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.
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.
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:2889
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:1046
__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:36
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.
see documentation in includes Linker php for Linker::makeImageLink & $time
Definition: hooks.txt:1749
calculateOverhead($profileCount)
Dummy calls to calculate profiling overhead.
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:300