MediaWiki  master
SectionProfiler.php
Go to the documentation of this file.
1 <?php
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 }
profileInInternal( $functionname)
This method should not be called outside SectionProfiler.
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
getTime( $metric='wall')
Get the initial time of the request, based on getrusage()
array $start
Map of (mem,real,cpu)
Apache License January AND DISTRIBUTION Definitions License shall mean the terms and conditions for use
wfGetRusage()
Get system resource usage of current request context.
collateData()
Populate collated data.
array $stack
List of resolved profile calls with start/end data.
see documentation in includes Linker php for Linker::makeImageLink & $time
Definition: hooks.txt:1780
scopedProfileOut(ScopedCallback &$section)
getCallTreeReport()
Returns a tree of function calls with their real times.
static configuration should be added through ResourceLoaderGetConfigVars instead can be used to get the real title e g db for database replication lag or jobqueue for job queue size converted to pseudo seconds It is possible to add more fields and they will be returned to the user in the API response after the basic globals have been set but before ordinary actions take place $output
Definition: hooks.txt:2204
calltreeCount( $stack, $start)
Counts the number of profiled function calls sitting under the given point in the call graph...
Custom PHP profiler for parser/DB type section names that xhprof/xdebug can&#39;t handle.
array $workStack
Queue of open profile calls with start data.
calculateOverhead( $profileCount)
Dummy calls to calculate profiling overhead.
getCallTreeLine( $entry)
Callback to get a formatted line for the call tree.
debug( $s)
Add an entry in the debug log file.
__construct(array $params=[])
getFunctionStats()
Get the aggregated inclusive profiling data for each method.
wfDebug( $text, $dest='all', array $context=[])
Sends a line to the debug log if enabled or, optionally, to a comment in output.
profileOutInternal( $functionname)
This method should not be called outside SectionProfiler.
$params
this hook is for auditing only or null if authentication failed before getting that far or null if we can t even determine that When $user is not null
Definition: hooks.txt:767
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)
if(defined( 'MW_SETUP_CALLBACK')) $fname
Customization point after all loading (constants, functions, classes, DefaultSettings, LocalSettings).
Definition: Setup.php:131
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:3038
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
Subclass ScopedCallback to avoid call_user_func_array(), which is slow.
wfDebugLog( $logGroup, $text, $dest='all', array $context=[])
Send a line to a supplementary debug log file, if configured, or main debug log if not...
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:271
updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange)
Update the collation entry for a given method name.
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.
scopedProfileIn( $section)
debugGroup( $group, $s)
Add an entry in the debug log group.