includes/profiler/Profiler.php

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