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                 array_push( $this->mWorkStack, array($functionname, count( $this->mWorkStack ), microtime(), memory_get_usage() ) );
  63         }
  64
  65         function profileOut( $functionname ) {
  66                 $memory = memory_get_usage();
  67                 global $wgDebugProfiling, $wgDebugFunctionEntry;
  68
  69                 if ( $wgDebugFunctionEntry && function_exists( 'wfDebug' ) ) {
  70                         wfDebug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Exiting '.$functionname."\n" );
  71                 }
  72
  73                 $bit = array_pop( $this->mWorkStack );
  74
  75                 if ( !$bit ) {
  76                         wfDebug( "Profiling error, !\$bit: $functionname\n" );
  77                 } else {
  78                         if ( $wgDebugProfiling ) {
  79                                 if ( $functionname == 'close' ) {
  80                                         wfDebug( "Profile section ended by close(): {$bit[0]}\n" );
  81                                 } elseif ( $bit[0] != $functionname ) {
  82                                         wfDebug( "Profiling error: in({$bit[0]}), out($functionname)\n" );
  83                                 }
  84                         }
  85                         array_push( $bit, microtime() );
  86                         array_push( $bit, $memory );
  87                         array_push( $this->mStack, $bit );
  88                 }
  89         }
  90
  91         function close() {
  92                 while ( count( $this->mWorkStack ) ) {
  93                         $this->profileOut( 'close' );
  94                 }
  95         }
  96
  97         function getOutput() {
  98                 global $wgDebugFunctionEntry;
  99                 $wgDebugFunctionEntry = false;
 100
 101                 if( !count( $this->mStack ) ) {
 102                         return "No profiling output\n";
 103                 }
 104                 $this->close();
 105                 $width = 125;
 106                 $format = "%-" . ($width - 34) . "s %6d %6.3f %6.3f %6.3f%% %6d\n";
 107                 $titleFormat = "%-" . ($width - 34) . "s %9s %9s %9s %9s %6s\n";
 108                 $prof = "\nProfiling data\n";
 109                 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
 110                 $this->mCollated = array();
 111                 $this->mCalls = array();
 112                 $this->mMemory = array();
 113
 114                 # Estimate profiling overhead
 115                 $profileCount = count( $this->mStack );
 116                 wfProfileIn( '-overhead-total' );
 117                 for ($i=0; $i<$profileCount ; $i++) {
 118                         wfProfileIn( '-overhead-internal' );
 119                         wfProfileOut( '-overhead-internal' );
 120                 }
 121                 wfProfileOut( '-overhead-total' );
 122
 123                 # Collate
 124                 foreach ( $this->mStack as $entry ) {
 125                         $fname = $entry[0];
 126                         $thislevel = $entry[1];
 127                         $start = explode( ' ', $entry[2]);
 128                         $start = (float)$start[0] + (float)$start[1];
 129                         $end = explode( ' ', $entry[4]);
 130                         $end = (float)$end[0] + (float)$end[1];
 131                         $elapsed = $end - $start;
 132
 133                         $memory = $entry[5] - $entry[3];
 134
 135                         if ( !array_key_exists( $fname, $this->mCollated ) ) {
 136                                 $this->mCollated[$fname] = 0;
 137                                 $this->mCalls[$fname] = 0;
 138                                 $this->mMemory[$fname] = 0;
 139                         }
 140
 141                         $this->mCollated[$fname] += $elapsed;
 142                         $this->mCalls[$fname] ++;
 143                         $this->mMemory[$fname] += $memory;
 144                 }
 145
 146                 $total = @$this->mCollated['-total'];
 147                 $overhead = $this->mCollated['-overhead-internal'] / $profileCount;
 148                 $this->mCalls['-overhead-total'] = $profileCount;
 149
 150                 # Output
 151                 arsort( $this->mCollated, SORT_NUMERIC );
 152                 foreach ( $this->mCollated as $fname => $elapsed ) {
 153                         $calls = $this->mCalls[$fname];
 154                         # Adjust for overhead
 155                         if ( $fname[0] != '-' ) {
 156                                 $elapsed -= $overhead * $calls;
 157                         }
 158
 159                         $percent = $total ? 100. * $elapsed / $total : 0;
 160                         $memory = $this->mMemory[$fname];
 161                         $prof .= sprintf( $format, $fname, $calls, (float)($elapsed * 1000),
 162                                         (float)($elapsed * 1000) / $calls, $percent, $memory );
 163
 164                         global $wgProfileToDatabase;
 165                         if( $wgProfileToDatabase ) {
 166                                 Profiler::logToDB( $fname, (float)($elapsed * 1000), $calls );
 167                         }
 168                 }
 169                 $prof .= "\nTotal: $total\n\n";
 170
 171                 return $prof;
 172         }
 173
 174
 175         /**
 176          * @static
 177          */
 178         function logToDB($name, $timeSum, $eventCount) {
 179                 $dbw =& wfGetDB( DB_MASTER );
 180                 $profiling = $dbw->tableName( 'profiling' );
 181
 182                 $name = substr($dbw->strencode( $name ),0,255);
 183                 $sql = "UPDATE $profiling ".
 184                         "SET pf_count=pf_count+{$eventCount}, ".
 185                         "pf_time=pf_time + {$timeSum} ".
 186                         "WHERE pf_name='{$name}'";
 187                 $dbw->query($sql);
 188
 189                 $rc = $dbw->affectedRows();
 190                 if( $rc == 0) {
 191                         $dbw->insertArray($profiling,array(
 192                                 'pf_name'=>$name,
 193                                 'pf_count'=>$eventCount,
 194                                 'pf_time'=>$timeSum),
 195                                 $fname,array('IGNORE'));
 196                 }
 197                 // When we upgrade to mysql 4.1, the insert+update
 198                 // can be merged into just a insert with this construct added:
 199                 //     "ON DUPLICATE KEY UPDATE ".
 200                 //     "pf_count=pf_count + VALUES(pf_count), ".
 201                 //     "pf_time=pf_time + VALUES(pf_time)";
 202         }
 203
 204 }
 205
 206
 207 $wgProfiler = new Profiler();
 208 $wgProfiler->profileIn( '-total' );
 209 ?>