MediaWiki  REL1_31
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  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 }
505 
511 class SectionProfileCallback extends ScopedCallback {
513  protected $profiler;
515  protected $section;
516 
522  parent::__construct( null );
523  $this->profiler = $profiler;
524  $this->section = $section;
525  }
526 
527  function __destruct() {
528  $this->profiler->profileOutInternal( $this->section );
529  }
530 }
$time
see documentation in includes Linker php for Linker::makeImageLink & $time
Definition: hooks.txt:1795
SectionProfiler\$start
array $start
Map of (mem,real,cpu)
Definition: SectionProfiler.php:32
use
Apache License January AND DISTRIBUTION Definitions License shall mean the terms and conditions for use
Definition: APACHE-LICENSE-2.0.txt:10
array
the array() calling protocol came about after MediaWiki 1.4rc1.
$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:2255
SectionProfiler\calculateOverhead
calculateOverhead( $profileCount)
Dummy calls to calculate profiling overhead.
Definition: SectionProfiler.php:428
SectionProfileCallback\$profiler
SectionProfiler $profiler
Definition: SectionProfiler.php:513
SectionProfiler\scopedProfileIn
scopedProfileIn( $section)
Definition: SectionProfiler.php:62
SectionProfiler\getFunctionStats
getFunctionStats()
Get the aggregated inclusive profiling data for each method.
Definition: SectionProfiler.php:96
SectionProfileCallback\__construct
__construct(SectionProfiler $profiler, $section)
Definition: SectionProfiler.php:521
SectionProfiler\calltreeCount
calltreeCount( $stack, $start)
Counts the number of profiled function calls sitting under the given point in the call graph.
Definition: SectionProfiler.php:445
$params
$params
Definition: styleTest.css.php:40
$s
$s
Definition: mergeMessageFileList.php:187
SectionProfileCallback\$section
string $section
Definition: SectionProfiler.php:515
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:1087
SectionProfileCallback
Subclass ScopedCallback to avoid call_user_func_array(), which is slow.
Definition: SectionProfiler.php:511
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:37
SectionProfiler\debug
debug( $s)
Add an entry in the debug log file.
Definition: SectionProfiler.php:487
SectionProfiler\debugGroup
debugGroup( $group, $s)
Add an entry in the debug log group.
Definition: SectionProfiler.php:499
wfGetRusage
wfGetRusage()
Get system resource usage of current request context.
Definition: GlobalFunctions.php:3448
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:338
SectionProfiler\__construct
__construct(array $params=[])
Definition: SectionProfiler.php:53
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:994
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:298
$fname
if(defined( 'MW_SETUP_CALLBACK')) $fname
Customization point after all loading (constants, functions, classes, DefaultSettings,...
Definition: Setup.php:112
SectionProfiler\reset
reset()
Clear all of the profiling data for another run.
Definition: SectionProfiler.php:144
SectionProfiler\profileOutInternal
profileOutInternal( $functionname)
This method should not be called outside SectionProfiler.
Definition: SectionProfiler.php:231
SectionProfiler\getErrorEntry
getErrorEntry()
Definition: SectionProfiler.php:170
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:184
$name
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:302
SectionProfiler\getTime
getTime( $metric='wall')
Get the initial time of the request, based on getrusage()
Definition: SectionProfiler.php:464
$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:3022
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:22
SectionProfiler\getCallTreeReport
getCallTreeReport()
Returns a tree of function calls with their real times.
Definition: SectionProfiler.php:283
SectionProfiler\collateData
collateData()
Populate collated data.
Definition: SectionProfiler.php:352
SectionProfiler\$end
array $end
Map of (mem,real,cpu)
Definition: SectionProfiler.php:34
SectionProfileCallback\__destruct
__destruct()
Definition: SectionProfiler.php:527
SectionProfiler\profileInInternal
profileInInternal( $functionname)
This method should not be called outside SectionProfiler.
Definition: SectionProfiler.php:203
SectionProfiler\getZeroEntry
getZeroEntry()
Definition: SectionProfiler.php:156