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