includes/Profiling.php

   1 <?php
   2 /**
   3  * This file is only included if profiling is enabled
   4  * @package MediaWiki
   5  */
   6
   7 /**
   8  * @param $functioname name of the function we will profile
   9  */
  10 function wfProfileIn( $functionname ) {
  11         global $wgProfiler;
  12         $wgProfiler->profileIn( $functionname );
  13 }
  14
  15 /**
  16  * @param $functioname name of the function we have profiled
  17  */
  18 function wfProfileOut( $functionname = 'missing' ) {
  19         global $wgProfiler;
  20         $wgProfiler->profileOut( $functionname );
  21 }
  22
  23 function wfGetProfilingOutput( $start, $elapsed ) {
  24         global $wgProfiler;
  25         return $wgProfiler->getOutput( $start, $elapsed );
  26 }
  27
  28 function wfProfileClose() {
  29         global $wgProfiler;
  30         $wgProfiler->close();
  31 }
  32
  33 if( !function_exists( 'memory_get_usage' ) ) {
  34         # Old PHP or --enable-memory-limit not compiled in
  35         function memory_get_usage() {
  36                 return 0;
  37         }
  38 }
  39
  40 /**
  41  * @todo document
  42  * @package MediaWiki
  43  */
  44 class Profiler
  45 {
  46         var $mStack = array(), $mWorkStack = array(), $mCollated = array();
  47         var $mCalls = array(), $mTotals = array();
  48         /*
  49         function Profiler()
  50         {
  51                 $this->mProfileStack = array();
  52                 $this->mWorkStack = array();
  53                 $this->mCollated = array();
  54         }
  55         */
  56
  57         function profileIn( $functionname ) {
  58                 global $wgDebugFunctionEntry;
  59                 if ( $wgDebugFunctionEntry && function_exists( 'wfDebug' ) ) {
  60                         wfDebug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Entering '.$functionname."\n" );
  61                 }
  62                 $this->mWorkStack[] = array($functionname, count( $this->mWorkStack ), microtime(), memory_get_usage() );
  63         }
  64
  65         function profileOut( $functionname ) {
  66                 $memory = memory_get_usage();
  67                 $time = microtime();
  68                 global $wgDebugProfiling, $wgDebugFunctionEntry;
  69
  70                 if ( $wgDebugFunctionEntry && function_exists( 'wfDebug' ) ) {
  71                         wfDebug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Exiting '.$functionname."\n" );
  72                 }
  73
  74                 $bit = array_pop( $this->mWorkStack );
  75
  76                 if ( !$bit ) {
  77                         wfDebug( "Profiling error, !\$bit: $functionname\n" );
  78                 } else {
  79                         if ( $wgDebugProfiling ) {
  80                                 if ( $functionname == 'close' ) {
  81                                         wfDebug( "Profile section ended by close(): {$bit[0]}\n" );
  82                                 } elseif ( $bit[0] != $functionname ) {
  83                                         wfDebug( "Profiling error: in({$bit[0]}), out($functionname)\n" );
  84                                 }
  85                         }
  86                         $bit[] = $time;
  87                         $bit[] = $memory;
  88                         $this->mStack[] = $bit;
  89                 }
  90         }
  91
  92         function close() {
  93                 while ( count( $this->mWorkStack ) ) {
  94                         $this->profileOut( 'close' );
  95                 }
  96         }
  97
  98         function getOutput() {
  99                 global $wgDebugFunctionEntry;
 100                 $wgDebugFunctionEntry = false;
 101
 102                 if( !count( $this->mStack ) ) {
 103                         return "No profiling output\n";
 104                 }
 105                 $this->close();
 106
 107                 global $wgProfileCallTree;
 108                 if( $wgProfileCallTree ) {
 109                         return $this->getCallTree();
 110                 } else {
 111                         return $this->getFunctionReport();
 112                 }
 113         }
 114
 115         function getCallTree( $start = 0 ) {
 116                 return implode( '',
 117                         array_map(
 118                                 array( &$this, 'getCallTreeLine' ),
 119                                 $this->remapCallTree( $this->mStack ) ) );
 120         }
 121
 122         function remapCallTree( $stack ) {
 123                 if( count( $stack ) < 2 ) {
 124                         return $stack;
 125                 }
 126                 $outputs = array();
 127                 for( $max = count( $stack ) - 1; $max > 0; ) {
 128                         /* Find all items under this entry */
 129                         $level = $stack[$max][1];
 130                         $working = array();
 131                         for( $i = $max - 1; $i >= 0; $i-- ) {
 132                                 if( $stack[$i][1] > $level ) {
 133                                         $working[] = $stack[$i];
 134                                 } else {
 135                                         break;
 136                                 }
 137                         }
 138                         $working = $this->remapCallTree( array_reverse( $working ) );
 139                         $output = array();
 140                         foreach( $working as $item ) {
 141                                 array_push( $output, $item );
 142                         }
 143                         array_unshift( $output, $stack[$max] );
 144                         $max = $i;
 145
 146                         array_unshift( $outputs, $output );
 147                 }
 148                 $final = array();
 149                 foreach( $outputs as $output ) {
 150                         foreach( $output as $item ) {
 151                                 $final[] = $item;
 152                         }
 153                 }
 154                 return $final;
 155         }
 156
 157         function getCallTreeLine( $entry ) {
 158                 list( $fname, $level, $start, $x, $end ) = $entry;
 159                 $delta = $this->microDelta( $start, $end );
 160                 $space = str_repeat( ' ', $level );
 161
 162                 # The ugly double sprintf is to work around a PHP bug,
 163                 # which has been fixed in recent releases.
 164                 return sprintf( "%10s %s %s\n",
 165                         trim( sprintf( "%7.3f", $delta * 1000.0 ) ),
 166                         $space, $fname );
 167         }
 168
 169         function micro2Float( $micro ) {
 170                 list( $whole, $fractional ) = explode( ' ', $micro );
 171                 return (float)$whole + (float)$fractional;
 172         }
 173
 174         function microDelta( $start, $end ) {
 175                 return $this->micro2Float( $end ) -
 176                        $this->micro2Float( $start );
 177         }
 178
 179         function getFunctionReport() {
 180                 $width = 125;
 181                 $format = "%-" . ($width - 34) . "s %6d %6.3f %6.3f %7.3f%% %6d (%6.3f-%6.3f) [%d]\n";
 182                 $titleFormat = "%-" . ($width - 34) . "s %9s %9s %9s %9s %6s\n";
 183                 $prof = "\nProfiling data\n";
 184                 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
 185                 $this->mCollated = array();
 186                 $this->mCalls = array();
 187                 $this->mMemory = array();
 188
 189                 # Estimate profiling overhead
 190                 $profileCount = count( $this->mStack );
 191                 wfProfileIn( '-overhead-total' );
 192                 for ($i=0; $i<$profileCount ; $i++) {
 193                         wfProfileIn( '-overhead-internal' );
 194                         wfProfileOut( '-overhead-internal' );
 195                 }
 196                 wfProfileOut( '-overhead-total' );
 197
 198                 # First, subtract the overhead!
 199                 foreach( $this->mStack as $entry ) {
 200                         $fname = $entry[0];
 201                         $thislevel = $entry[1];
 202                         $start = explode( ' ', $entry[2]);
 203                         $start = (float)$start[0] + (float)$start[1];
 204                         $end = explode( ' ', $entry[4]);
 205                         $end = (float)$end[0] + (float)$end[1];
 206                         $elapsed = $end - $start;
 207                         $memory = $entry[5] - $entry[3];
 208
 209                         if( $fname == '-overhead-total' ) {
 210                                 $overheadTotal[] = $elapsed;
 211                                 $overheadMemory[] = $memory;
 212                         } elseif( $fname == '-overhead-internal' ) {
 213                                 $overheadInternal[] = $elapsed;
 214                         }
 215                 }
 216                 $overheadTotal = array_sum( $overheadTotal ) / count( $overheadInternal );
 217                 $overheadMemory = array_sum( $overheadMemory ) / count( $overheadInternal );
 218                 $overheadInternal = array_sum( $overheadInternal ) / count( $overheadInternal );
 219
 220                 # Collate
 221                 foreach ( $this->mStack as $index => $entry ) {
 222                         $fname = $entry[0];
 223                         $thislevel = $entry[1];
 224                         $start = explode( ' ', $entry[2]);
 225                         $start = (float)$start[0] + (float)$start[1];
 226                         $end = explode( ' ', $entry[4]);
 227                         $end = (float)$end[0] + (float)$end[1];
 228                         $elapsed = $end - $start;
 229
 230                         $memory = $entry[5] - $entry[3];
 231                         $subcalls = $this->calltreeCount( $this->mStack, $index );
 232
 233                         if( !preg_match( '/^-overhead/', $fname ) ) {
 234                                 # Adjust for profiling overhead
 235                                 $elapsed -= $overheadInternal;
 236                                 $elapsed -= ($subcalls * $overheadTotal);
 237                                 $memory -= ($subcalls * $overheadMemory);
 238                         }
 239
 240                         if ( !array_key_exists( $fname, $this->mCollated ) ) {
 241                                 $this->mCollated[$fname] = 0;
 242                                 $this->mCalls[$fname] = 0;
 243                                 $this->mMemory[$fname] = 0;
 244                                 $this->mMin[$fname] = 1 << 24;
 245                                 $this->mMax[$fname] = 0;
 246                                 $this->mOverhead[$fname] = 0;
 247                         }
 248
 249                         $this->mCollated[$fname] += $elapsed;
 250                         $this->mCalls[$fname] ++;
 251                         $this->mMemory[$fname] += $memory;
 252                         $this->mMin[$fname] = min( $this->mMin[$fname], $elapsed );
 253                         $this->mMax[$fname] = max( $this->mMax[$fname], $elapsed );
 254                         $this->mOverhead[$fname] += $subcalls;
 255                 }
 256
 257                 $total = @$this->mCollated['-total'];
 258                 $this->mCalls['-overhead-total'] = $profileCount;
 259
 260                 # Output
 261                 asort( $this->mCollated, SORT_NUMERIC );
 262                 foreach ( $this->mCollated as $fname => $elapsed ) {
 263                         $calls = $this->mCalls[$fname];
 264                         $percent = $total ? 100. * $elapsed / $total : 0;
 265                         $memory = $this->mMemory[$fname];
 266                         $prof .= sprintf( $format, $fname, $calls, (float)($elapsed * 1000),
 267                                         (float)($elapsed * 1000) / $calls, $percent, $memory,
 268                                         ($this->mMin[$fname] * 1000.0),
 269                                         ($this->mMax[$fname] * 1000.0),
 270                                         $this->mOverhead[$fname] );
 271
 272                         global $wgProfileToDatabase;
 273                         if( $wgProfileToDatabase ) {
 274                                 Profiler::logToDB( $fname, (float)($elapsed * 1000), $calls );
 275                         }
 276                 }
 277                 $prof .= "\nTotal: $total\n\n";
 278
 279                 return $prof;
 280         }
 281
 282         /**
 283          * Counts the number of profiled function calls sitting under
 284          * the given point in the call graph. Not the most efficient algo.
 285          *
 286          * @param array $stack
 287          * @param int $start
 288          * @return int
 289          * @access private
 290          */
 291         function calltreeCount( &$stack, $start ) {
 292                 $level = $stack[$start][1];
 293                 $count = 0;
 294                 for( $i = $start - 1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
 295                         $count++;
 296                 }
 297                 return $count;
 298         }
 299
 300         /**
 301          * @static
 302          */
 303         function logToDB($name, $timeSum, $eventCount) {
 304                 $fname = 'Profiler::logToDB';
 305                 $dbw =& wfGetDB( DB_MASTER );
 306                 $profiling = $dbw->tableName( 'profiling' );
 307
 308                 $name = substr($name,0,255);
 309                 $encname = $dbw->strencode($name);
 310                 $sql = "UPDATE $profiling ".
 311                         "SET pf_count=pf_count+{$eventCount}, ".
 312                         "pf_time=pf_time + {$timeSum} ".
 313                         "WHERE pf_name='{$encname}'";
 314                 $dbw->query($sql);
 315
 316                 $rc = $dbw->affectedRows();
 317                 if( $rc == 0) {
 318                         $dbw->insert('profiling',array(
 319                                 'pf_name'=>$name,
 320                                 'pf_count'=>$eventCount,
 321                                 'pf_time'=>$timeSum),
 322                                 $fname,array('IGNORE'));
 323                 }
 324                 // When we upgrade to mysql 4.1, the insert+update
 325                 // can be merged into just a insert with this construct added:
 326                 //     "ON DUPLICATE KEY UPDATE ".
 327                 //     "pf_count=pf_count + VALUES(pf_count), ".
 328                 //     "pf_time=pf_time + VALUES(pf_time)";
 329         }
 330
 331 }
 332
 333
 334 $wgProfiler = new Profiler();
 335 $wgProfiler->profileIn( '-total' );
 336 ?>