MediaWiki  1.30.0
SectionProfiler.php
Go to the documentation of this file.
1 <?php
23 use Wikimedia\ScopedCallback;
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  $totalCpu = max( $this->end['cpu'] - $this->start['cpu'], 0 );
100  $totalReal = max( $this->end['real'] - $this->start['real'], 0 );
101  $totalMem = max( $this->end['memory'] - $this->start['memory'], 0 );
102 
103  $profile = [];
104  foreach ( $this->collated as $fname => $data ) {
105  $profile[] = [
106  'name' => $fname,
107  'calls' => $data['count'],
108  'real' => $data['real'] * 1000,
109  '%real' => $totalReal ? 100 * $data['real'] / $totalReal : 0,
110  'cpu' => $data['cpu'] * 1000,
111  '%cpu' => $totalCpu ? 100 * $data['cpu'] / $totalCpu : 0,
112  'memory' => $data['memory'],
113  '%memory' => $totalMem ? 100 * $data['memory'] / $totalMem : 0,
114  'min_real' => 1000 * $data['min_real'],
115  'max_real' => 1000 * $data['max_real']
116  ];
117  }
118 
119  $profile[] = [
120  'name' => '-total',
121  'calls' => 1,
122  'real' => 1000 * $totalReal,
123  '%real' => 100,
124  'cpu' => 1000 * $totalCpu,
125  '%cpu' => 100,
126  'memory' => $totalMem,
127  '%memory' => 100,
128  'min_real' => 1000 * $totalReal,
129  'max_real' => 1000 * $totalReal
130  ];
131 
132  return $profile;
133  }
134 
138  public function reset() {
139  $this->start = null;
140  $this->end = null;
141  $this->stack = [];
142  $this->workStack = [];
143  $this->collated = [];
144  $this->collateDone = false;
145  }
146 
150  protected function getZeroEntry() {
151  return [
152  'cpu' => 0.0,
153  'real' => 0.0,
154  'memory' => 0,
155  'count' => 0,
156  'min_real' => 0.0,
157  'max_real' => 0.0
158  ];
159  }
160 
164  protected function getErrorEntry() {
165  $entry = $this->getZeroEntry();
166  $entry['count'] = 1;
167  return $entry;
168  }
169 
178  protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) {
179  $entry =& $this->collated[$name];
180  if ( !is_array( $entry ) ) {
181  $entry = $this->getZeroEntry();
182  $this->collated[$name] =& $entry;
183  }
184  $entry['cpu'] += $elapsedCpu;
185  $entry['real'] += $elapsedReal;
186  $entry['memory'] += $memChange > 0 ? $memChange : 0;
187  $entry['count']++;
188  $entry['min_real'] = min( $entry['min_real'], $elapsedReal );
189  $entry['max_real'] = max( $entry['max_real'], $elapsedReal );
190  }
191 
197  public function profileInInternal( $functionname ) {
198  // Once the data is collated for reports, any future calls
199  // should clear the collation cache so the next report will
200  // reflect them. This matters when trace mode is used.
201  $this->collateDone = false;
202 
203  $cpu = $this->getTime( 'cpu' );
204  $real = $this->getTime( 'wall' );
205  $memory = memory_get_usage();
206 
207  if ( $this->start === null ) {
208  $this->start = [ 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ];
209  }
210 
211  $this->workStack[] = [
212  $functionname,
213  count( $this->workStack ),
214  $real,
215  $cpu,
216  $memory
217  ];
218  }
219 
225  public function profileOutInternal( $functionname ) {
226  $item = array_pop( $this->workStack );
227  if ( $item === null ) {
228  $this->debugGroup( 'profileerror', "Profiling error: $functionname" );
229  return;
230  }
231  list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item;
232 
233  if ( $functionname === 'close' ) {
234  $message = "Profile section ended by close(): {$ofname}";
235  $this->debugGroup( 'profileerror', $message );
236  if ( $this->collateOnly ) {
237  $this->collated[$message] = $this->errorEntry;
238  } else {
239  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
240  }
241  $functionname = $ofname;
242  } elseif ( $ofname !== $functionname ) {
243  $message = "Profiling error: in({$ofname}), out($functionname)";
244  $this->debugGroup( 'profileerror', $message );
245  if ( $this->collateOnly ) {
246  $this->collated[$message] = $this->errorEntry;
247  } else {
248  $this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
249  }
250  }
251 
252  $realTime = $this->getTime( 'wall' );
253  $cpuTime = $this->getTime( 'cpu' );
254  $memUsage = memory_get_usage();
255 
256  if ( $this->collateOnly ) {
257  $elapsedcpu = $cpuTime - $octime;
258  $elapsedreal = $realTime - $ortime;
259  $memchange = $memUsage - $omem;
260  $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
261  } else {
262  $this->stack[] = array_merge( $item, [ $realTime, $cpuTime, $memUsage ] );
263  }
264 
265  $this->end = [
266  'cpu' => $cpuTime,
267  'real' => $realTime,
268  'memory' => $memUsage
269  ];
270  }
271 
277  public function getCallTreeReport() {
278  if ( $this->collateOnly ) {
279  throw new Exception( "Tree is only available for trace profiling." );
280  }
281  return implode( '', array_map(
282  [ $this, 'getCallTreeLine' ], $this->remapCallTree( $this->stack )
283  ) );
284  }
285 
292  protected function remapCallTree( array $stack ) {
293  if ( count( $stack ) < 2 ) {
294  return $stack;
295  }
296  $outputs = [];
297  for ( $max = count( $stack ) - 1; $max > 0; ) {
298  /* Find all items under this entry */
299  $level = $stack[$max][1];
300  $working = [];
301  for ( $i = $max - 1; $i >= 0; $i-- ) {
302  if ( $stack[$i][1] > $level ) {
303  $working[] = $stack[$i];
304  } else {
305  break;
306  }
307  }
308  $working = $this->remapCallTree( array_reverse( $working ) );
309  $output = [];
310  foreach ( $working as $item ) {
311  array_push( $output, $item );
312  }
313  array_unshift( $output, $stack[$max] );
314  $max = $i;
315 
316  array_unshift( $outputs, $output );
317  }
318  $final = [];
319  foreach ( $outputs as $output ) {
320  foreach ( $output as $item ) {
321  $final[] = $item;
322  }
323  }
324  return $final;
325  }
326 
332  protected function getCallTreeLine( $entry ) {
333  // $entry has (name, level, stime, scpu, smem, etime, ecpu, emem)
334  list( $fname, $level, $startreal, , , $endreal ) = $entry;
335  $delta = $endreal - $startreal;
336  $space = str_repeat( ' ', $level );
337  # The ugly double sprintf is to work around a PHP bug,
338  # which has been fixed in recent releases.
339  return sprintf( "%10s %s %s\n",
340  trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
341  }
342 
346  protected function collateData() {
347  if ( $this->collateDone ) {
348  return;
349  }
350  $this->collateDone = true;
351  // Close opened profiling sections
352  while ( count( $this->workStack ) ) {
353  $this->profileOutInternal( 'close' );
354  }
355 
356  if ( $this->collateOnly ) {
357  return; // already collated as methods exited
358  }
359 
360  $this->collated = [];
361 
362  # Estimate profiling overhead
363  $oldEnd = $this->end;
364  $profileCount = count( $this->stack );
365  $this->calculateOverhead( $profileCount );
366 
367  # First, subtract the overhead!
368  $overheadTotal = $overheadMemory = $overheadInternal = [];
369  foreach ( $this->stack as $entry ) {
370  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
371  $fname = $entry[0];
372  $elapsed = $entry[5] - $entry[2];
373  $memchange = $entry[7] - $entry[4];
374 
375  if ( $fname === '-overhead-total' ) {
376  $overheadTotal[] = $elapsed;
377  $overheadMemory[] = max( 0, $memchange );
378  } elseif ( $fname === '-overhead-internal' ) {
379  $overheadInternal[] = $elapsed;
380  }
381  }
382  $overheadTotal = $overheadTotal ?
383  array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
384  $overheadMemory = $overheadMemory ?
385  array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
386  $overheadInternal = $overheadInternal ?
387  array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
388 
389  # Collate
390  foreach ( $this->stack as $index => $entry ) {
391  // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
392  $fname = $entry[0];
393  $elapsedCpu = $entry[6] - $entry[3];
394  $elapsedReal = $entry[5] - $entry[2];
395  $memchange = $entry[7] - $entry[4];
396  $subcalls = $this->calltreeCount( $this->stack, $index );
397 
398  if ( substr( $fname, 0, 9 ) !== '-overhead' ) {
399  # Adjust for profiling overhead (except special values with elapsed=0)
400  if ( $elapsed ) {
401  $elapsed -= $overheadInternal;
402  $elapsed -= ( $subcalls * $overheadTotal );
403  $memchange -= ( $subcalls * $overheadMemory );
404  }
405  }
406 
407  $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange );
408  }
409 
410  $this->collated['-overhead-total']['count'] = $profileCount;
411  arsort( $this->collated, SORT_NUMERIC );
412 
413  // Unclobber the end info map (the overhead checking alters it)
414  $this->end = $oldEnd;
415  }
416 
422  protected function calculateOverhead( $profileCount ) {
423  $this->profileInInternal( '-overhead-total' );
424  for ( $i = 0; $i < $profileCount; $i++ ) {
425  $this->profileInInternal( '-overhead-internal' );
426  $this->profileOutInternal( '-overhead-internal' );
427  }
428  $this->profileOutInternal( '-overhead-total' );
429  }
430 
439  protected function calltreeCount( $stack, $start ) {
440  $level = $stack[$start][1];
441  $count = 0;
442  for ( $i = $start - 1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
443  $count ++;
444  }
445  return $count;
446  }
447 
458  protected function getTime( $metric = 'wall' ) {
459  if ( $metric === 'cpu' || $metric === 'user' ) {
460  $ru = wfGetRusage();
461  if ( !$ru ) {
462  return 0;
463  }
464  $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
465  if ( $metric === 'cpu' ) {
466  # This is the time of system calls, added to the user time
467  # it gives the total CPU time
468  $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
469  }
470  return $time;
471  } else {
472  return microtime( true );
473  }
474  }
475 
481  protected function debug( $s ) {
482  if ( function_exists( 'wfDebug' ) ) {
483  wfDebug( $s );
484  }
485  }
486 
493  protected function debugGroup( $group, $s ) {
494  if ( function_exists( 'wfDebugLog' ) ) {
495  wfDebugLog( $group, $s );
496  }
497  }
498 }
499 
505 class SectionProfileCallback extends ScopedCallback {
507  protected $profiler;
509  protected $section;
510 
516  parent::__construct( null );
517  $this->profiler = $profiler;
518  $this->section = $section;
519  }
520 
521  function __destruct() {
522  $this->profiler->profileOutInternal( $this->section );
523  }
524 }
SectionProfiler\$start
array $start
Map of (mem,real,cpu)
Definition: SectionProfiler.php:32
captcha-old.count
count
Definition: captcha-old.py:249
SectionProfiler\calculateOverhead
calculateOverhead( $profileCount)
Dummy calls to calculate profiling overhead.
Definition: SectionProfiler.php:422
SectionProfileCallback\$profiler
SectionProfiler $profiler
Definition: SectionProfiler.php:507
SectionProfiler\scopedProfileIn
scopedProfileIn( $section)
Definition: SectionProfiler.php:62
use
as see the revision history and available at free of to any person obtaining a copy of this software and associated documentation to deal in the Software without including without limitation the rights to use
Definition: MIT-LICENSE.txt:10
SectionProfiler\getFunctionStats
getFunctionStats()
Get the aggregated inclusive profiling data for each method.
Definition: SectionProfiler.php:96
$fname
if(!defined( 'MEDIAWIKI')) $fname
This file is not a valid entry point, perform no further processing unless MEDIAWIKI is defined.
Definition: Setup.php:36
SectionProfileCallback\__construct
__construct(SectionProfiler $profiler, $section)
Definition: SectionProfiler.php:515
SectionProfiler\calltreeCount
calltreeCount( $stack, $start)
Counts the number of profiled function calls sitting under the given point in the call graph.
Definition: SectionProfiler.php:439
$params
$params
Definition: styleTest.css.php:40
$s
$s
Definition: mergeMessageFileList.php:188
$name
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:302
SectionProfileCallback\$section
string $section
Definition: SectionProfiler.php:509
$output
static configuration should be added through ResourceLoaderGetConfigVars instead can be used to get the real title after the basic globals have been set but before ordinary actions take place $output
Definition: hooks.txt:2198
wfDebugLog
wfDebugLog( $logGroup, $text, $dest='all', array $context=[])
Send a line to a supplementary debug log file, if configured, or main debug log if not.
Definition: GlobalFunctions.php:1140
SectionProfileCallback
Subclass ScopedCallback to avoid call_user_func_array(), which is slow.
Definition: SectionProfiler.php:505
php
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
SectionProfiler\debug
debug( $s)
Add an entry in the debug log file.
Definition: SectionProfiler.php:481
SectionProfiler\debugGroup
debugGroup( $group, $s)
Add an entry in the debug log group.
Definition: SectionProfiler.php:493
SectionProfiler\$workStack
array $workStack
Queue of open profile calls with start data.
Definition: SectionProfiler.php:38
SectionProfiler\$collateDone
bool $collateDone
Definition: SectionProfiler.php:43
SectionProfiler\$collateOnly
bool $collateOnly
Whether to collect the full stack trace or just aggregates.
Definition: SectionProfiler.php:46
SectionProfiler\getCallTreeLine
getCallTreeLine( $entry)
Callback to get a formatted line for the call tree.
Definition: SectionProfiler.php:332
SectionProfiler\__construct
__construct(array $params=[])
Definition: SectionProfiler.php:53
$time
see documentation in includes Linker php for Linker::makeImageLink & $time
Definition: hooks.txt:1778
SectionProfiler\$collated
array $collated
Map of (function name => aggregate data array)
Definition: SectionProfiler.php:41
SectionProfiler
Custom PHP profiler for parser/DB type section names that xhprof/xdebug can't handle.
Definition: SectionProfiler.php:30
SectionProfiler\$errorEntry
array $errorEntry
Cache of a standard broken collation entry.
Definition: SectionProfiler.php:48
wfDebug
wfDebug( $text, $dest='all', array $context=[])
Sends a line to the debug log if enabled or, optionally, to a comment in output.
Definition: GlobalFunctions.php:1047
list
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
SectionProfiler\remapCallTree
remapCallTree(array $stack)
Recursive function the format the current profiling array into a tree.
Definition: SectionProfiler.php:292
SectionProfiler\reset
reset()
Clear all of the profiling data for another run.
Definition: SectionProfiler.php:138
SectionProfiler\profileOutInternal
profileOutInternal( $functionname)
This method should not be called outside SectionProfiler.
Definition: SectionProfiler.php:225
SectionProfiler\getErrorEntry
getErrorEntry()
Definition: SectionProfiler.php:164
SectionProfiler\$stack
array $stack
List of resolved profile calls with start/end data.
Definition: SectionProfiler.php:36
SectionProfiler\scopedProfileOut
scopedProfileOut(ScopedCallback &$section)
Definition: SectionProfiler.php:71
SectionProfiler\updateEntry
updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange)
Update the collation entry for a given method name.
Definition: SectionProfiler.php:178
SectionProfiler\getTime
getTime( $metric='wall')
Get the initial time of the request, based on getrusage()
Definition: SectionProfiler.php:458
$section
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:2981
as
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
SectionProfiler\getCallTreeReport
getCallTreeReport()
Returns a tree of function calls with their real times.
Definition: SectionProfiler.php:277
SectionProfiler\collateData
collateData()
Populate collated data.
Definition: SectionProfiler.php:346
SectionProfiler\$end
array $end
Map of (mem,real,cpu)
Definition: SectionProfiler.php:34
SectionProfileCallback\__destruct
__destruct()
Definition: SectionProfiler.php:521
wfGetRusage
wfGetRusage()
Get system resource usage of current request context.
Definition: ProfilerFunctions.php:32
SectionProfiler\profileInInternal
profileInInternal( $functionname)
This method should not be called outside SectionProfiler.
Definition: SectionProfiler.php:197
array
the array() calling protocol came about after MediaWiki 1.4rc1.
SectionProfiler\getZeroEntry
getZeroEntry()
Definition: SectionProfiler.php:150