includes/Profiling.php

   1 <?php
   2 # This file is only included if profiling is enabled
   3 function wfProfileIn( $functionname )
   4 {
   5         global $wgProfiler;
   6         $wgProfiler->profileIn( $functionname );
   7 }
   8
   9 function wfProfileOut( $functionname = 'missing' )
  10 {
  11         global $wgProfiler;
  12         $wgProfiler->profileOut( $functionname );
  13 }
  14
  15 function wfGetProfilingOutput( $start, $elapsed ) {
  16         global $wgProfiler;
  17         return $wgProfiler->getOutput( $start, $elapsed );
  18 }
  19
  20 function wfProfileClose()
  21 {
  22         global $wgProfiler;
  23         $wgProfiler->close();
  24 }
  25
  26 if( !function_exists( 'memory_get_usage' ) ) {
  27         # Old PHP or --enable-memory-limit not compiled in
  28         function memory_get_usage() {
  29                 return 0;
  30         }
  31 }
  32
  33 class Profiler
  34 {
  35         var $mStack = array(), $mWorkStack = array(), $mCollated = array();
  36         var $mCalls = array(), $mTotals = array();
  37         /*
  38         function Profiler()
  39         {
  40                 $this->mProfileStack = array();
  41                 $this->mWorkStack = array();
  42                 $this->mCollated = array();
  43         }
  44         */
  45
  46         function profileIn( $functionname )
  47         {
  48                 global $wgDebugFunctionEntry;
  49                 if ( $wgDebugFunctionEntry && function_exists( 'wfDebug' ) ) {
  50                         wfDebug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Entering '.$functionname."\n" );
  51                 }
  52                 array_push( $this->mWorkStack, array($functionname, count( $this->mWorkStack ), microtime(), memory_get_usage() ) );
  53         }
  54
  55         function profileOut( $functionname )
  56         {
  57                 $memory = memory_get_usage();
  58                 global $wgDebugProfiling, $wgDebugFunctionEntry;
  59
  60                 if ( $wgDebugFunctionEntry && function_exists( 'wfDebug' ) ) {
  61                         wfDebug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Exiting '.$functionname."\n" );
  62                 }
  63
  64                 $bit = array_pop( $this->mWorkStack );
  65
  66                 if ( !$bit ) {
  67                         wfDebug( "Profiling error, !\$bit: $functionname\n" );
  68                 } else {
  69                         if ( $wgDebugProfiling ) {
  70                                 if ( $functionname == 'close' ) {
  71                                         wfDebug( "Profile section ended by close(): {$bit[0]}\n" );
  72                                 } elseif ( $bit[0] != $functionname ) {
  73                                         wfDebug( "Profiling error: in({$bit[0]}), out($functionname)\n" );
  74                                 }
  75                         }
  76                         array_push( $bit, microtime() );
  77                         array_push( $bit, $memory );
  78                         array_push( $this->mStack, $bit );
  79                 }
  80         }
  81
  82         function close()
  83         {
  84                 while ( count( $this->mWorkStack ) ) {
  85                         $this->profileOut( 'close' );
  86                 }
  87         }
  88
  89         function getOutput()
  90         {
  91                 global $wgDebugFunctionEntry;
  92                 $wgDebugFunctionEntry = false;
  93
  94                 if( !count( $this->mStack ) ) {
  95                         return "No profiling output\n";
  96                 }
  97                 $this->close();
  98                 $width = 125;
  99                 $format = "%-" . ($width - 34) . "s %6d %6.3f %6.3f %6.3f%% %6d\n";
 100                 $titleFormat = "%-" . ($width - 34) . "s %9s %9s %9s %9s %6s\n";
 101                 $prof = "\nProfiling data\n";
 102                 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
 103                 $this->mCollated = array();
 104                 $this->mCalls = array();
 105                 $this->mMemory = array();
 106
 107                 # Estimate profiling overhead
 108                 $profileCount = count( $this->mStack );
 109                 wfProfileIn( '-overhead-total' );
 110                 for ($i=0; $i<$profileCount ; $i++) {
 111                         wfProfileIn( '-overhead-internal' );
 112                         wfProfileOut( '-overhead-internal' );
 113                 }
 114                 wfProfileOut( '-overhead-total' );
 115
 116                 # Collate
 117                 foreach ( $this->mStack as $entry ) {
 118                         $fname = $entry[0];
 119                         $thislevel = $entry[1];
 120                         $start = explode( ' ', $entry[2]);
 121                         $start = (float)$start[0] + (float)$start[1];
 122                         $end = explode( ' ', $entry[4]);
 123                         $end = (float)$end[0] + (float)$end[1];
 124                         $elapsed = $end - $start;
 125
 126                         $memory = $entry[5] - $entry[3];
 127
 128                         if ( !array_key_exists( $fname, $this->mCollated ) ) {
 129                                 $this->mCollated[$fname] = 0;
 130                                 $this->mCalls[$fname] = 0;
 131                                 $this->mMemory[$fname] = 0;
 132                         }
 133
 134                         $this->mCollated[$fname] += $elapsed;
 135                         $this->mCalls[$fname] ++;
 136                         $this->mMemory[$fname] += $memory;
 137                 }
 138
 139                 $total = @$this->mCollated['-total'];
 140                 $overhead = $this->mCollated['-overhead-internal'] / $profileCount;
 141                 $this->mCalls['-overhead-total'] = $profileCount;
 142
 143                 # Output
 144                 arsort( $this->mCollated, SORT_NUMERIC );
 145                 foreach ( $this->mCollated as $fname => $elapsed ) {
 146                         $calls = $this->mCalls[$fname];
 147                         # Adjust for overhead
 148                         if ( $fname[0] != '-' ) {
 149                                 $elapsed -= $overhead * $calls;
 150                         }
 151
 152                         $percent = $total ? 100. * $elapsed / $total : 0;
 153                         $memory = $this->mMemory[$fname];
 154                         $prof .= sprintf( $format, $fname, $calls, (float)($elapsed * 1000),
 155                                         (float)($elapsed * 1000) / $calls, $percent, $memory );
 156
 157                         global $wgProfileToDatabase;
 158                         if( $wgProfileToDatabase ) {
 159                                 Profiler::logToDB( $fname, (float)($elapsed * 1000), $calls );
 160                         }
 161                 }
 162                 $prof .= "\nTotal: $total\n\n";
 163
 164                 return $prof;
 165         }
 166
 167
 168         /* static */ function logToDB($name, $timeSum, $eventCount)
 169         {
 170                 $dbw =& wfGetDB( DB_MASTER );
 171                 $profiling = $dbw->tableName( 'profiling' );
 172
 173                 $name = substr($dbw->strencode( $name ),0,255);
 174                 $sql = "UPDATE $profiling ".
 175                         "SET pf_count=pf_count+{$eventCount}, ".
 176                         "pf_time=pf_time + {$timeSum} ".
 177                         "WHERE pf_name='{$name}'";
 178                 $dbw->query($sql);
 179
 180                 $rc = $dbw->affectedRows();
 181                 if( $rc == 0) {
 182                         $dbw->insertArray($profiling,array(
 183                                 'pf_name'=>$name,
 184                                 'pf_count'=>$eventCount,
 185                                 'pf_time'=>$timeSum),
 186                                 $fname,array('IGNORE'));
 187                 }
 188                 // When we upgrade to mysql 4.1, the insert+update
 189                 // can be merged into just a insert with this construct added:
 190                 //     "ON DUPLICATE KEY UPDATE ".
 191                 //     "pf_count=pf_count + VALUES(pf_count), ".
 192                 //     "pf_time=pf_time + VALUES(pf_time)";
 193         }
 194
 195 }
 196
 197
 198 $wgProfiler = new Profiler();
 199 $wgProfiler->profileIn( '-total' );
 200 ?>