includes/profiler/Profiler.php

   1 <?php
   2 /**
   3  * Base class and functions for profiling.
   4  *
   5  * This program is free software; you can redistribute it and/or modify
   6  * it under the terms of the GNU General Public License as published by
   7  * the Free Software Foundation; either version 2 of the License, or
   8  * (at your option) any later version.
   9  *
  10  * This program is distributed in the hope that it will be useful,
  11  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  12  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
  13  * GNU General Public License for more details.
  14  *
  15  * You should have received a copy of the GNU General Public License along
  16  * with this program; if not, write to the Free Software Foundation, Inc.,
  17  * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
  18  * http://www.gnu.org/copyleft/gpl.html
  19  *
  20  * @file
  21  * @ingroup Profiler
  22  * This file is only included if profiling is enabled
  23  */
  24
  25 /**
  26  * @defgroup Profiler Profiler
  27  */
  28
  29 /**
  30  * Begin profiling of a function
  31  * @param string $functionname name of the function we will profile
  32  */
  33 function wfProfileIn( $functionname ) {
  34         if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
  35                 Profiler::instance();
  36         }
  37         if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
  38                 Profiler::$__instance->profileIn( $functionname );
  39         }
  40 }
  41
  42 /**
  43  * Stop profiling of a function
  44  * @param string $functionname name of the function we have profiled
  45  */
  46 function wfProfileOut( $functionname = 'missing' ) {
  47         if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
  48                 Profiler::instance();
  49         }
  50         if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
  51                 Profiler::$__instance->profileOut( $functionname );
  52         }
  53 }
  54
  55 /**
  56  * Class for handling function-scope profiling
  57  *
  58  * @since 1.22
  59  */
  60 class ProfileSection {
  61         protected $name; // string; method name
  62         protected $enabled = false; // boolean; whether profiling is enabled
  63
  64         /**
  65          * Begin profiling of a function and return an object that ends profiling of
  66          * the function when that object leaves scope. As long as the object is not
  67          * specifically linked to other objects, it will fall out of scope at the same
  68          * moment that the function to be profiled terminates.
  69          *
  70          * This is typically called like:
  71          * <code>$section = new ProfileSection( __METHOD__ );</code>
  72          *
  73          * @param string $name Name of the function to profile
  74          */
  75         public function __construct( $name ) {
  76                 $this->name = $name;
  77                 if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
  78                         Profiler::instance();
  79                 }
  80                 if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
  81                         $this->enabled = true;
  82                         Profiler::$__instance->profileIn( $this->name );
  83                 }
  84         }
  85
  86         function __destruct() {
  87                 if ( $this->enabled ) {
  88                         Profiler::$__instance->profileOut( $this->name );
  89                 }
  90         }
  91 }
  92
  93 /**
  94  * @ingroup Profiler
  95  * @todo document
  96  */
  97 class Profiler {
  98         /** @var array List of resolved profile calls with start/end data */
  99         protected $mStack = array();
 100         /** @var array Queue of open profile calls with start data */
 101         protected $mWorkStack = array();
 102
 103         /** @var array Map of (function name => aggregate data array) */
 104         protected $mCollated = array();
 105         /** @var bool */
 106         protected $mCollateDone = false;
 107         /** @var bool */
 108         protected $mCollateOnly = false;
 109         /** @var array Cache of a standard broken collation entry */
 110         protected $mErrorEntry;
 111
 112         /** @var string wall|cpu|user */
 113         protected $mTimeMetric = 'wall';
 114         /** @var string|bool Profiler ID for bucketing data */
 115         protected $mProfileID = false;
 116         /** @var bool Whether MediaWiki is in a SkinTemplate output context */
 117         protected $mTemplated = false;
 118
 119         /** @var float seconds */
 120         protected $mDBLockThreshold = 5.0;
 121         /** @var array DB/server name => (active trx count,timestamp) */
 122         protected $mDBTrxHoldingLocks = array();
 123         /** @var array DB/server name => list of (function name, elapsed time) */
 124         protected $mDBTrxMethodTimes = array();
 125
 126         /** @var Profiler */
 127         public static $__instance = null; // do not call this outside Profiler and ProfileSection
 128
 129         /**
 130          * @param array $params
 131          */
 132         public function __construct( array $params ) {
 133                 if ( isset( $params['timeMetric'] ) ) {
 134                         $this->mTimeMetric = $params['timeMetric'];
 135                 }
 136                 if ( isset( $params['profileID'] ) ) {
 137                         $this->mProfileID = $params['profileID'];
 138                 }
 139
 140                 $this->mCollateOnly = $this->collateOnly();
 141
 142                 $this->addInitialStack();
 143         }
 144
 145         /**
 146          * Singleton
 147          * @return Profiler
 148          */
 149         public static function instance() {
 150                 if ( self::$__instance === null ) {
 151                         global $wgProfiler;
 152                         if ( is_array( $wgProfiler ) ) {
 153                                 if ( !isset( $wgProfiler['class'] ) ) {
 154                                         $class = 'ProfilerStub';
 155                                 } else {
 156                                         $class = $wgProfiler['class'];
 157                                 }
 158                                 self::$__instance = new $class( $wgProfiler );
 159                         } elseif ( $wgProfiler instanceof Profiler ) {
 160                                 self::$__instance = $wgProfiler; // back-compat
 161                         } else {
 162                                 self::$__instance = new ProfilerStub( $wgProfiler );
 163                         }
 164                 }
 165                 return self::$__instance;
 166         }
 167
 168         /**
 169          * Set the profiler to a specific profiler instance. Mostly for dumpHTML
 170          * @param Profiler $p
 171          */
 172         public static function setInstance( Profiler $p ) {
 173                 self::$__instance = $p;
 174         }
 175
 176         /**
 177          * Return whether this a stub profiler
 178          *
 179          * @return bool
 180          */
 181         public function isStub() {
 182                 return false;
 183         }
 184
 185         /**
 186          * Return whether this profiler stores data
 187          *
 188          * @see Profiler::logData()
 189          * @return bool
 190          */
 191         public function isPersistent() {
 192                 return false;
 193         }
 194
 195         /**
 196          * @param string $id
 197          */
 198         public function setProfileID( $id ) {
 199                 $this->mProfileID = $id;
 200         }
 201
 202         /**
 203          * @return string
 204          */
 205         public function getProfileID() {
 206                 if ( $this->mProfileID === false ) {
 207                         return wfWikiID();
 208                 } else {
 209                         return $this->mProfileID;
 210                 }
 211         }
 212
 213         /**
 214          * Whether to internally just track aggregates and ignore the full stack trace
 215          *
 216          * @return bool
 217          */
 218         protected function collateOnly() {
 219                 return false;
 220         }
 221
 222         /**
 223          * Add the inital item in the stack.
 224          */
 225         protected function addInitialStack() {
 226                 $this->mErrorEntry = $this->getErrorEntry();
 227
 228                 $initialTime = $this->getInitialTime( 'wall' );
 229                 $initialCpu = $this->getInitialTime( 'cpu' );
 230                 if ( $initialTime !== null && $initialCpu !== null ) {
 231                         $this->mWorkStack[] = array( '-total', 0, $initialTime, $initialCpu, 0 );
 232                         if ( $this->mCollateOnly ) {
 233                                 $this->mWorkStack[] = array( '-setup', 1, $initialTime, $initialCpu, 0 );
 234                                 $this->profileOut( '-setup' );
 235                         } else {
 236                                 $this->mStack[] = array( '-setup', 1, $initialTime, $initialCpu, 0,
 237                                         $this->getTime( 'wall' ), $this->getTime( 'cpu' ), 0 );
 238                         }
 239                 } else {
 240                         $this->profileIn( '-total' );
 241                 }
 242         }
 243
 244         /**
 245          * @return array Initial collation entry
 246          */
 247         protected function getZeroEntry() {
 248                 return array(
 249                         'cpu'      => 0.0,
 250                         'cpu_sq'   => 0.0,
 251                         'real'     => 0.0,
 252                         'real_sq'  => 0.0,
 253                         'memory'   => 0,
 254                         'count'    => 0,
 255                         'min_cpu'  => 0.0,
 256                         'max_cpu'  => 0.0,
 257                         'min_real' => 0.0,
 258                         'max_real' => 0.0,
 259                         'periods'  => array(), // not filled if mCollateOnly
 260                         'overhead' => 0 // not filled if mCollateOnly
 261                 );
 262         }
 263
 264         /**
 265          * @return array Initial collation entry for errors
 266          */
 267         protected function getErrorEntry() {
 268                 $entry = $this->getZeroEntry();
 269                 $entry['count'] = 1;
 270                 return $entry;
 271         }
 272
 273         /**
 274          * Update the collation entry for a given method name
 275          *
 276          * @param string $name
 277          * @param float $elapsedCpu
 278          * @param float $elapsedReal
 279          * @param int $memChange
 280          * @param int $subcalls
 281          * @param array|null $period Map of ('start','end','memory','subcalls')
 282          */
 283         protected function updateEntry(
 284                 $name, $elapsedCpu, $elapsedReal, $memChange, $subcalls = 0, $period = null
 285         ) {
 286                 $entry =& $this->mCollated[$name];
 287                 if ( !is_array( $entry ) ) {
 288                         $entry = $this->getZeroEntry();
 289                         $this->mCollated[$name] =& $entry;
 290                 }
 291                 $entry['cpu'] += $elapsedCpu;
 292                 $entry['cpu_sq'] += $elapsedCpu * $elapsedCpu;
 293                 $entry['real'] += $elapsedReal;
 294                 $entry['real_sq'] += $elapsedReal * $elapsedReal;
 295                 $entry['memory'] += $memChange > 0 ? $memChange : 0;
 296                 $entry['count']++;
 297                 $entry['min_cpu'] = $elapsedCpu < $entry['min_cpu'] ? $elapsedCpu : $entry['min_cpu'];
 298                 $entry['max_cpu'] = $elapsedCpu > $entry['max_cpu'] ? $elapsedCpu : $entry['max_cpu'];
 299                 $entry['min_real'] = $elapsedReal < $entry['min_real'] ? $elapsedReal : $entry['min_real'];
 300                 $entry['max_real'] = $elapsedReal > $entry['max_real'] ? $elapsedReal : $entry['max_real'];
 301                 // Apply optional fields
 302                 $entry['overhead'] += $subcalls;
 303                 if ( $period ) {
 304                         $entry['periods'][] = $period;
 305                 }
 306         }
 307
 308         /**
 309          * Called by wfProfieIn()
 310          *
 311          * @param string $functionname
 312          */
 313         public function profileIn( $functionname ) {
 314                 global $wgDebugFunctionEntry;
 315
 316                 if ( $wgDebugFunctionEntry ) {
 317                         $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) .
 318                                 'Entering ' . $functionname . "\n" );
 319                 }
 320
 321                 $this->mWorkStack[] = array(
 322                         $functionname,
 323                         count( $this->mWorkStack ),
 324                         $this->getTime( 'time' ),
 325                         $this->getTime( 'cpu' ),
 326                         memory_get_usage()
 327                 );
 328         }
 329
 330         /**
 331          * Called by wfProfieOut()
 332          *
 333          * @param  string $functionname
 334          */
 335         public function profileOut( $functionname ) {
 336                 global $wgDebugFunctionEntry;
 337
 338                 if ( $wgDebugFunctionEntry ) {
 339                         $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) .
 340                                 'Exiting ' . $functionname . "\n" );
 341                 }
 342
 343                 $item = array_pop( $this->mWorkStack );
 344                 list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item;
 345
 346                 if ( $item === null ) {
 347                         $this->debugGroup( 'profileerror', "Profiling error: $functionname" );
 348                 } else {
 349                         if ( $functionname === 'close' ) {
 350                                 if ( $ofname !== '-total' ) {
 351                                         $message = "Profile section ended by close(): {$ofname}";
 352                                         $this->debugGroup( 'profileerror', $message );
 353                                         if ( $this->mCollateOnly ) {
 354                                                 $this->mCollated[$message] = $this->mErrorEntry;
 355                                         } else {
 356                                                 $this->mStack[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 );
 357                                         }
 358                                 }
 359                                 $functionname = $ofname;
 360                         } elseif ( $ofname !== $functionname ) {
 361                                 $message = "Profiling error: in({$ofname}), out($functionname)";
 362                                 $this->debugGroup( 'profileerror', $message );
 363                                 if ( $this->mCollateOnly ) {
 364                                         $this->mCollated[$message] = $this->mErrorEntry;
 365                                 } else {
 366                                         $this->mStack[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 );
 367                                 }
 368                         }
 369                         $realTime = $this->getTime( 'wall' );
 370                         $cpuTime = $this->getTime( 'cpu' );
 371                         if ( $this->mCollateOnly ) {
 372                                 $elapsedcpu = $cpuTime - $octime;
 373                                 $elapsedreal = $realTime - $ortime;
 374                                 $memchange = memory_get_usage() - $omem;
 375                                 $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
 376                         } else {
 377                                 $this->mStack[] = array_merge( $item,
 378                                         array( $realTime, $cpuTime,     memory_get_usage() ) );
 379                         }
 380                         $this->updateTrxProfiling( $functionname, $realTime - $ortime );
 381                 }
 382         }
 383
 384         /**
 385          * Close opened profiling sections
 386          */
 387         public function close() {
 388                 while ( count( $this->mWorkStack ) ) {
 389                         $this->profileOut( 'close' );
 390                 }
 391         }
 392
 393         /**
 394          * Log the data to some store or even the page output
 395          */
 396         public function logData() {
 397                 /* Implement in subclasses */
 398         }
 399
 400         /**
 401          * Mark a DB as in a transaction with one or more writes pending
 402          *
 403          * Note that there can be multiple connections to a single DB.
 404          *
 405          * @param string $server DB server
 406          * @param string $db DB name
 407          */
 408         public function transactionWritingIn( $server, $db ) {
 409                 $name = "{$server} ({$db})";
 410                 if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
 411                         ++$this->mDBTrxHoldingLocks[$name]['refs'];
 412                 } else {
 413                         $this->mDBTrxHoldingLocks[$name] = array( 'refs' => 1, 'start' => microtime( true ) );
 414                         $this->mDBTrxMethodTimes[$name] = array();
 415                 }
 416         }
 417
 418         /**
 419          * Register the name and time of a method for slow DB trx detection
 420          *
 421          * @param string $method Function name
 422          * @param float $realtime Wal time ellapsed
 423          */
 424         protected function updateTrxProfiling( $method, $realtime ) {
 425                 if ( !$this->mDBTrxHoldingLocks ) {
 426                         return; // short-circuit
 427                 // @TODO: hardcoded check is a tad janky (what about FOR UPDATE?)
 428                 } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
 429                         && $realtime < $this->mDBLockThreshold
 430                 ) {
 431                         return; // not a DB master query nor slow enough
 432                 }
 433                 $now = microtime( true );
 434                 foreach ( $this->mDBTrxHoldingLocks as $name => $info ) {
 435                         // Hacky check to exclude entries from before the first TRX write
 436                         if ( ( $now - $realtime ) >= $info['start'] ) {
 437                                 $this->mDBTrxMethodTimes[$name][] = array( $method, $realtime );
 438                         }
 439                 }
 440         }
 441
 442         /**
 443          * Mark a DB as no longer in a transaction
 444          *
 445          * This will check if locks are possibly held for longer than
 446          * needed and log any affected transactions to a special DB log.
 447          * Note that there can be multiple connections to a single DB.
 448          *
 449          * @param string $server DB server
 450          * @param string $db DB name
 451          */
 452         public function transactionWritingOut( $server, $db ) {
 453                 $name = "{$server} ({$db})";
 454                 if ( --$this->mDBTrxHoldingLocks[$name]['refs'] <= 0 ) {
 455                         $slow = false;
 456                         foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
 457                                 list( $method, $realtime ) = $info;
 458                                 if ( $realtime >= $this->mDBLockThreshold ) {
 459                                         $slow = true;
 460                                         break;
 461                                 }
 462                         }
 463                         if ( $slow ) {
 464                                 $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks ) );
 465                                 $msg = "Sub-optimal transaction on DB(s) {$dbs}:\n";
 466                                 foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) {
 467                                         list( $method, $realtime ) = $info;
 468                                         $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
 469                                 }
 470                                 $this->debugGroup( 'DBPerformance', $msg );
 471                         }
 472                         unset( $this->mDBTrxHoldingLocks[$name] );
 473                         unset( $this->mDBTrxMethodTimes[$name] );
 474                 }
 475         }
 476
 477         /**
 478          * Mark this call as templated or not
 479          *
 480          * @param bool $t
 481          */
 482         public function setTemplated( $t ) {
 483                 $this->mTemplated = $t;
 484         }
 485
 486         /**
 487          * Returns a profiling output to be stored in debug file
 488          *
 489          * @return string
 490          */
 491         public function getOutput() {
 492                 global $wgDebugFunctionEntry, $wgProfileCallTree;
 493
 494                 $wgDebugFunctionEntry = false; // hack
 495
 496                 if ( !count( $this->mStack ) && !count( $this->mCollated ) ) {
 497                         return "No profiling output\n";
 498                 }
 499
 500                 if ( $wgProfileCallTree ) {
 501                         return $this->getCallTree();
 502                 } else {
 503                         return $this->getFunctionReport();
 504                 }
 505         }
 506
 507         /**
 508          * Returns a tree of function call instead of a list of functions
 509          * @return string
 510          */
 511         protected function getCallTree() {
 512                 return implode( '', array_map(
 513                         array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack )
 514                 ) );
 515         }
 516
 517         /**
 518          * Recursive function the format the current profiling array into a tree
 519          *
 520          * @param array $stack profiling array
 521          * @return array
 522          */
 523         protected function remapCallTree( array $stack ) {
 524                 if ( count( $stack ) < 2 ) {
 525                         return $stack;
 526                 }
 527                 $outputs = array();
 528                 for ( $max = count( $stack ) - 1; $max > 0; ) {
 529                         /* Find all items under this entry */
 530                         $level = $stack[$max][1];
 531                         $working = array();
 532                         for ( $i = $max -1; $i >= 0; $i-- ) {
 533                                 if ( $stack[$i][1] > $level ) {
 534                                         $working[] = $stack[$i];
 535                                 } else {
 536                                         break;
 537                                 }
 538                         }
 539                         $working = $this->remapCallTree( array_reverse( $working ) );
 540                         $output = array();
 541                         foreach ( $working as $item ) {
 542                                 array_push( $output, $item );
 543                         }
 544                         array_unshift( $output, $stack[$max] );
 545                         $max = $i;
 546
 547                         array_unshift( $outputs, $output );
 548                 }
 549                 $final = array();
 550                 foreach ( $outputs as $output ) {
 551                         foreach ( $output as $item ) {
 552                                 $final[] = $item;
 553                         }
 554                 }
 555                 return $final;
 556         }
 557
 558         /**
 559          * Callback to get a formatted line for the call tree
 560          * @return string
 561          */
 562         protected function getCallTreeLine( $entry ) {
 563                 list( $fname, $level, $startreal, , , $endreal ) = $entry;
 564                 $delta = $endreal - $startreal;
 565                 $space = str_repeat( ' ', $level );
 566                 # The ugly double sprintf is to work around a PHP bug,
 567                 # which has been fixed in recent releases.
 568                 return sprintf( "%10s %s %s\n",
 569                         trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
 570         }
 571
 572         /**
 573          * Get the initial time of the request, based either on $wgRequestTime or
 574          * $wgRUstart. Will return null if not able to find data.
 575          *
 576          * @param string|false $metric Metric to use, with the following possibilities:
 577          *   - user: User CPU time (without system calls)
 578          *   - cpu: Total CPU time (user and system calls)
 579          *   - wall (or any other string): elapsed time
 580          *   - false (default): will fall back to default metric
 581          * @return float|null
 582          */
 583         protected function getTime( $metric = false ) {
 584                 if ( $metric === false ) {
 585                         $metric = $this->mTimeMetric;
 586                 }
 587
 588                 if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) {
 589                         if ( !function_exists( 'getrusage' ) ) {
 590                                 return 0;
 591                         }
 592                         $ru = getrusage();
 593                         $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
 594                         if ( $metric === 'cpu' ) {
 595                                 # This is the time of system calls, added to the user time
 596                                 # it gives the total CPU time
 597                                 $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
 598                         }
 599                         return $time;
 600                 } else {
 601                         return microtime( true );
 602                 }
 603         }
 604
 605         /**
 606          * Get the initial time of the request, based either on $wgRequestTime or
 607          * $wgRUstart. Will return null if not able to find data.
 608          *
 609          * @param string|false $metric Metric to use, with the following possibilities:
 610          *   - user: User CPU time (without system calls)
 611          *   - cpu: Total CPU time (user and system calls)
 612          *   - wall (or any other string): elapsed time
 613          *   - false (default): will fall back to default metric
 614          * @return float|null
 615          */
 616         protected function getInitialTime( $metric = false ) {
 617                 global $wgRequestTime, $wgRUstart;
 618
 619                 if ( $metric === false ) {
 620                         $metric = $this->mTimeMetric;
 621                 }
 622
 623                 if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) {
 624                         if ( !count( $wgRUstart ) ) {
 625                                 return null;
 626                         }
 627
 628                         $time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
 629                         if ( $metric === 'cpu' ) {
 630                                 # This is the time of system calls, added to the user time
 631                                 # it gives the total CPU time
 632                                 $time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
 633                         }
 634                         return $time;
 635                 } else {
 636                         if ( empty( $wgRequestTime ) ) {
 637                                 return null;
 638                         } else {
 639                                 return $wgRequestTime;
 640                         }
 641                 }
 642         }
 643
 644         /**
 645          * Populate mCollated
 646          */
 647         protected function collateData() {
 648                 if ( $this->mCollateDone ) {
 649                         return;
 650                 }
 651                 $this->mCollateDone = true;
 652                 $this->close(); // set "-total" entry
 653
 654                 if ( $this->mCollateOnly ) {
 655                         return; // already collated as methods exited
 656                 }
 657
 658                 $this->mCollated = array();
 659
 660                 # Estimate profiling overhead
 661                 $profileCount = count( $this->mStack );
 662                 self::calculateOverhead( $profileCount );
 663
 664                 # First, subtract the overhead!
 665                 $overheadTotal = $overheadMemory = $overheadInternal = array();
 666                 foreach ( $this->mStack as $entry ) {
 667                         // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
 668                         $fname = $entry[0];
 669                         $elapsed = $entry[5] - $entry[2];
 670                         $memchange = $entry[7] - $entry[4];
 671
 672                         if ( $fname === '-overhead-total' ) {
 673                                 $overheadTotal[] = $elapsed;
 674                                 $overheadMemory[] = max( 0, $memchange );
 675                         } elseif ( $fname === '-overhead-internal' ) {
 676                                 $overheadInternal[] = $elapsed;
 677                         }
 678                 }
 679                 $overheadTotal = $overheadTotal ?
 680                         array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
 681                 $overheadMemory = $overheadMemory ?
 682                         array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
 683                 $overheadInternal = $overheadInternal ?
 684                         array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
 685
 686                 # Collate
 687                 foreach ( $this->mStack as $index => $entry ) {
 688                         // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
 689                         $fname = $entry[0];
 690                         $elapsedCpu = $entry[6] - $entry[3];
 691                         $elapsedReal = $entry[5] - $entry[2];
 692                         $memchange = $entry[7] - $entry[4];
 693                         $subcalls = $this->calltreeCount( $this->mStack, $index );
 694
 695                         if ( substr( $fname, 0, 9 ) !== '-overhead' ) {
 696                                 # Adjust for profiling overhead (except special values with elapsed=0
 697                                 if ( $elapsed ) {
 698                                         $elapsed -= $overheadInternal;
 699                                         $elapsed -= ( $subcalls * $overheadTotal );
 700                                         $memchange -= ( $subcalls * $overheadMemory );
 701                                 }
 702                         }
 703
 704                         $period = array( 'start' => $entry[2], 'end' => $entry[5],
 705                                 'memory' => $memchange, 'subcalls' => $subcalls );
 706                         $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange, $subcalls, $period );
 707                 }
 708
 709                 $this->mCollated['-overhead-total']['count'] = $profileCount;
 710                 arsort( $this->mCollated, SORT_NUMERIC );
 711         }
 712
 713         /**
 714          * Returns a list of profiled functions.
 715          *
 716          * @return string
 717          */
 718         protected function getFunctionReport() {
 719                 $this->collateData();
 720
 721                 $width = 140;
 722                 $nameWidth = $width - 65;
 723                 $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d  (%13.3f -%13.3f) [%d]\n";
 724                 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
 725                 $prof = "\nProfiling data\n";
 726                 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
 727
 728                 $total = isset( $this->mCollated['-total'] )
 729                         ? $this->mCollated['-total']['real']
 730                         : 0;
 731
 732                 foreach ( $this->mCollated as $fname => $data ) {
 733                         $calls = $data['count'];
 734                         $percent = $total ? 100 * $data['real'] / $total : 0;
 735                         $memory = $data['memory'];
 736                         $prof .= sprintf( $format,
 737                                 substr( $fname, 0, $nameWidth ),
 738                                 $calls,
 739                                 (float)( $data['real'] * 1000 ),
 740                                 (float)( $data['real'] * 1000 ) / $calls,
 741                                 $percent,
 742                                 $memory,
 743                                 ( $data['min_real'] * 1000.0 ),
 744                                 ( $data['max_real'] * 1000.0 ),
 745                                 $data['overhead']
 746                         );
 747                 }
 748                 $prof .= "\nTotal: $total\n\n";
 749
 750                 return $prof;
 751         }
 752
 753         /**
 754          * @return array
 755          */
 756         public function getRawData() {
 757                 // This method is called before shutdown in the footer method on Skins.
 758                 // If some outer methods have not yet called wfProfileOut(), work around
 759                 // that by clearing anything in the work stack to just the "-total" entry.
 760                 // Collate after doing this so the results do not include profile errors.
 761                 if ( count( $this->mWorkStack ) > 1 ) {
 762                         $oldWorkStack = $this->mWorkStack;
 763                         $this->mWorkStack = array( $this->mWorkStack[0] ); // just the "-total" one
 764                 } else {
 765                         $oldWorkStack = null;
 766                 }
 767                 $this->collateData();
 768                 // If this trick is used, then the old work stack is swapped back afterwards
 769                 // and mCollateDone is reset to false. This means that logData() will still
 770                 // make use of all the method data since the missing wfProfileOut() calls
 771                 // should be made by the time it is called.
 772                 if ( $oldWorkStack ) {
 773                         $this->mWorkStack = $oldWorkStack;
 774                         $this->mCollateDone = false;
 775                 }
 776
 777                 $total = isset( $this->mCollated['-total'] )
 778                         ? $this->mCollated['-total']['real']
 779                         : 0;
 780
 781                 $profile = array();
 782                 foreach ( $this->mCollated as $fname => $data ) {
 783                         $periods = array();
 784                         foreach ( $data['periods'] as $period ) {
 785                                 $period['start'] *= 1000;
 786                                 $period['end'] *= 1000;
 787                                 $periods[] = $period;
 788                         }
 789                         $profile[] = array(
 790                                 'name' => $fname,
 791                                 'calls' => $data['count'],
 792                                 'elapsed' => $data['real'] * 1000,
 793                                 'percent' => $total ? 100 * $data['real'] / $total : 0,
 794                                 'memory' => $data['memory'],
 795                                 'min' => $data['min_real'] * 1000,
 796                                 'max' => $data['max_real'] * 1000,
 797                                 'overhead' => $data['overhead'],
 798                                 'periods' => $periods
 799                         );
 800                 }
 801
 802                 return $profile;
 803         }
 804
 805         /**
 806          * Dummy calls to wfProfileIn/wfProfileOut to calculate its overhead
 807          *
 808          * @param int $profileCount
 809          */
 810         protected static function calculateOverhead( $profileCount ) {
 811                 wfProfileIn( '-overhead-total' );
 812                 for ( $i = 0; $i < $profileCount; $i++ ) {
 813                         wfProfileIn( '-overhead-internal' );
 814                         wfProfileOut( '-overhead-internal' );
 815                 }
 816                 wfProfileOut( '-overhead-total' );
 817         }
 818
 819         /**
 820          * Counts the number of profiled function calls sitting under
 821          * the given point in the call graph. Not the most efficient algo.
 822          *
 823          * @param array $stack
 824          * @param int $start
 825          * @return int
 826          */
 827         protected function calltreeCount( $stack, $start ) {
 828                 $level = $stack[$start][1];
 829                 $count = 0;
 830                 for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
 831                         $count ++;
 832                 }
 833                 return $count;
 834         }
 835
 836         /**
 837          * Add an entry in the debug log file
 838          *
 839          * @param string $s String to output
 840          */
 841         protected function debug( $s ) {
 842                 if ( function_exists( 'wfDebug' ) ) {
 843                         wfDebug( $s );
 844                 }
 845         }
 846
 847         /**
 848          * Add an entry in the debug log group
 849          *
 850          * @param string $group Group to send the message to
 851          * @param string $s String to output
 852          */
 853         protected function debugGroup( $group, $s ) {
 854                 if ( function_exists( 'wfDebugLog' ) ) {
 855                         wfDebugLog( $group, $s );
 856                 }
 857         }
 858
 859         /**
 860          * Get the content type sent out to the client.
 861          * Used for profilers that output instead of store data.
 862          * @return string
 863          */
 864         protected function getContentType() {
 865                 foreach ( headers_list() as $header ) {
 866                         if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {
 867                                 return $m[1];
 868                         }
 869                 }
 870                 return null;
 871         }
 872 }