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 $functionname String: name of the function we will profile
  32  */
  33 function wfProfileIn( $functionname ) {
  34         global $wgProfiler;
  35         if ( $wgProfiler instanceof Profiler || isset( $wgProfiler['class'] ) ) {
  36                 Profiler::instance()->profileIn( $functionname );
  37         }
  38 }
  39
  40 /**
  41  * Stop profiling of a function
  42  * @param $functionname String: name of the function we have profiled
  43  */
  44 function wfProfileOut( $functionname = 'missing' ) {
  45         global $wgProfiler;
  46         if ( $wgProfiler instanceof Profiler || isset( $wgProfiler['class'] ) ) {
  47                 Profiler::instance()->profileOut( $functionname );
  48         }
  49 }
  50
  51 /**
  52  * @ingroup Profiler
  53  * @todo document
  54  */
  55 class Profiler {
  56         protected $mStack = array(), $mWorkStack = array (), $mCollated = array (),
  57                 $mCalls = array (), $mTotals = array ();
  58         protected $mTimeMetric = 'wall';
  59         protected $mProfileID = false, $mCollateDone = false, $mTemplated = false;
  60         private static $__instance = null;
  61
  62         function __construct( $params ) {
  63                 if ( isset( $params['timeMetric'] ) ) {
  64                         $this->mTimeMetric = $params['timeMetric'];
  65                 }
  66                 if ( isset( $params['profileID'] ) ) {
  67                         $this->mProfileID = $params['profileID'];
  68                 }
  69
  70                 $this->addInitialStack();
  71         }
  72
  73         /**
  74          * Singleton
  75          * @return Profiler
  76          */
  77         public static function instance() {
  78                 if( is_null( self::$__instance ) ) {
  79                         global $wgProfiler;
  80                         if( is_array( $wgProfiler ) ) {
  81                                 if( !isset( $wgProfiler['class'] ) ) {
  82                                         wfDebug( __METHOD__ . " called without \$wgProfiler['class']"
  83                                                 . " set, falling back to ProfilerStub for safety\n" );
  84                                         $class = 'ProfilerStub';
  85                                 } else {
  86                                         $class = $wgProfiler['class'];
  87                                 }
  88                                 self::$__instance = new $class( $wgProfiler );
  89                         } elseif( $wgProfiler instanceof Profiler ) {
  90                                 self::$__instance = $wgProfiler; // back-compat
  91                         } else {
  92                                 wfDebug( __METHOD__ . ' called with bogus $wgProfiler setting,'
  93                                                 . " falling back to ProfilerStub for safety\n" );
  94                                 self::$__instance = new ProfilerStub( $wgProfiler );
  95                         }
  96                 }
  97                 return self::$__instance;
  98         }
  99
 100         /**
 101          * Set the profiler to a specific profiler instance. Mostly for dumpHTML
 102          * @param $p Profiler object
 103          */
 104         public static function setInstance( Profiler $p ) {
 105                 self::$__instance = $p;
 106         }
 107
 108         /**
 109          * Return whether this a stub profiler
 110          *
 111          * @return Boolean
 112          */
 113         public function isStub() {
 114                 return false;
 115         }
 116
 117         public function setProfileID( $id ) {
 118                 $this->mProfileID = $id;
 119         }
 120
 121         public function getProfileID() {
 122                 if ( $this->mProfileID === false ) {
 123                         return wfWikiID();
 124                 } else {
 125                         return $this->mProfileID;
 126                 }
 127         }
 128
 129         /**
 130          * Add the inital item in the stack.
 131          */
 132         protected function addInitialStack() {
 133                 // Push an entry for the pre-profile setup time onto the stack
 134                 $initial = $this->getInitialTime();
 135                 if ( $initial !== null ) {
 136                         $this->mWorkStack[] = array( '-total', 0, $initial, 0 );
 137                         $this->mStack[] = array( '-setup', 1, $initial, 0, $this->getTime(), 0 );
 138                 } else {
 139                         $this->profileIn( '-total' );
 140                 }
 141         }
 142
 143         /**
 144          * Called by wfProfieIn()
 145          *
 146          * @param $functionname String
 147          */
 148         public function profileIn( $functionname ) {
 149                 global $wgDebugFunctionEntry;
 150                 if( $wgDebugFunctionEntry ){
 151                         $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Entering ' . $functionname . "\n" );
 152                 }
 153
 154                 $this->mWorkStack[] = array( $functionname, count( $this->mWorkStack ), $this->getTime(), memory_get_usage() );
 155         }
 156
 157         /**
 158          * Called by wfProfieOut()
 159          *
 160          * @param $functionname String
 161          */
 162         public function profileOut( $functionname ) {
 163                 global $wgDebugFunctionEntry;
 164                 $memory = memory_get_usage();
 165                 $time = $this->getTime();
 166
 167                 if( $wgDebugFunctionEntry ){
 168                         $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . 'Exiting ' . $functionname . "\n" );
 169                 }
 170
 171                 $bit = array_pop($this->mWorkStack);
 172
 173                 if (!$bit) {
 174                         $this->debug("Profiling error, !\$bit: $functionname\n");
 175                 } else {
 176                         //if( $wgDebugProfiling ){
 177                                 if( $functionname == 'close' ){
 178                                         $message = "Profile section ended by close(): {$bit[0]}";
 179                                         $this->debug( "$message\n" );
 180                                         $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 );
 181                                 }
 182                                 elseif( $bit[0] != $functionname ){
 183                                         $message = "Profiling error: in({$bit[0]}), out($functionname)";
 184                                         $this->debug( "$message\n" );
 185                                         $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 );
 186                                 }
 187                         //}
 188                         $bit[] = $time;
 189                         $bit[] = $memory;
 190                         $this->mStack[] = $bit;
 191                 }
 192         }
 193
 194         /**
 195          * Close opened profiling sections
 196          */
 197         public function close() {
 198                 while( count( $this->mWorkStack ) ){
 199                         $this->profileOut( 'close' );
 200                 }
 201         }
 202
 203         /**
 204          * Mark this call as templated or not
 205          *
 206          * @param $t Boolean
 207          */
 208         function setTemplated( $t ) {
 209                 $this->mTemplated = $t;
 210         }
 211
 212         /**
 213          * Returns a profiling output to be stored in debug file
 214          *
 215          * @return String
 216          */
 217         public function getOutput() {
 218                 global $wgDebugFunctionEntry, $wgProfileCallTree;
 219                 $wgDebugFunctionEntry = false;
 220
 221                 if( !count( $this->mStack ) && !count( $this->mCollated ) ){
 222                         return "No profiling output\n";
 223                 }
 224
 225                 if( $wgProfileCallTree ) {
 226                         return $this->getCallTree();
 227                 } else {
 228                         return $this->getFunctionReport();
 229                 }
 230         }
 231
 232         /**
 233          * Returns a tree of function call instead of a list of functions
 234          * @return string
 235          */
 236         function getCallTree() {
 237                 return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) ) );
 238         }
 239
 240         /**
 241          * Recursive function the format the current profiling array into a tree
 242          *
 243          * @param $stack array profiling array
 244          * @return array
 245          */
 246         function remapCallTree( $stack ) {
 247                 if( count( $stack ) < 2 ){
 248                         return $stack;
 249                 }
 250                 $outputs = array ();
 251                 for( $max = count( $stack ) - 1; $max > 0; ){
 252                         /* Find all items under this entry */
 253                         $level = $stack[$max][1];
 254                         $working = array ();
 255                         for( $i = $max -1; $i >= 0; $i-- ){
 256                                 if( $stack[$i][1] > $level ){
 257                                         $working[] = $stack[$i];
 258                                 } else {
 259                                         break;
 260                                 }
 261                         }
 262                         $working = $this->remapCallTree( array_reverse( $working ) );
 263                         $output = array();
 264                         foreach( $working as $item ){
 265                                 array_push( $output, $item );
 266                         }
 267                         array_unshift( $output, $stack[$max] );
 268                         $max = $i;
 269
 270                         array_unshift( $outputs, $output );
 271                 }
 272                 $final = array();
 273                 foreach( $outputs as $output ){
 274                         foreach( $output as $item ){
 275                                 $final[] = $item;
 276                         }
 277                 }
 278                 return $final;
 279         }
 280
 281         /**
 282          * Callback to get a formatted line for the call tree
 283          * @return string
 284          */
 285         function getCallTreeLine( $entry ) {
 286                 list( $fname, $level, $start, /* $x */, $end)  = $entry;
 287                 $delta = $end - $start;
 288                 $space = str_repeat(' ', $level);
 289                 # The ugly double sprintf is to work around a PHP bug,
 290                 # which has been fixed in recent releases.
 291                 return sprintf( "%10s %s %s\n", trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
 292         }
 293
 294         /**
 295          * Get the initial time of the request, based either on $wgRequestTime or
 296          * $wgRUstart. Will return null if not able to find data.
 297          *
 298          * @param $metric string|false: metric to use, with the following possibilities:
 299          *   - user: User CPU time (without system calls)
 300          *   - cpu: Total CPU time (user and system calls)
 301          *   - wall (or any other string): elapsed time
 302          *   - false (default): will fall back to default metric
 303          * @return float|null
 304          */
 305         function getTime( $metric = false ) {
 306                 if ( $metric === false ) {
 307                         $metric = $this->mTimeMetric;
 308                 }
 309
 310                 if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) {
 311                         if ( !function_exists( 'getrusage' ) ) {
 312                                 return 0;
 313                         }
 314                         $ru = getrusage();
 315                         $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
 316                         if ( $metric === 'cpu' ) {
 317                                 # This is the time of system calls, added to the user time
 318                                 # it gives the total CPU time
 319                                 $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
 320                         }
 321                         return $time;
 322                 } else {
 323                         return microtime( true );
 324                 }
 325         }
 326
 327         /**
 328          * Get the initial time of the request, based either on $wgRequestTime or
 329          * $wgRUstart. Will return null if not able to find data.
 330          *
 331          * @param $metric string|false: metric to use, with the following possibilities:
 332          *   - user: User CPU time (without system calls)
 333          *   - cpu: Total CPU time (user and system calls)
 334          *   - wall (or any other string): elapsed time
 335          *   - false (default): will fall back to default metric
 336          * @return float|null
 337          */
 338         protected function getInitialTime( $metric = false ) {
 339                 global $wgRequestTime, $wgRUstart;
 340
 341                 if ( $metric === false ) {
 342                         $metric = $this->mTimeMetric;
 343                 }
 344
 345                 if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) {
 346                         if ( !count( $wgRUstart ) ) {
 347                                 return null;
 348                         }
 349
 350                         $time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
 351                         if ( $metric === 'cpu' ) {
 352                                 # This is the time of system calls, added to the user time
 353                                 # it gives the total CPU time
 354                                 $time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
 355                         }
 356                         return $time;
 357                 } else {
 358                         if ( empty( $wgRequestTime ) ) {
 359                                 return null;
 360                         } else {
 361                                 return $wgRequestTime;
 362                         }
 363                 }
 364         }
 365
 366         protected function collateData() {
 367                 if ( $this->mCollateDone ) {
 368                         return;
 369                 }
 370                 $this->mCollateDone = true;
 371
 372                 $this->close();
 373
 374                 $this->mCollated = array();
 375                 $this->mCalls = array();
 376                 $this->mMemory = array();
 377
 378                 # Estimate profiling overhead
 379                 $profileCount = count($this->mStack);
 380                 self::calculateOverhead( $profileCount );
 381
 382                 # First, subtract the overhead!
 383                 $overheadTotal = $overheadMemory = $overheadInternal = array();
 384                 foreach( $this->mStack as $entry ){
 385                         $fname = $entry[0];
 386                         $start = $entry[2];
 387                         $end = $entry[4];
 388                         $elapsed = $end - $start;
 389                         $memory = $entry[5] - $entry[3];
 390
 391                         if( $fname == '-overhead-total' ){
 392                                 $overheadTotal[] = $elapsed;
 393                                 $overheadMemory[] = $memory;
 394                         }
 395                         elseif( $fname == '-overhead-internal' ){
 396                                 $overheadInternal[] = $elapsed;
 397                         }
 398                 }
 399                 $overheadTotal = $overheadTotal ? array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
 400                 $overheadMemory = $overheadMemory ? array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
 401                 $overheadInternal = $overheadInternal ? array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
 402
 403                 # Collate
 404                 foreach( $this->mStack as $index => $entry ){
 405                         $fname = $entry[0];
 406                         $start = $entry[2];
 407                         $end = $entry[4];
 408                         $elapsed = $end - $start;
 409
 410                         $memory = $entry[5] - $entry[3];
 411                         $subcalls = $this->calltreeCount( $this->mStack, $index );
 412
 413                         if( !preg_match( '/^-overhead/', $fname ) ){
 414                                 # Adjust for profiling overhead (except special values with elapsed=0
 415                                 if( $elapsed ) {
 416                                         $elapsed -= $overheadInternal;
 417                                         $elapsed -= ($subcalls * $overheadTotal);
 418                                         $memory -= ($subcalls * $overheadMemory);
 419                                 }
 420                         }
 421
 422                         if( !array_key_exists( $fname, $this->mCollated ) ){
 423                                 $this->mCollated[$fname] = 0;
 424                                 $this->mCalls[$fname] = 0;
 425                                 $this->mMemory[$fname] = 0;
 426                                 $this->mMin[$fname] = 1 << 24;
 427                                 $this->mMax[$fname] = 0;
 428                                 $this->mOverhead[$fname] = 0;
 429                         }
 430
 431                         $this->mCollated[$fname] += $elapsed;
 432                         $this->mCalls[$fname]++;
 433                         $this->mMemory[$fname] += $memory;
 434                         $this->mMin[$fname] = min($this->mMin[$fname], $elapsed);
 435                         $this->mMax[$fname] = max($this->mMax[$fname], $elapsed);
 436                         $this->mOverhead[$fname] += $subcalls;
 437                 }
 438
 439                 $this->mCalls['-overhead-total'] = $profileCount;
 440                 arsort( $this->mCollated, SORT_NUMERIC );
 441         }
 442
 443         /**
 444          * Returns a list of profiled functions.
 445          *
 446          * @return string
 447          */
 448         function getFunctionReport() {
 449                 $this->collateData();
 450
 451                 $width = 140;
 452                 $nameWidth = $width - 65;
 453                 $format =      "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d  (%13.3f -%13.3f) [%d]\n";
 454                 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
 455                 $prof = "\nProfiling data\n";
 456                 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
 457
 458                 $total = isset( $this->mCollated['-total'] ) ? $this->mCollated['-total'] : 0;
 459
 460                 foreach( $this->mCollated as $fname => $elapsed ){
 461                         $calls = $this->mCalls[$fname];
 462                         $percent = $total ? 100. * $elapsed / $total : 0;
 463                         $memory = $this->mMemory[$fname];
 464                         $prof .= sprintf($format, substr($fname, 0, $nameWidth), $calls, (float) ($elapsed * 1000), (float) ($elapsed * 1000) / $calls, $percent, $memory, ($this->mMin[$fname] * 1000.0), ($this->mMax[$fname] * 1000.0), $this->mOverhead[$fname]);
 465                 }
 466                 $prof .= "\nTotal: $total\n\n";
 467
 468                 return $prof;
 469         }
 470
 471         /**
 472          * Dummy calls to wfProfileIn/wfProfileOut to calculate its overhead
 473          */
 474         protected static function calculateOverhead( $profileCount ) {
 475                 wfProfileIn( '-overhead-total' );
 476                 for( $i = 0; $i < $profileCount; $i++ ){
 477                         wfProfileIn( '-overhead-internal' );
 478                         wfProfileOut( '-overhead-internal' );
 479                 }
 480                 wfProfileOut( '-overhead-total' );
 481         }
 482
 483         /**
 484          * Counts the number of profiled function calls sitting under
 485          * the given point in the call graph. Not the most efficient algo.
 486          *
 487          * @param $stack Array:
 488          * @param $start Integer:
 489          * @return Integer
 490          * @private
 491          */
 492         function calltreeCount($stack, $start) {
 493                 $level = $stack[$start][1];
 494                 $count = 0;
 495                 for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) {
 496                         $count ++;
 497                 }
 498                 return $count;
 499         }
 500
 501         /**
 502          * Log the whole profiling data into the database.
 503          */
 504         public function logData(){
 505                 global $wgProfilePerHost, $wgProfileToDatabase;
 506
 507                 # Do not log anything if database is readonly (bug 5375)
 508                 if( wfReadOnly() || !$wgProfileToDatabase ) {
 509                         return;
 510                 }
 511
 512                 $dbw = wfGetDB( DB_MASTER );
 513                 if( !is_object( $dbw ) ) {
 514                         return;
 515                 }
 516
 517                 $errorState = $dbw->ignoreErrors( true );
 518
 519                 if( $wgProfilePerHost ){
 520                         $pfhost = wfHostname();
 521                 } else {
 522                         $pfhost = '';
 523                 }
 524
 525                 $this->collateData();
 526
 527                 foreach( $this->mCollated as $name => $elapsed ){
 528                         $eventCount = $this->mCalls[$name];
 529                         $timeSum = (float) ($elapsed * 1000);
 530                         $memorySum = (float)$this->mMemory[$name];
 531                         $name = substr($name, 0, 255);
 532
 533                         // Kludge
 534                         $timeSum = ($timeSum >= 0) ? $timeSum : 0;
 535                         $memorySum = ($memorySum >= 0) ? $memorySum : 0;
 536
 537                         $dbw->update( 'profiling',
 538                                 array(
 539                                         "pf_count=pf_count+{$eventCount}",
 540                                         "pf_time=pf_time+{$timeSum}",
 541                                         "pf_memory=pf_memory+{$memorySum}",
 542                                 ),
 543                                 array(
 544                                         'pf_name' => $name,
 545                                         'pf_server' => $pfhost,
 546                                 ),
 547                                 __METHOD__ );
 548
 549                         $rc = $dbw->affectedRows();
 550                         if ( $rc == 0 ) {
 551                                 $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount,
 552                                         'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ),
 553                                         __METHOD__, array ('IGNORE'));
 554                         }
 555                         // When we upgrade to mysql 4.1, the insert+update
 556                         // can be merged into just a insert with this construct added:
 557                         //     "ON DUPLICATE KEY UPDATE ".
 558                         //     "pf_count=pf_count + VALUES(pf_count), ".
 559                         //     "pf_time=pf_time + VALUES(pf_time)";
 560                 }
 561
 562                 $dbw->ignoreErrors( $errorState );
 563         }
 564
 565         /**
 566          * Get the function name of the current profiling section
 567          * @return
 568          */
 569         function getCurrentSection() {
 570                 $elt = end( $this->mWorkStack );
 571                 return $elt[0];
 572         }
 573
 574         /**
 575          * Add an entry in the debug log file
 576          *
 577          * @param $s String to output
 578          */
 579         function debug( $s ) {
 580                 if( defined( 'MW_COMPILED' ) || function_exists( 'wfDebug' ) ) {
 581                         wfDebug( $s );
 582                 }
 583         }
 584 }