Code Coverage |
||||||||||
Lines |
Functions and Methods |
Classes and Traits |
||||||||
| Total | |
0.00% |
0 / 118 |
|
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 | * This program is free software; you can redistribute it and/or modify |
| 4 | * it under the terms of the GNU General Public License as published by |
| 5 | * the Free Software Foundation; either version 2 of the License, or |
| 6 | * (at your option) any later version. |
| 7 | * |
| 8 | * This program is distributed in the hope that it will be useful, |
| 9 | * but WITHOUT ANY WARRANTY; without even the implied warranty of |
| 10 | * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the |
| 11 | * GNU General Public License for more details. |
| 12 | * |
| 13 | * You should have received a copy of the GNU General Public License along |
| 14 | * with this program; if not, write to the Free Software Foundation, Inc., |
| 15 | * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. |
| 16 | * http://www.gnu.org/copyleft/gpl.html |
| 17 | * |
| 18 | * @file |
| 19 | */ |
| 20 | |
| 21 | use MediaWiki\Logger\LoggerFactory; |
| 22 | use Psr\Log\LoggerInterface; |
| 23 | use Wikimedia\ScopedCallback; |
| 24 | |
| 25 | /** |
| 26 | * Arbitrary section name based PHP profiling. |
| 27 | * |
| 28 | * This custom profiler can track code execution that doesn't cleanly map to a |
| 29 | * function call and thus can't be handled by ProfilerXhprof or ProfilerExcimer. |
| 30 | * For example, parser invocations or DB queries. |
| 31 | * |
| 32 | * @since 1.25 |
| 33 | * @ingroup Profiler |
| 34 | */ |
| 35 | class SectionProfiler { |
| 36 | /** @var array|null Map of (mem,real,cpu) */ |
| 37 | protected $start; |
| 38 | /** @var array|null Map of (mem,real,cpu) */ |
| 39 | protected $end; |
| 40 | /** @var array[] List of resolved profile calls with start/end data */ |
| 41 | protected $stack = []; |
| 42 | /** @var array Queue of open profile calls with start data */ |
| 43 | protected $workStack = []; |
| 44 | /** @var array[] Map of (function name => aggregate data array) */ |
| 45 | protected $collated = []; |
| 46 | /** @var bool */ |
| 47 | protected $collateDone = false; |
| 48 | |
| 49 | /** @var array Cache of a standard broken collation entry */ |
| 50 | protected $errorEntry; |
| 51 | /** @var LoggerInterface */ |
| 52 | protected $logger; |
| 53 | |
| 54 | /** |
| 55 | * @param array $params |
| 56 | */ |
| 57 | public function __construct( array $params = [] ) { |
| 58 | $this->errorEntry = $this->getErrorEntry(); |
| 59 | $this->logger = LoggerFactory::getInstance( 'profiler' ); |
| 60 | } |
| 61 | |
| 62 | /** |
| 63 | * @param string $section |
| 64 | * @return SectionProfileCallback |
| 65 | */ |
| 66 | public function scopedProfileIn( $section ) { |
| 67 | $this->profileInInternal( $section ); |
| 68 | |
| 69 | return new SectionProfileCallback( $this, $section ); |
| 70 | } |
| 71 | |
| 72 | /** |
| 73 | * @param ScopedCallback &$section |
| 74 | */ |
| 75 | public function scopedProfileOut( ScopedCallback &$section ) { |
| 76 | $section = null; |
| 77 | } |
| 78 | |
| 79 | /** |
| 80 | * Get the aggregated inclusive profiling data for each method |
| 81 | * |
| 82 | * The percent time for each time is based on the current "total" time |
| 83 | * used is based on all methods so far. This method can therefore be |
| 84 | * called several times in between several profiling calls without the |
| 85 | * delays in usage of the profiler skewing the results. A "-total" entry |
| 86 | * is always included in the results. |
| 87 | * |
| 88 | * @return array[] List of method entries arrays, each having: |
| 89 | * - name : method name |
| 90 | * - calls : the number of invoking calls |
| 91 | * - real : real time elapsed (ms) |
| 92 | * - %real : percent real time |
| 93 | * - cpu : real time elapsed (ms) |
| 94 | * - %cpu : percent real time |
| 95 | * - memory : memory used (bytes) |
| 96 | * - %memory : percent memory used |
| 97 | * - min_real : min real time in a call (ms) |
| 98 | * - max_real : max real time in a call (ms) |
| 99 | */ |
| 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 | |
| 145 | /** |
| 146 | * Clear all of the profiling data for another run |
| 147 | */ |
| 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 | |
| 157 | /** |
| 158 | * @return array Initial collation entry |
| 159 | */ |
| 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 | |
| 171 | /** |
| 172 | * @return array Initial collation entry for errors |
| 173 | */ |
| 174 | protected function getErrorEntry() { |
| 175 | $entry = $this->getZeroEntry(); |
| 176 | $entry['count'] = 1; |
| 177 | return $entry; |
| 178 | } |
| 179 | |
| 180 | /** |
| 181 | * Update the collation entry for a given method name |
| 182 | * |
| 183 | * @param string $name |
| 184 | * @param float $elapsedCpu |
| 185 | * @param float $elapsedReal |
| 186 | * @param int $memChange |
| 187 | */ |
| 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 | |
| 202 | /** |
| 203 | * This method should not be called outside SectionProfiler |
| 204 | * |
| 205 | * @param string $functionname |
| 206 | */ |
| 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 | |
| 230 | /** |
| 231 | * This method should not be called outside SectionProfiler |
| 232 | * |
| 233 | * @param string $functionname |
| 234 | */ |
| 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 | |
| 270 | /** |
| 271 | * Populate collated data |
| 272 | */ |
| 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 | |
| 284 | /** |
| 285 | * Get the initial time of the request, based on getrusage() |
| 286 | * |
| 287 | * @param string|bool $metric Metric to use, with the following possibilities: |
| 288 | * - user: User CPU time (without system calls) |
| 289 | * - cpu: Total CPU time (user and system calls) |
| 290 | * - wall (or any other string): elapsed time |
| 291 | * - false (default): will fall back to default metric |
| 292 | * @return float |
| 293 | */ |
| 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 | } |