MediaWiki  1.29.1
SectionProfiler.php
Go to the documentation of this file.
1 <?php
24 use Wikimedia\ScopedCallback;
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 }
SectionProfiler\$start
array $start
Map of (mem,real,cpu)
Definition: SectionProfiler.php:33
captcha-old.count
count
Definition: captcha-old.py:225
SectionProfiler\calculateOverhead
calculateOverhead( $profileCount)
Dummy calls to calculate profiling overhead.
Definition: SectionProfiler.php:423
SectionProfileCallback\$profiler
SectionProfiler $profiler
Definition: SectionProfiler.php:508
SectionProfiler\scopedProfileIn
scopedProfileIn( $section)
Definition: SectionProfiler.php:63
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:97
$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:516
SectionProfiler\calltreeCount
calltreeCount( $stack, $start)
Counts the number of profiled function calls sitting under the given point in the call graph.
Definition: SectionProfiler.php:440
$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:304
SectionProfileCallback\$section
string $section
Definition: SectionProfiler.php:510
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:1092
SectionProfileCallback
Subclass ScopedCallback to avoid call_user_func_array(), which is slow.
Definition: SectionProfiler.php:506
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:482
SectionProfiler\debugGroup
debugGroup( $group, $s)
Add an entry in the debug log group.
Definition: SectionProfiler.php:494
SectionProfiler\$workStack
array $workStack
Queue of open profile calls with start data.
Definition: SectionProfiler.php:39
SectionProfiler\$collateDone
bool $collateDone
Definition: SectionProfiler.php:44
SectionProfiler\$collateOnly
bool $collateOnly
Whether to collect the full stack trace or just aggregates.
Definition: SectionProfiler.php:47
$output
this hook is for auditing only RecentChangesLinked and Watchlist RecentChangesLinked and Watchlist Do not use this to implement individual filters if they are compatible with the ChangesListFilter and ChangesListFilterGroup structure use sub classes of those in conjunction with the ChangesListSpecialPageStructuredFilters hook This hook can be used to implement filters that do not implement that or custom behavior that is not an individual filter e g Watchlist and Watchlist you will want to construct new ChangesListBooleanFilter or ChangesListStringOptionsFilter objects When constructing you specify which group they belong to You can reuse existing or create your you must register them with $special registerFilterGroup 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:1049
SectionProfiler\getCallTreeLine
getCallTreeLine( $entry)
Callback to get a formatted line for the call tree.
Definition: SectionProfiler.php:333
SectionProfiler\__construct
__construct(array $params=[])
Definition: SectionProfiler.php:54
$time
see documentation in includes Linker php for Linker::makeImageLink & $time
Definition: hooks.txt:1769
SectionProfiler\$collated
array $collated
Map of (function name => aggregate data array)
Definition: SectionProfiler.php:42
SectionProfiler
Custom PHP profiler for parser/DB type section names that xhprof/xdebug can't handle.
Definition: SectionProfiler.php:31
SectionProfiler\$errorEntry
array $errorEntry
Cache of a standard broken collation entry.
Definition: SectionProfiler.php:49
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:999
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:293
SectionProfiler\reset
reset()
Clear all of the profiling data for another run.
Definition: SectionProfiler.php:139
SectionProfiler\profileOutInternal
profileOutInternal( $functionname)
This method should not be called outside SectionProfiler.
Definition: SectionProfiler.php:226
SectionProfiler\getErrorEntry
getErrorEntry()
Definition: SectionProfiler.php:165
SectionProfiler\$stack
array $stack
List of resolved profile calls with start/end data.
Definition: SectionProfiler.php:37
SectionProfiler\scopedProfileOut
scopedProfileOut(ScopedCallback &$section)
Definition: SectionProfiler.php:72
SectionProfiler\updateEntry
updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange)
Update the collation entry for a given method name.
Definition: SectionProfiler.php:179
SectionProfiler\getTime
getTime( $metric='wall')
Get the initial time of the request, based on getrusage()
Definition: SectionProfiler.php:459
$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:2929
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:278
SectionProfiler\collateData
collateData()
Populate collated data.
Definition: SectionProfiler.php:347
SectionProfiler\$end
array $end
Map of (mem,real,cpu)
Definition: SectionProfiler.php:35
SectionProfileCallback\__destruct
__destruct()
Definition: SectionProfiler.php:522
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:198
array
the array() calling protocol came about after MediaWiki 1.4rc1.
SectionProfiler\getZeroEntry
getZeroEntry()
Definition: SectionProfiler.php:151