includes/Profiler.php

   1 <?php
   2 /**
   3  * This file is only included if profiling is enabled
   4  * @addtogroup Profiler
   5  */
   6
   7 /** backward compatibility */
   8 $wgProfiling = true;
   9
  10 /**
  11  * Begin profiling of a function
  12  * @param $functioname name of the function we will profile
  13  */
  14 function wfProfileIn( $functionname ) {
  15         global $wgProfiler;
  16         $wgProfiler->profileIn( $functionname );
  17 }
  18
  19 /**
  20  * Stop profiling of a function
  21  * @param $functioname name of the function we have profiled
  22  */
  23 function wfProfileOut( $functionname = 'missing' ) {
  24         global $wgProfiler;
  25         $wgProfiler->profileOut( $functionname );
  26 }
  27
  28 /**
  29  * Returns a profiling output to be stored in debug file
  30  *
  31  * @param float $start
  32  * @param float $elapsed time elapsed since the beginning of the request
  33  */
  34 function wfGetProfilingOutput( $start, $elapsed ) {
  35         global $wgProfiler;
  36         return $wgProfiler->getOutput( $start, $elapsed );
  37 }
  38
  39 /**
  40  * Close opened profiling sections
  41  */
  42 function wfProfileClose() {
  43         global $wgProfiler;
  44         $wgProfiler->close();
  45 }
  46
  47 if (!function_exists('memory_get_usage')) {
  48         # Old PHP or --enable-memory-limit not compiled in
  49         function memory_get_usage() {
  50                 return 0;
  51         }
  52 }
  53
  54 /**
  55  * @todo document
  56  * @addtogroup Profiler
  57  */
  58 class Profiler {
  59         var $mStack = array (), $mWorkStack = array (), $mCollated = array ();
  60         var $mCalls = array (), $mTotals = array ();
  61
  62         function __construct() {
  63                 // Push an entry for the pre-profile setup time onto the stack
  64                 global $wgRequestTime;
  65                 if ( !empty( $wgRequestTime ) ) {
  66                         $this->mWorkStack[] = array( '-total', 0, $wgRequestTime, 0 );
  67                         $this->mStack[] = array( '-setup', 1, $wgRequestTime, 0, microtime(true), 0 );
  68                 } else {
  69                         $this->profileIn( '-total' );
  70                 }
  71         }
  72
  73         /**
  74          * Called by wfProfieIn()
  75          * @param string $functionname
  76          */
  77         function profileIn( $functionname ) {
  78                 global $wgDebugFunctionEntry;
  79
  80                 if( $wgDebugFunctionEntry ){
  81                         $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Entering ' . $functionname . "\n" );
  82                 }
  83
  84                 $this->mWorkStack[] = array( $functionname, count( $this->mWorkStack ), $this->getTime(), memory_get_usage() );
  85         }
  86
  87         /**
  88          * Called by wfProfieOut()
  89          * @param string $functionname
  90          */
  91         function profileOut($functionname) {
  92                 global $wgDebugFunctionEntry;
  93
  94                 $memory = memory_get_usage();
  95                 $time = $this->getTime();
  96
  97                 if( $wgDebugFunctionEntry ){
  98                         $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . 'Exiting ' . $functionname . "\n" );
  99                 }
 100
 101                 $bit = array_pop($this->mWorkStack);
 102
 103                 if (!$bit) {
 104                         $this->debug("Profiling error, !\$bit: $functionname\n");
 105                 } else {
 106                         //if( $wgDebugProfiling ){
 107                                 if( $functionname == 'close' ){
 108                                         $message = "Profile section ended by close(): {$bit[0]}";
 109                                         $this->debug( "$message\n" );
 110                                         $this->mStack[] = array( $message, 0, '0 0', 0, '0 0', 0 );
 111                                 }
 112                                 elseif( $bit[0] != $functionname ){
 113                                         $message = "Profiling error: in({$bit[0]}), out($functionname)";
 114                                         $this->debug( "$message\n" );
 115                                         $this->mStack[] = array( $message, 0, '0 0', 0, '0 0', 0 );
 116                                 }
 117                         //}
 118                         $bit[] = $time;
 119                         $bit[] = $memory;
 120                         $this->mStack[] = $bit;
 121                 }
 122         }
 123
 124         /**
 125          * called by wfProfileClose()
 126          */
 127         function close() {
 128                 while( count( $this->mWorkStack ) ){
 129                         $this->profileOut( 'close' );
 130                 }
 131         }
 132
 133         /**
 134          * called by wfGetProfilingOutput()
 135          */
 136         function getOutput() {
 137                 global $wgDebugFunctionEntry, $wgProfileCallTree;
 138                 $wgDebugFunctionEntry = false;
 139
 140                 if( !count( $this->mStack ) && !count( $this->mCollated ) ){
 141                         return "No profiling output\n";
 142                 }
 143                 $this->close();
 144
 145                 if( $wgProfileCallTree ){
 146                         return $this->getCallTree();
 147                 } else {
 148                         return $this->getFunctionReport();
 149                 }
 150         }
 151
 152         /**
 153          * returns a tree of function call instead of a list of functions
 154          */
 155         function getCallTree() {
 156                 return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) ) );
 157         }
 158
 159         /**
 160          * Recursive function the format the current profiling array into a tree
 161          *
 162          * @param array $stack profiling array
 163          */
 164         function remapCallTree( $stack ) {
 165                 if( count( $stack ) < 2 ){
 166                         return $stack;
 167                 }
 168                 $outputs = array ();
 169                 for( $max = count( $stack ) - 1; $max > 0; ){
 170                         /* Find all items under this entry */
 171                         $level = $stack[$max][1];
 172                         $working = array ();
 173                         for( $i = $max -1; $i >= 0; $i-- ){
 174                                 if( $stack[$i][1] > $level ){
 175                                         $working[] = $stack[$i];
 176                                 } else {
 177                                         break;
 178                                 }
 179                         }
 180                         $working = $this->remapCallTree( array_reverse( $working ) );
 181                         $output = array();
 182                         foreach( $working as $item ){
 183                                 array_push( $output, $item );
 184                         }
 185                         array_unshift( $output, $stack[$max] );
 186                         $max = $i;
 187
 188                         array_unshift( $outputs, $output );
 189                 }
 190                 $final = array();
 191                 foreach( $outputs as $output ){
 192                         foreach( $output as $item ){
 193                                 $final[] = $item;
 194                         }
 195                 }
 196                 return $final;
 197         }
 198
 199         /**
 200          * Callback to get a formatted line for the call tree
 201          */
 202         function getCallTreeLine($entry) {
 203                 list( $fname, $level, $start, /* $x */, $end)  = $entry;
 204                 $delta = $end - $start;
 205                 $space = str_repeat(' ', $level);
 206
 207                 # The ugly double sprintf is to work around a PHP bug,
 208                 # which has been fixed in recent releases.
 209                 return sprintf( "%10s %s %s\n",
 210                         trim( sprintf( "%7.3f", $delta * 1000.0 ) ),
 211                         $space, $fname );
 212         }
 213
 214         function getTime() {
 215                 return microtime(true);
 216                 #return $this->getUserTime();
 217         }
 218
 219         function getUserTime() {
 220                 $ru = getrusage();
 221                 return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6;
 222         }
 223
 224         /**
 225          * Returns a list of profiled functions.
 226          * Also log it into the database if $wgProfileToDatabase is set to true.
 227          */
 228         function getFunctionReport() {
 229                 global $wgProfileToDatabase;
 230
 231                 $width = 140;
 232                 $nameWidth = $width - 65;
 233                 $format =      "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d  (%13.3f -%13.3f) [%d]\n";
 234                 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
 235                 $prof = "\nProfiling data\n";
 236                 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
 237                 $this->mCollated = array ();
 238                 $this->mCalls = array ();
 239                 $this->mMemory = array ();
 240
 241                 # Estimate profiling overhead
 242                 $profileCount = count($this->mStack);
 243                 wfProfileIn( '-overhead-total' );
 244                 for( $i = 0; $i < $profileCount; $i ++ ){
 245                         wfProfileIn( '-overhead-internal' );
 246                         wfProfileOut( '-overhead-internal' );
 247                 }
 248                 wfProfileOut( '-overhead-total' );
 249
 250                 # First, subtract the overhead!
 251                 foreach( $this->mStack as $entry ){
 252                         $fname = $entry[0];
 253                         $start = $entry[2];
 254                         $end = $entry[4];
 255                         $elapsed = $end - $start;
 256                         $memory = $entry[5] - $entry[3];
 257
 258                         if( $fname == '-overhead-total' ){
 259                                 $overheadTotal[] = $elapsed;
 260                                 $overheadMemory[] = $memory;
 261                         }
 262                         elseif( $fname == '-overhead-internal' ){
 263                                 $overheadInternal[] = $elapsed;
 264                         }
 265                 }
 266                 $overheadTotal = array_sum( $overheadTotal ) / count( $overheadInternal );
 267                 $overheadMemory = array_sum( $overheadMemory ) / count( $overheadInternal );
 268                 $overheadInternal = array_sum( $overheadInternal ) / count( $overheadInternal );
 269
 270                 # Collate
 271                 foreach( $this->mStack as $index => $entry ){
 272                         $fname = $entry[0];
 273                         $start = $entry[2];
 274                         $end = $entry[4];
 275                         $elapsed = $end - $start;
 276
 277                         $memory = $entry[5] - $entry[3];
 278                         $subcalls = $this->calltreeCount( $this->mStack, $index );
 279
 280                         if( !preg_match( '/^-overhead/', $fname ) ){
 281                                 # Adjust for profiling overhead (except special values with elapsed=0
 282                                 if( $elapsed ) {
 283                                         $elapsed -= $overheadInternal;
 284                                         $elapsed -= ($subcalls * $overheadTotal);
 285                                         $memory -= ($subcalls * $overheadMemory);
 286                                 }
 287                         }
 288
 289                         if( !array_key_exists( $fname, $this->mCollated ) ){
 290                                 $this->mCollated[$fname] = 0;
 291                                 $this->mCalls[$fname] = 0;
 292                                 $this->mMemory[$fname] = 0;
 293                                 $this->mMin[$fname] = 1 << 24;
 294                                 $this->mMax[$fname] = 0;
 295                                 $this->mOverhead[$fname] = 0;
 296                         }
 297
 298                         $this->mCollated[$fname] += $elapsed;
 299                         $this->mCalls[$fname]++;
 300                         $this->mMemory[$fname] += $memory;
 301                         $this->mMin[$fname] = min($this->mMin[$fname], $elapsed);
 302                         $this->mMax[$fname] = max($this->mMax[$fname], $elapsed);
 303                         $this->mOverhead[$fname] += $subcalls;
 304                 }
 305
 306                 $total = @$this->mCollated['-total'];
 307                 $this->mCalls['-overhead-total'] = $profileCount;
 308
 309                 # Output
 310                 arsort( $this->mCollated, SORT_NUMERIC );
 311                 foreach( $this->mCollated as $fname => $elapsed ){
 312                         $calls = $this->mCalls[$fname];
 313                         $percent = $total ? 100. * $elapsed / $total : 0;
 314                         $memory = $this->mMemory[$fname];
 315                         $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]);
 316
 317                         if( $wgProfileToDatabase ){
 318                                 self::logToDB($fname, (float) ($elapsed * 1000), $calls, (float) ($memory) );
 319                         }
 320                 }
 321                 $prof .= "\nTotal: $total\n\n";
 322
 323                 return $prof;
 324         }
 325
 326         /**
 327          * Counts the number of profiled function calls sitting under
 328          * the given point in the call graph. Not the most efficient algo.
 329          *
 330          * @param $stack Array:
 331          * @param $start Integer:
 332          * @return Integer
 333          * @private
 334          */
 335         function calltreeCount($stack, $start) {
 336                 $level = $stack[$start][1];
 337                 $count = 0;
 338                 for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) {
 339                         $count ++;
 340                 }
 341                 return $count;
 342         }
 343
 344         /**
 345          * Log a function into the database.
 346          *
 347          * @param string $name function name
 348          * @param float $timeSum
 349          * @param int $eventCount number of times that function was called
 350          */
 351         static function logToDB( $name, $timeSum, $eventCount, $memorySum ){
 352                 # Do not log anything if database is readonly (bug 5375)
 353                 if( wfReadOnly() ) { return; }
 354
 355                 # Warning: $wguname is a live patch, it should be moved to Setup.php
 356                 global $wguname, $wgProfilePerHost;
 357
 358                 $dbw = wfGetDB( DB_MASTER );
 359                 if( !is_object( $dbw ) )
 360                         return false;
 361                 $errorState = $dbw->ignoreErrors( true );
 362
 363                 $name = substr($name, 0, 255);
 364
 365                 if( $wgProfilePerHost ){
 366                         $pfhost = $wguname['nodename'];
 367                 } else {
 368                         $pfhost = '';
 369                 }
 370
 371                 // Kludge
 372                 $timeSum = ($timeSum >= 0) ? $timeSum : 0;
 373                 $memorySum = ($memorySum >= 0) ? $memorySum : 0;
 374
 375                 $dbw->update( 'profiling',
 376                         array(
 377                                 "pf_count=pf_count+{$eventCount}",
 378                                 "pf_time=pf_time+{$timeSum}",
 379                                 "pf_memory=pf_memory+{$memorySum}",
 380                         ),
 381                         array(
 382                                 'pf_name' => $name,
 383                                 'pf_server' => $pfhost,
 384                         ),
 385                         __METHOD__ );
 386
 387
 388                 $rc = $dbw->affectedRows();
 389                 if ($rc == 0) {
 390                         $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount,
 391                                 'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ),
 392                                 __METHOD__, array ('IGNORE'));
 393                 }
 394                 // When we upgrade to mysql 4.1, the insert+update
 395                 // can be merged into just a insert with this construct added:
 396                 //     "ON DUPLICATE KEY UPDATE ".
 397                 //     "pf_count=pf_count + VALUES(pf_count), ".
 398                 //     "pf_time=pf_time + VALUES(pf_time)";
 399                 $dbw->ignoreErrors( $errorState );
 400         }
 401
 402         /**
 403          * Get the function name of the current profiling section
 404          */
 405         function getCurrentSection() {
 406                 $elt = end( $this->mWorkStack );
 407                 return $elt[0];
 408         }
 409
 410         /**
 411          * Get function caller
 412          * @param int $level
 413          */
 414         static function getCaller( $level ) {
 415                 $backtrace = wfDebugBacktrace();
 416                 if ( isset( $backtrace[$level] ) ) {
 417                         if ( isset( $backtrace[$level]['class'] ) ) {
 418                                 $caller = $backtrace[$level]['class'] . '::' . $backtrace[$level]['function'];
 419                         } else {
 420                                 $caller = $backtrace[$level]['function'];
 421                         }
 422                 } else {
 423                         $caller = 'unknown';
 424                 }
 425                 return $caller;
 426         }
 427
 428         /**
 429          * Add an entry in the debug log file
 430          * @param string $s string to output
 431          */
 432         function debug( $s ) {
 433                 if( function_exists( 'wfDebug' ) ) {
 434                         wfDebug( $s );
 435                 }
 436         }
 437 }