MediaWiki REL1_39
SectionProfiler.php
Go to the documentation of this file.
1<?php
22use Psr\Log\LoggerInterface;
23use 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 list( $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.