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         var $mStack = array (), $mWorkStack = array (), $mCollated = array ();
  46         var $mCalls = array (), $mTotals = array ();
  47         /*
  48         function Profiler()
  49         {
  50                 $this->mProfileStack = array();
  51                 $this->mWorkStack = array();
  52                 $this->mCollated = array();
  53         }
  54         */
  55
  56         function profileIn($functionname) {
  57                 global $wgDebugFunctionEntry;
  58                 if ($wgDebugFunctionEntry && function_exists('wfDebug')) {
  59                         wfDebug(str_repeat(' ', count($this->mWorkStack)).'Entering '.$functionname."\n");
  60                 }
  61                 $this->mWorkStack[] = array($functionname, count($this->mWorkStack), microtime(), memory_get_usage());
  62                 #$this->mWorkStack[] = array($functionname, count( $this->mWorkStack ), $this->getUserTime(), memory_get_usage());
  63         }
  64
  65         function profileOut($functionname) {
  66                 $memory = memory_get_usage();
  67                 $time = microtime();
  68                 #$time = $this->getUserTime();
  69
  70                 global $wgDebugProfiling, $wgDebugFunctionEntry;
  71
  72                 if ($wgDebugFunctionEntry && function_exists('wfDebug')) {
  73                         wfDebug(str_repeat(' ', count($this->mWorkStack) - 1).'Exiting '.$functionname."\n");
  74                 }
  75
  76                 $bit = array_pop($this->mWorkStack);
  77
  78                 if (!$bit) {
  79                         wfDebug("Profiling error, !\$bit: $functionname\n");
  80                 } else {
  81                         if ($wgDebugProfiling) {
  82                                 if ($functionname == 'close') {
  83                                         wfDebug("Profile section ended by close(): {$bit[0]}\n");
  84                                 }
  85                                 elseif ($bit[0] != $functionname) {
  86                                         wfDebug("Profiling error: in({$bit[0]}), out($functionname)\n");
  87                                 }
  88                         }
  89                         $bit[] = $time;
  90                         $bit[] = $memory;
  91                         $this->mStack[] = $bit;
  92                 }
  93         }
  94
  95         function close() {
  96                 while (count($this->mWorkStack)) {
  97                         $this->profileOut('close');
  98                 }
  99         }
 100
 101         function getOutput() {
 102                 global $wgDebugFunctionEntry;
 103                 $wgDebugFunctionEntry = false;
 104
 105                 if (!count($this->mStack)) {
 106                         return "No profiling output\n";
 107                 }
 108                 $this->close();
 109
 110                 global $wgProfileCallTree;
 111                 if ($wgProfileCallTree) {
 112                         return $this->getCallTree();
 113                 } else {
 114                         return $this->getFunctionReport();
 115                 }
 116         }
 117
 118         function getCallTree($start = 0) {
 119                 return implode('', array_map(array (& $this, 'getCallTreeLine'), $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 <<<<<<< Profiling.php
 165                 return sprintf("%10s %s %s\n", trim(sprintf("%7.3f", $delta * 1000.0)), $space, $fname);
 166         }
 167
 168         function micro2Float($micro) {
 169                 list ($whole, $fractional) = explode(' ', $micro);
 170                 return (float) $whole + (float) $fractional;
 171         }
 172
 173         function microDelta($start, $end) {
 174                 return $this->micro2Float($end) - $this->micro2Float($start);
 175         }
 176
 177         function getFunctionReport() {
 178                 $width = 125;
 179                 $format = "%-". ($width -34)."s %6d %6.3f %6.3f %7.3f%% %6d (%6.3f-%6.3f) [%d]\n";
 180                 $titleFormat = "%-". ($width -34)."s %9s %9s %9s %9s %6s\n";
 181 =======
 182                 return sprintf( "%10s %s %s\n",
 183                         trim( sprintf( "%7.3f", $delta * 1000.0 ) ),
 184                         $space, $fname );
 185         }
 186
 187         function micro2Float( $micro ) {
 188                 list( $whole, $fractional ) = explode( ' ', $micro );
 189                 return (float)$whole + (float)$fractional;
 190         }
 191
 192         function microDelta( $start, $end ) {
 193                 return $this->micro2Float( $end ) -
 194                        $this->micro2Float( $start );
 195         }
 196
 197         function getUserTime() {
 198                 $ru = getrusage();
 199                 return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6;
 200         }
 201
 202         function getFunctionReport() {
 203                 $width = 140;
 204                 $nameWidth = $width - 65;
 205                 $format =      "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d  (%13.3f -%13.3f) [%d]\n";
 206                 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s %14s   %14s %9s\n";
 207 >>>>>>> 1.29.2.6
 208                 $prof = "\nProfiling data\n";
 209                 $prof .= sprintf($titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem');
 210                 $this->mCollated = array ();
 211                 $this->mCalls = array ();
 212                 $this->mMemory = array ();
 213
 214                 # Estimate profiling overhead
 215                 $profileCount = count($this->mStack);
 216                 wfProfileIn('-overhead-total');
 217                 for ($i = 0; $i < $profileCount; $i ++) {
 218                         wfProfileIn('-overhead-internal');
 219                         wfProfileOut('-overhead-internal');
 220                 }
 221                 wfProfileOut('-overhead-total');
 222
 223                 # First, subtract the overhead!
 224                 foreach ($this->mStack as $entry) {
 225                         $fname = $entry[0];
 226                         $thislevel = $entry[1];
 227                         $start = explode(' ', $entry[2]);
 228                         $start = (float) $start[0] + (float) $start[1];
 229                         $end = explode(' ', $entry[4]);
 230                         $end = (float) $end[0] + (float) $end[1];
 231                         $elapsed = $end - $start;
 232                         $memory = $entry[5] - $entry[3];
 233
 234                         if ($fname == '-overhead-total') {
 235                                 $overheadTotal[] = $elapsed;
 236                                 $overheadMemory[] = $memory;
 237                         }
 238                         elseif ($fname == '-overhead-internal') {
 239                                 $overheadInternal[] = $elapsed;
 240                         }
 241                 }
 242                 $overheadTotal = array_sum($overheadTotal) / count($overheadInternal);
 243                 $overheadMemory = array_sum($overheadMemory) / count($overheadInternal);
 244                 $overheadInternal = array_sum($overheadInternal) / count($overheadInternal);
 245
 246                 # Collate
 247                 foreach ($this->mStack as $index => $entry) {
 248                         $fname = $entry[0];
 249                         $thislevel = $entry[1];
 250                         $start = explode(' ', $entry[2]);
 251                         $start = (float) $start[0] + (float) $start[1];
 252                         $end = explode(' ', $entry[4]);
 253                         $end = (float) $end[0] + (float) $end[1];
 254                         $elapsed = $end - $start;
 255
 256                         $memory = $entry[5] - $entry[3];
 257                         $subcalls = $this->calltreeCount($this->mStack, $index);
 258
 259                         if (!preg_match('/^-overhead/', $fname)) {
 260                                 # Adjust for profiling overhead
 261                                 $elapsed -= $overheadInternal;
 262                                 $elapsed -= ($subcalls * $overheadTotal);
 263                                 $memory -= ($subcalls * $overheadMemory);
 264                         }
 265
 266                         if (!array_key_exists($fname, $this->mCollated)) {
 267                                 $this->mCollated[$fname] = 0;
 268                                 $this->mCalls[$fname] = 0;
 269                                 $this->mMemory[$fname] = 0;
 270                                 $this->mMin[$fname] = 1 << 24;
 271                                 $this->mMax[$fname] = 0;
 272                                 $this->mOverhead[$fname] = 0;
 273                         }
 274
 275                         $this->mCollated[$fname] += $elapsed;
 276                         $this->mCalls[$fname]++;
 277                         $this->mMemory[$fname] += $memory;
 278                         $this->mMin[$fname] = min($this->mMin[$fname], $elapsed);
 279                         $this->mMax[$fname] = max($this->mMax[$fname], $elapsed);
 280                         $this->mOverhead[$fname] += $subcalls;
 281                 }
 282
 283                 $total = @ $this->mCollated['-total'];
 284                 $this->mCalls['-overhead-total'] = $profileCount;
 285
 286                 # Output
 287                 asort($this->mCollated, SORT_NUMERIC);
 288                 foreach ($this->mCollated as $fname => $elapsed) {
 289                         $calls = $this->mCalls[$fname];
 290                         $percent = $total ? 100. * $elapsed / $total : 0;
 291                         $memory = $this->mMemory[$fname];
 292                         $prof .= sprintf($format, $fname, $calls, (float) ($elapsed * 1000), (float) ($elapsed * 1000) / $calls, $percent, $memory, ($this->mMin[$fname] * 1000.0), ($this->mMax[$fname] * 1000.0), $this->mOverhead[$fname]);
 293
 294                         global $wgProfileToDatabase;
 295                         if ($wgProfileToDatabase) {
 296                                 Profiler :: logToDB($fname, (float) ($elapsed * 1000), $calls);
 297                         }
 298                 }
 299                 $prof .= "\nTotal: $total\n\n";
 300
 301                 return $prof;
 302         }
 303
 304         /**
 305          * Counts the number of profiled function calls sitting under
 306          * the given point in the call graph. Not the most efficient algo.
 307          *
 308          * @param array $stack
 309          * @param int $start
 310          * @return int
 311          * @access private
 312          */
 313         function calltreeCount(& $stack, $start) {
 314                 $level = $stack[$start][1];
 315                 $count = 0;
 316                 for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) {
 317                         $count ++;
 318                 }
 319                 return $count;
 320         }
 321
 322         /**
 323          * @static
 324          */
 325         function logToDB($name, $timeSum, $eventCount) {
 326                 $fname = 'Profiler::logToDB';
 327                 $dbw = & wfGetDB(DB_MASTER);
 328                 $profiling = $dbw->tableName('profiling');
 329
 330                 $name = substr($name, 0, 255);
 331                 $encname = $dbw->strencode($name);
 332                 $sql = "UPDATE $profiling "."SET pf_count=pf_count+{$eventCount}, "."pf_time=pf_time + {$timeSum} "."WHERE pf_name='{$encname}'";
 333                 $dbw->query($sql);
 334
 335                 $rc = $dbw->affectedRows();
 336                 if ($rc == 0) {
 337                         $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount, 'pf_time' => $timeSum), $fname, array ('IGNORE'));
 338                 }
 339                 // When we upgrade to mysql 4.1, the insert+update
 340                 // can be merged into just a insert with this construct added:
 341                 //     "ON DUPLICATE KEY UPDATE ".
 342                 //     "pf_count=pf_count + VALUES(pf_count), ".
 343                 //     "pf_time=pf_time + VALUES(pf_time)";
 344         }
 345
 346 }
 347
 348 $wgProfiler = new Profiler();
 349 $wgProfiler->profileIn('-total');
 350 ?>