Code Coverage |
||||||||||
Lines |
Functions and Methods |
Classes and Traits |
||||||||
| Total | |
0.00% |
0 / 119 |
|
0.00% |
0 / 12 |
CRAP | |
0.00% |
0 / 1 |
| SectionProfiler | |
0.00% |
0 / 118 |
|
0.00% |
0 / 12 |
870 | |
0.00% |
0 / 1 |
| __construct | |
0.00% |
0 / 2 |
|
0.00% |
0 / 1 |
2 | |||
| scopedProfileIn | |
0.00% |
0 / 2 |
|
0.00% |
0 / 1 |
2 | |||
| scopedProfileOut | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| getFunctionStats | |
0.00% |
0 / 35 |
|
0.00% |
0 / 1 |
56 | |||
| reset | |
0.00% |
0 / 6 |
|
0.00% |
0 / 1 |
2 | |||
| getZeroEntry | |
0.00% |
0 / 8 |
|
0.00% |
0 / 1 |
2 | |||
| getErrorEntry | |
0.00% |
0 / 3 |
|
0.00% |
0 / 1 |
2 | |||
| updateEntry | |
0.00% |
0 / 10 |
|
0.00% |
0 / 1 |
12 | |||
| profileInInternal | |
0.00% |
0 / 13 |
|
0.00% |
0 / 1 |
6 | |||
| profileOutInternal | |
0.00% |
0 / 26 |
|
0.00% |
0 / 1 |
20 | |||
| collateData | |
0.00% |
0 / 5 |
|
0.00% |
0 / 1 |
12 | |||
| getTime | |
0.00% |
0 / 7 |
|
0.00% |
0 / 1 |
20 | |||
| 1 | <?php |
| 2 | /** |
| 3 | * @license GPL-2.0-or-later |
| 4 | * @file |
| 5 | */ |
| 6 | |
| 7 | namespace MediaWiki\Profiler; |
| 8 | |
| 9 | use MediaWiki\Logger\LoggerFactory; |
| 10 | use Psr\Log\LoggerInterface; |
| 11 | use Wikimedia\Timestamp\ConvertibleTimestamp; |
| 12 | |
| 13 | /** |
| 14 | * Arbitrary section name based PHP profiling. |
| 15 | * |
| 16 | * This custom profiler can track code execution that doesn't cleanly map to a |
| 17 | * function call and thus can't be handled by ProfilerXhprof or ProfilerExcimer. |
| 18 | * For example, parser invocations or DB queries. |
| 19 | * |
| 20 | * @since 1.25 |
| 21 | * @ingroup Profiler |
| 22 | */ |
| 23 | class SectionProfiler { |
| 24 | /** @var array|null Map of (mem,real,cpu) */ |
| 25 | protected $start; |
| 26 | /** @var array|null Map of (mem,real,cpu) */ |
| 27 | protected $end; |
| 28 | /** @var array[] List of resolved profile calls with start/end data */ |
| 29 | protected $stack = []; |
| 30 | /** @var array Queue of open profile calls with start data */ |
| 31 | protected $workStack = []; |
| 32 | /** @var array[] Map of (function name => aggregate data array) */ |
| 33 | protected $collated = []; |
| 34 | /** @var bool */ |
| 35 | protected $collateDone = false; |
| 36 | |
| 37 | /** @var array Cache of a standard broken collation entry */ |
| 38 | protected $errorEntry; |
| 39 | /** @var LoggerInterface */ |
| 40 | protected $logger; |
| 41 | |
| 42 | /** |
| 43 | * @param array $params |
| 44 | */ |
| 45 | public function __construct( array $params = [] ) { |
| 46 | $this->errorEntry = $this->getErrorEntry(); |
| 47 | $this->logger = LoggerFactory::getInstance( 'profiler' ); |
| 48 | } |
| 49 | |
| 50 | /** |
| 51 | * @param string $section |
| 52 | */ |
| 53 | #[\NoDiscard] |
| 54 | public function scopedProfileIn( $section ): ?SectionProfileCallback { |
| 55 | $this->profileInInternal( $section ); |
| 56 | |
| 57 | return new SectionProfileCallback( $this, $section ); |
| 58 | } |
| 59 | |
| 60 | public function scopedProfileOut( ?SectionProfileCallback &$section ) { |
| 61 | $section = null; |
| 62 | } |
| 63 | |
| 64 | /** |
| 65 | * Get the aggregated inclusive profiling data for each method |
| 66 | * |
| 67 | * The percent time for each time is based on the current "total" time |
| 68 | * used is based on all methods so far. This method can therefore be |
| 69 | * called several times in between several profiling calls without the |
| 70 | * delays in usage of the profiler skewing the results. A "-total" entry |
| 71 | * is always included in the results. |
| 72 | * |
| 73 | * @return array[] List of method entries arrays, each having: |
| 74 | * - name : method name |
| 75 | * - calls : the number of invoking calls |
| 76 | * - real : real time elapsed (ms) |
| 77 | * - %real : percent real time |
| 78 | * - cpu : real time elapsed (ms) |
| 79 | * - %cpu : percent real time |
| 80 | * - memory : memory used (bytes) |
| 81 | * - %memory : percent memory used |
| 82 | * - min_real : min real time in a call (ms) |
| 83 | * - max_real : max real time in a call (ms) |
| 84 | */ |
| 85 | public function getFunctionStats() { |
| 86 | $this->collateData(); |
| 87 | |
| 88 | if ( is_array( $this->start ) && is_array( $this->end ) ) { |
| 89 | $totalCpu = max( $this->end['cpu'] - $this->start['cpu'], 0 ); |
| 90 | $totalReal = max( $this->end['real'] - $this->start['real'], 0 ); |
| 91 | $totalMem = max( $this->end['memory'] - $this->start['memory'], 0 ); |
| 92 | } else { |
| 93 | $totalCpu = 0; |
| 94 | $totalReal = 0; |
| 95 | $totalMem = 0; |
| 96 | } |
| 97 | |
| 98 | $profile = []; |
| 99 | foreach ( $this->collated as $fname => $data ) { |
| 100 | $profile[] = [ |
| 101 | 'name' => $fname, |
| 102 | 'calls' => $data['count'], |
| 103 | 'real' => $data['real'] * 1000, |
| 104 | '%real' => $totalReal ? 100 * $data['real'] / $totalReal : 0, |
| 105 | 'cpu' => $data['cpu'] * 1000, |
| 106 | '%cpu' => $totalCpu ? 100 * $data['cpu'] / $totalCpu : 0, |
| 107 | 'memory' => $data['memory'], |
| 108 | '%memory' => $totalMem ? 100 * $data['memory'] / $totalMem : 0, |
| 109 | 'min_real' => 1000 * $data['min_real'], |
| 110 | 'max_real' => 1000 * $data['max_real'] |
| 111 | ]; |
| 112 | } |
| 113 | |
| 114 | $profile[] = [ |
| 115 | 'name' => '-total', |
| 116 | 'calls' => 1, |
| 117 | 'real' => 1000 * $totalReal, |
| 118 | '%real' => 100, |
| 119 | 'cpu' => 1000 * $totalCpu, |
| 120 | '%cpu' => 100, |
| 121 | 'memory' => $totalMem, |
| 122 | '%memory' => 100, |
| 123 | 'min_real' => 1000 * $totalReal, |
| 124 | 'max_real' => 1000 * $totalReal |
| 125 | ]; |
| 126 | |
| 127 | return $profile; |
| 128 | } |
| 129 | |
| 130 | /** |
| 131 | * Clear all of the profiling data for another run |
| 132 | */ |
| 133 | public function reset() { |
| 134 | $this->start = null; |
| 135 | $this->end = null; |
| 136 | $this->stack = []; |
| 137 | $this->workStack = []; |
| 138 | $this->collated = []; |
| 139 | $this->collateDone = false; |
| 140 | } |
| 141 | |
| 142 | /** |
| 143 | * @return array Initial collation entry |
| 144 | */ |
| 145 | protected function getZeroEntry() { |
| 146 | return [ |
| 147 | 'cpu' => 0.0, |
| 148 | 'real' => 0.0, |
| 149 | 'memory' => 0, |
| 150 | 'count' => 0, |
| 151 | 'min_real' => 0.0, |
| 152 | 'max_real' => 0.0 |
| 153 | ]; |
| 154 | } |
| 155 | |
| 156 | /** |
| 157 | * @return array Initial collation entry for errors |
| 158 | */ |
| 159 | protected function getErrorEntry() { |
| 160 | $entry = $this->getZeroEntry(); |
| 161 | $entry['count'] = 1; |
| 162 | return $entry; |
| 163 | } |
| 164 | |
| 165 | /** |
| 166 | * Update the collation entry for a given method name |
| 167 | * |
| 168 | * @param string $name |
| 169 | * @param float $elapsedCpu |
| 170 | * @param float $elapsedReal |
| 171 | * @param int $memChange |
| 172 | */ |
| 173 | protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) { |
| 174 | $entry =& $this->collated[$name]; |
| 175 | if ( !is_array( $entry ) ) { |
| 176 | $entry = $this->getZeroEntry(); |
| 177 | $this->collated[$name] =& $entry; |
| 178 | } |
| 179 | $entry['cpu'] += $elapsedCpu; |
| 180 | $entry['real'] += $elapsedReal; |
| 181 | $entry['memory'] += $memChange > 0 ? $memChange : 0; |
| 182 | $entry['count']++; |
| 183 | $entry['min_real'] = min( $entry['min_real'], $elapsedReal ); |
| 184 | $entry['max_real'] = max( $entry['max_real'], $elapsedReal ); |
| 185 | } |
| 186 | |
| 187 | /** |
| 188 | * This method should not be called outside SectionProfiler |
| 189 | * |
| 190 | * @param string $functionname |
| 191 | */ |
| 192 | public function profileInInternal( $functionname ) { |
| 193 | // Once the data is collated for reports, any future calls |
| 194 | // should clear the collation cache so the next report will |
| 195 | // reflect them. This matters when trace mode is used. |
| 196 | $this->collateDone = false; |
| 197 | |
| 198 | $cpu = $this->getTime( 'cpu' ); |
| 199 | $real = $this->getTime( 'wall' ); |
| 200 | $memory = memory_get_usage(); |
| 201 | |
| 202 | if ( $this->start === null ) { |
| 203 | $this->start = [ 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ]; |
| 204 | } |
| 205 | |
| 206 | $this->workStack[] = [ |
| 207 | $functionname, |
| 208 | count( $this->workStack ), |
| 209 | $real, |
| 210 | $cpu, |
| 211 | $memory |
| 212 | ]; |
| 213 | } |
| 214 | |
| 215 | /** |
| 216 | * This method should not be called outside SectionProfiler |
| 217 | * |
| 218 | * @param string $functionname |
| 219 | */ |
| 220 | public function profileOutInternal( $functionname ) { |
| 221 | $item = array_pop( $this->workStack ); |
| 222 | if ( $item === null ) { |
| 223 | $this->logger->error( "Profiling error: $functionname" ); |
| 224 | return; |
| 225 | } |
| 226 | [ $ofname, /* $ocount */, $ortime, $octime, $omem ] = $item; |
| 227 | |
| 228 | if ( $functionname === 'close' ) { |
| 229 | $message = "Profile section ended by close(): {$ofname}"; |
| 230 | $this->logger->error( $message ); |
| 231 | $this->collated[$message] = $this->errorEntry; |
| 232 | $functionname = $ofname; |
| 233 | } elseif ( $ofname !== $functionname ) { |
| 234 | $message = "Profiling error: in({$ofname}), out($functionname)"; |
| 235 | $this->logger->error( $message ); |
| 236 | $this->collated[$message] = $this->errorEntry; |
| 237 | } |
| 238 | |
| 239 | $realTime = $this->getTime( 'wall' ); |
| 240 | $cpuTime = $this->getTime( 'cpu' ); |
| 241 | $memUsage = memory_get_usage(); |
| 242 | |
| 243 | $elapsedcpu = $cpuTime - $octime; |
| 244 | $elapsedreal = $realTime - $ortime; |
| 245 | $memchange = $memUsage - $omem; |
| 246 | $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange ); |
| 247 | |
| 248 | $this->end = [ |
| 249 | 'cpu' => $cpuTime, |
| 250 | 'real' => $realTime, |
| 251 | 'memory' => $memUsage |
| 252 | ]; |
| 253 | } |
| 254 | |
| 255 | /** |
| 256 | * Populate collated data |
| 257 | */ |
| 258 | protected function collateData() { |
| 259 | if ( $this->collateDone ) { |
| 260 | return; |
| 261 | } |
| 262 | $this->collateDone = true; |
| 263 | // Close opened profiling sections |
| 264 | while ( count( $this->workStack ) ) { |
| 265 | $this->profileOutInternal( 'close' ); |
| 266 | } |
| 267 | } |
| 268 | |
| 269 | /** |
| 270 | * Get the initial time of the request, based on getrusage() |
| 271 | * |
| 272 | * @param string|bool $metric Metric to use, with the following possibilities: |
| 273 | * - user: User CPU time (without system calls) |
| 274 | * - cpu: Total CPU time (user and system calls) |
| 275 | * - wall (or any other string): elapsed time |
| 276 | * - false (default): will fall back to default metric |
| 277 | * @return float |
| 278 | */ |
| 279 | private function getTime( $metric = 'wall' ) { |
| 280 | if ( $metric === 'cpu' || $metric === 'user' ) { |
| 281 | $ru = getrusage( 0 /* RUSAGE_SELF */ ); |
| 282 | $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6; |
| 283 | if ( $metric === 'cpu' ) { |
| 284 | # This is the time of system calls, added to the user time |
| 285 | # it gives the total CPU time |
| 286 | $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6; |
| 287 | } |
| 288 | return $time; |
| 289 | } else { |
| 290 | return ConvertibleTimestamp::hrtime() / 1e9; |
| 291 | } |
| 292 | } |
| 293 | } |
| 294 | |
| 295 | /** @deprecated class alias since 1.46 */ |
| 296 | class_alias( SectionProfiler::class, 'SectionProfiler' ); |