MediaWiki  master
SectionProfiler.php
Go to the documentation of this file.
1 <?php
22 use Psr\Log\LoggerInterface;
23 use Wikimedia\ScopedCallback;
24 
37  protected $start;
39  protected $end;
41  protected $stack = [];
43  protected $workStack = [];
45  protected $collated = [];
47  protected $collateDone = false;
48 
50  protected $errorEntry;
52  protected $logger;
53 
57  public function __construct( array $params = [] ) {
58  $this->errorEntry = $this->getErrorEntry();
59  $this->logger = LoggerFactory::getInstance( 'profiler' );
60  }
61 
66  public function scopedProfileIn( $section ) {
67  $this->profileInInternal( $section );
68 
69  return new SectionProfileCallback( $this, $section );
70  }
71 
75  public function scopedProfileOut( ScopedCallback &$section ) {
76  $section = null;
77  }
78 
100  public function getFunctionStats() {
101  $this->collateData();
102 
103  if ( is_array( $this->start ) && is_array( $this->end ) ) {
104  $totalCpu = max( $this->end['cpu'] - $this->start['cpu'], 0 );
105  $totalReal = max( $this->end['real'] - $this->start['real'], 0 );
106  $totalMem = max( $this->end['memory'] - $this->start['memory'], 0 );
107  } else {
108  $totalCpu = 0;
109  $totalReal = 0;
110  $totalMem = 0;
111  }
112 
113  $profile = [];
114  foreach ( $this->collated as $fname => $data ) {
115  $profile[] = [
116  'name' => $fname,
117  'calls' => $data['count'],
118  'real' => $data['real'] * 1000,
119  '%real' => $totalReal ? 100 * $data['real'] / $totalReal : 0,
120  'cpu' => $data['cpu'] * 1000,
121  '%cpu' => $totalCpu ? 100 * $data['cpu'] / $totalCpu : 0,
122  'memory' => $data['memory'],
123  '%memory' => $totalMem ? 100 * $data['memory'] / $totalMem : 0,
124  'min_real' => 1000 * $data['min_real'],
125  'max_real' => 1000 * $data['max_real']
126  ];
127  }
128 
129  $profile[] = [
130  'name' => '-total',
131  'calls' => 1,
132  'real' => 1000 * $totalReal,
133  '%real' => 100,
134  'cpu' => 1000 * $totalCpu,
135  '%cpu' => 100,
136  'memory' => $totalMem,
137  '%memory' => 100,
138  'min_real' => 1000 * $totalReal,
139  'max_real' => 1000 * $totalReal
140  ];
141 
142  return $profile;
143  }
144 
148  public function reset() {
149  $this->start = null;
150  $this->end = null;
151  $this->stack = [];
152  $this->workStack = [];
153  $this->collated = [];
154  $this->collateDone = false;
155  }
156 
160  protected function getZeroEntry() {
161  return [
162  'cpu' => 0.0,
163  'real' => 0.0,
164  'memory' => 0,
165  'count' => 0,
166  'min_real' => 0.0,
167  'max_real' => 0.0
168  ];
169  }
170 
174  protected function getErrorEntry() {
175  $entry = $this->getZeroEntry();
176  $entry['count'] = 1;
177  return $entry;
178  }
179 
188  protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) {
189  $entry =& $this->collated[$name];
190  if ( !is_array( $entry ) ) {
191  $entry = $this->getZeroEntry();
192  $this->collated[$name] =& $entry;
193  }
194  $entry['cpu'] += $elapsedCpu;
195  $entry['real'] += $elapsedReal;
196  $entry['memory'] += $memChange > 0 ? $memChange : 0;
197  $entry['count']++;
198  $entry['min_real'] = min( $entry['min_real'], $elapsedReal );
199  $entry['max_real'] = max( $entry['max_real'], $elapsedReal );
200  }
201 
207  public function profileInInternal( $functionname ) {
208  // Once the data is collated for reports, any future calls
209  // should clear the collation cache so the next report will
210  // reflect them. This matters when trace mode is used.
211  $this->collateDone = false;
212 
213  $cpu = $this->getTime( 'cpu' );
214  $real = $this->getTime( 'wall' );
215  $memory = memory_get_usage();
216 
217  if ( $this->start === null ) {
218  $this->start = [ 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ];
219  }
220 
221  $this->workStack[] = [
222  $functionname,
223  count( $this->workStack ),
224  $real,
225  $cpu,
226  $memory
227  ];
228  }
229 
235  public function profileOutInternal( $functionname ) {
236  $item = array_pop( $this->workStack );
237  if ( $item === null ) {
238  $this->logger->error( "Profiling error: $functionname" );
239  return;
240  }
241  [ $ofname, /* $ocount */, $ortime, $octime, $omem ] = $item;
242 
243  if ( $functionname === 'close' ) {
244  $message = "Profile section ended by close(): {$ofname}";
245  $this->logger->error( $message );
246  $this->collated[$message] = $this->errorEntry;
247  $functionname = $ofname;
248  } elseif ( $ofname !== $functionname ) {
249  $message = "Profiling error: in({$ofname}), out($functionname)";
250  $this->logger->error( $message );
251  $this->collated[$message] = $this->errorEntry;
252  }
253 
254  $realTime = $this->getTime( 'wall' );
255  $cpuTime = $this->getTime( 'cpu' );
256  $memUsage = memory_get_usage();
257 
258  $elapsedcpu = $cpuTime - $octime;
259  $elapsedreal = $realTime - $ortime;
260  $memchange = $memUsage - $omem;
261  $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
262 
263  $this->end = [
264  'cpu' => $cpuTime,
265  'real' => $realTime,
266  'memory' => $memUsage
267  ];
268  }
269 
273  protected function collateData() {
274  if ( $this->collateDone ) {
275  return;
276  }
277  $this->collateDone = true;
278  // Close opened profiling sections
279  while ( count( $this->workStack ) ) {
280  $this->profileOutInternal( 'close' );
281  }
282  }
283 
294  protected function getTime( $metric = 'wall' ) {
295  if ( $metric === 'cpu' || $metric === 'user' ) {
296  $ru = getrusage( 0 /* RUSAGE_SELF */ );
297  $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
298  if ( $metric === 'cpu' ) {
299  # This is the time of system calls, added to the user time
300  # it gives the total CPU time
301  $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
302  }
303  return $time;
304  } else {
305  return microtime( true );
306  }
307  }
308 }
PSR-3 logger instance factory.
Subclass ScopedCallback to avoid call_user_func_array(), which is slow.
Arbitrary section name based PHP profiling.
array[] $collated
Map of (function name => aggregate data array)
profileInInternal( $functionname)
This method should not be called outside SectionProfiler.
LoggerInterface $logger
array $errorEntry
Cache of a standard broken collation entry.
scopedProfileOut(ScopedCallback &$section)
getTime( $metric='wall')
Get the initial time of the request, based on getrusage()
array null $start
Map of (mem,real,cpu)
__construct(array $params=[])
array $workStack
Queue of open profile calls with start data.
getFunctionStats()
Get the aggregated inclusive profiling data for each method.
array null $end
Map of (mem,real,cpu)
scopedProfileIn( $section)
profileOutInternal( $functionname)
This method should not be called outside SectionProfiler.
array[] $stack
List of resolved profile calls with start/end data.
reset()
Clear all of the profiling data for another run.
updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange)
Update the collation entry for a given method name.
collateData()
Populate collated data.