includes/profiler/SectionProfiler.php

   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         public function scopedProfileOut( ScopedCallback &$section ) {
  73                 $section = null;
  74         }
  75
  76         /**
  77          * Get the aggregated inclusive profiling data for each method
  78          *
  79          * The percent time for each time is based on the current "total" time
  80          * used is based on all methods so far. This method can therefore be
  81          * called several times in between several profiling calls without the
  82          * delays in usage of the profiler skewing the results. A "-total" entry
  83          * is always included in the results.
  84          *
  85          * @return array[] List of method entries arrays, each having:
  86          *   - name    : method name
  87          *   - calls   : the number of invoking calls
  88          *   - real    : real time elapsed (ms)
  89          *   - %real   : percent real time
  90          *   - cpu     : real time elapsed (ms)
  91          *   - %cpu    : percent real time
  92          *   - memory  : memory used (bytes)
  93          *   - %memory : percent memory used
  94          *   - min_real : min real time in a call (ms)
  95          *   - max_real : max real time in a call (ms)
  96          */
  97         public function getFunctionStats() {
  98                 $this->collateData();
  99
 100                 if ( is_array( $this->start ) && is_array( $this->end ) ) {
 101                         $totalCpu = max( $this->end['cpu'] - $this->start['cpu'], 0 );
 102                         $totalReal = max( $this->end['real'] - $this->start['real'], 0 );
 103                         $totalMem = max( $this->end['memory'] - $this->start['memory'], 0 );
 104                 } else {
 105                         $totalCpu = 0;
 106                         $totalReal = 0;
 107                         $totalMem = 0;
 108                 }
 109
 110                 $profile = [];
 111                 foreach ( $this->collated as $fname => $data ) {
 112                         $profile[] = [
 113                                 'name' => $fname,
 114                                 'calls' => $data['count'],
 115                                 'real' => $data['real'] * 1000,
 116                                 '%real' => $totalReal ? 100 * $data['real'] / $totalReal : 0,
 117                                 'cpu' => $data['cpu'] * 1000,
 118                                 '%cpu' => $totalCpu ? 100 * $data['cpu'] / $totalCpu : 0,
 119                                 'memory' => $data['memory'],
 120                                 '%memory' => $totalMem ? 100 * $data['memory'] / $totalMem : 0,
 121                                 'min_real' => 1000 * $data['min_real'],
 122                                 'max_real' => 1000 * $data['max_real']
 123                         ];
 124                 }
 125
 126                 $profile[] = [
 127                         'name' => '-total',
 128                         'calls' => 1,
 129                         'real' => 1000 * $totalReal,
 130                         '%real' => 100,
 131                         'cpu' => 1000 * $totalCpu,
 132                         '%cpu' => 100,
 133                         'memory' => $totalMem,
 134                         '%memory' => 100,
 135                         'min_real' => 1000 * $totalReal,
 136                         'max_real' => 1000 * $totalReal
 137                 ];
 138
 139                 return $profile;
 140         }
 141
 142         /**
 143          * Clear all of the profiling data for another run
 144          */
 145         public function reset() {
 146                 $this->start = null;
 147                 $this->end = null;
 148                 $this->stack = [];
 149                 $this->workStack = [];
 150                 $this->collated = [];
 151                 $this->collateDone = false;
 152         }
 153
 154         /**
 155          * @return array Initial collation entry
 156          */
 157         protected function getZeroEntry() {
 158                 return [
 159                         'cpu'      => 0.0,
 160                         'real'     => 0.0,
 161                         'memory'   => 0,
 162                         'count'    => 0,
 163                         'min_real' => 0.0,
 164                         'max_real' => 0.0
 165                 ];
 166         }
 167
 168         /**
 169          * @return array Initial collation entry for errors
 170          */
 171         protected function getErrorEntry() {
 172                 $entry = $this->getZeroEntry();
 173                 $entry['count'] = 1;
 174                 return $entry;
 175         }
 176
 177         /**
 178          * Update the collation entry for a given method name
 179          *
 180          * @param string $name
 181          * @param float $elapsedCpu
 182          * @param float $elapsedReal
 183          * @param int $memChange
 184          */
 185         protected function updateEntry( $name, $elapsedCpu, $elapsedReal, $memChange ) {
 186                 $entry =& $this->collated[$name];
 187                 if ( !is_array( $entry ) ) {
 188                         $entry = $this->getZeroEntry();
 189                         $this->collated[$name] =& $entry;
 190                 }
 191                 $entry['cpu'] += $elapsedCpu;
 192                 $entry['real'] += $elapsedReal;
 193                 $entry['memory'] += $memChange > 0 ? $memChange : 0;
 194                 $entry['count']++;
 195                 $entry['min_real'] = min( $entry['min_real'], $elapsedReal );
 196                 $entry['max_real'] = max( $entry['max_real'], $elapsedReal );
 197         }
 198
 199         /**
 200          * This method should not be called outside SectionProfiler
 201          *
 202          * @param string $functionname
 203          */
 204         public function profileInInternal( $functionname ) {
 205                 // Once the data is collated for reports, any future calls
 206                 // should clear the collation cache so the next report will
 207                 // reflect them. This matters when trace mode is used.
 208                 $this->collateDone = false;
 209
 210                 $cpu = $this->getTime( 'cpu' );
 211                 $real = $this->getTime( 'wall' );
 212                 $memory = memory_get_usage();
 213
 214                 if ( $this->start === null ) {
 215                         $this->start = [ 'cpu' => $cpu, 'real' => $real, 'memory' => $memory ];
 216                 }
 217
 218                 $this->workStack[] = [
 219                         $functionname,
 220                         count( $this->workStack ),
 221                         $real,
 222                         $cpu,
 223                         $memory
 224                 ];
 225         }
 226
 227         /**
 228          * This method should not be called outside SectionProfiler
 229          *
 230          * @param string $functionname
 231          */
 232         public function profileOutInternal( $functionname ) {
 233                 $item = array_pop( $this->workStack );
 234                 if ( $item === null ) {
 235                         $this->logger->error( "Profiling error: $functionname" );
 236                         return;
 237                 }
 238                 [ $ofname, /* $ocount */, $ortime, $octime, $omem ] = $item;
 239
 240                 if ( $functionname === 'close' ) {
 241                         $message = "Profile section ended by close(): {$ofname}";
 242                         $this->logger->error( $message );
 243                         $this->collated[$message] = $this->errorEntry;
 244                         $functionname = $ofname;
 245                 } elseif ( $ofname !== $functionname ) {
 246                         $message = "Profiling error: in({$ofname}), out($functionname)";
 247                         $this->logger->error( $message );
 248                         $this->collated[$message] = $this->errorEntry;
 249                 }
 250
 251                 $realTime = $this->getTime( 'wall' );
 252                 $cpuTime = $this->getTime( 'cpu' );
 253                 $memUsage = memory_get_usage();
 254
 255                 $elapsedcpu = $cpuTime - $octime;
 256                 $elapsedreal = $realTime - $ortime;
 257                 $memchange = $memUsage - $omem;
 258                 $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
 259
 260                 $this->end = [
 261                         'cpu'      => $cpuTime,
 262                         'real'     => $realTime,
 263                         'memory'   => $memUsage
 264                 ];
 265         }
 266
 267         /**
 268          * Populate collated data
 269          */
 270         protected function collateData() {
 271                 if ( $this->collateDone ) {
 272                         return;
 273                 }
 274                 $this->collateDone = true;
 275                 // Close opened profiling sections
 276                 while ( count( $this->workStack ) ) {
 277                         $this->profileOutInternal( 'close' );
 278                 }
 279         }
 280
 281         /**
 282          * Get the initial time of the request, based on getrusage()
 283          *
 284          * @param string|bool $metric Metric to use, with the following possibilities:
 285          *   - user: User CPU time (without system calls)
 286          *   - cpu: Total CPU time (user and system calls)
 287          *   - wall (or any other string): elapsed time
 288          *   - false (default): will fall back to default metric
 289          * @return float
 290          */
 291         protected function getTime( $metric = 'wall' ) {
 292                 if ( $metric === 'cpu' || $metric === 'user' ) {
 293                         $ru = getrusage( 0 /* RUSAGE_SELF */ );
 294                         $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
 295                         if ( $metric === 'cpu' ) {
 296                                 # This is the time of system calls, added to the user time
 297                                 # it gives the total CPU time
 298                                 $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
 299                         }
 300                         return $time;
 301                 } else {
 302                         return microtime( true );
 303                 }
 304         }
 305 }