| Index: trunk/phase3/includes/ProfilerSimpleText.php |
| — | — | @@ -0,0 +1,39 @@ |
| | 2 | +<?php |
| | 3 | +/** |
| | 4 | + * @file |
| | 5 | + * @ingroup Profiler |
| | 6 | + */ |
| | 7 | + |
| | 8 | +require_once( dirname( __FILE__ ) . '/ProfilerSimple.php' ); |
| | 9 | + |
| | 10 | +/** |
| | 11 | + * The least sophisticated profiler output class possible, view your source! :) |
| | 12 | + * |
| | 13 | + * Put the following 3 lines in StartProfiler.php: |
| | 14 | + * |
| | 15 | + * require_once( dirname( __FILE__ ) . '/includes/ProfilerSimpleText.php' ); |
| | 16 | + * $wgProfiler = new ProfilerSimpleText; |
| | 17 | + * $wgProfiler->visible=true; |
| | 18 | + * |
| | 19 | + * @ingroup Profiler |
| | 20 | + */ |
| | 21 | +class ProfilerSimpleText extends ProfilerSimple { |
| | 22 | + public $visible=false; /* Show as <PRE> or <!-- ? */ |
| | 23 | + static private $out; |
| | 24 | + |
| | 25 | + function getFunctionReport() { |
| | 26 | + if($this->mTemplated) { |
| | 27 | + uasort($this->mCollated,array('self','sort')); |
| | 28 | + array_walk($this->mCollated,array('self','format')); |
| | 29 | + if ($this->visible) { |
| | 30 | + print '<pre>'.self::$out.'</pre>'; |
| | 31 | + } else { |
| | 32 | + print "<!--\n".self::$out."\n-->\n"; |
| | 33 | + } |
| | 34 | + } |
| | 35 | + } |
| | 36 | + |
| | 37 | + /* dense is good */ |
| | 38 | + static function sort($a,$b) { return $a['real']<$b['real']; /* sort descending by time elapsed */ } |
| | 39 | + static function format($item,$key) { self::$out .= sprintf("%3.6f %6d - %s\n",$item['real'],$item['count'], $key); } |
| | 40 | +} |
| Property changes on: trunk/phase3/includes/ProfilerSimpleText.php |
| ___________________________________________________________________ |
| Added: svn:eol-style |
| 1 | 41 | + native |
| Index: trunk/phase3/includes/ProfilerStub.php |
| — | — | @@ -0,0 +1,52 @@ |
| | 2 | +<?php |
| | 3 | +/** |
| | 4 | + * Stub profiling functions |
| | 5 | + * @file |
| | 6 | + * @ingroup Profiler |
| | 7 | + */ |
| | 8 | + |
| | 9 | +/** backward compatibility */ |
| | 10 | +$wgProfiling = false; |
| | 11 | +$wgProfiler = null; |
| | 12 | + |
| | 13 | +/** is setproctitle function available ? */ |
| | 14 | +$haveProctitle = function_exists( 'setproctitle' ); |
| | 15 | + |
| | 16 | +/** |
| | 17 | + * Begin profiling of a function |
| | 18 | + * @param $fn string |
| | 19 | + */ |
| | 20 | +function wfProfileIn( $fn = '' ) { |
| | 21 | + global $hackwhere, $wgDBname, $haveProctitle; |
| | 22 | + if( $haveProctitle ){ |
| | 23 | + $hackwhere[] = $fn; |
| | 24 | + setproctitle( $fn . " [$wgDBname]" ); |
| | 25 | + } |
| | 26 | +} |
| | 27 | + |
| | 28 | +/** |
| | 29 | + * Stop profiling of a function |
| | 30 | + * @param $fn string |
| | 31 | + */ |
| | 32 | +function wfProfileOut( $fn = '' ) { |
| | 33 | + global $hackwhere, $wgDBname, $haveProctitle; |
| | 34 | + if( !$haveProctitle ) { |
| | 35 | + return; |
| | 36 | + } |
| | 37 | + if( count( $hackwhere ) ) { |
| | 38 | + array_pop( $hackwhere ); |
| | 39 | + } |
| | 40 | + if( count( $hackwhere ) ) { |
| | 41 | + setproctitle( $hackwhere[count( $hackwhere )-1] . " [$wgDBname]" ); |
| | 42 | + } |
| | 43 | +} |
| | 44 | + |
| | 45 | +/** |
| | 46 | + * Does nothing, just for compatibility |
| | 47 | + */ |
| | 48 | +function wfGetProfilingOutput( $s, $e ) {} |
| | 49 | + |
| | 50 | +/** |
| | 51 | + * Does nothing, just for compatibility |
| | 52 | + */ |
| | 53 | +function wfProfileClose() {} |
| Property changes on: trunk/phase3/includes/ProfilerStub.php |
| ___________________________________________________________________ |
| Added: svn:eol-style |
| 1 | 54 | + native |
| Added: svn:keywords |
| 2 | 55 | + Author Date Id Revision |
| Index: trunk/phase3/includes/Profiler.php |
| — | — | @@ -0,0 +1,463 @@ |
| | 2 | +<?php |
| | 3 | +/** |
| | 4 | + * @defgroup Profiler Profiler |
| | 5 | + * |
| | 6 | + * @file |
| | 7 | + * @ingroup Profiler |
| | 8 | + * This file is only included if profiling is enabled |
| | 9 | + */ |
| | 10 | + |
| | 11 | +/** backward compatibility */ |
| | 12 | +$wgProfiling = true; |
| | 13 | + |
| | 14 | +/** |
| | 15 | + * Begin profiling of a function |
| | 16 | + * @param $functionname String: name of the function we will profile |
| | 17 | + */ |
| | 18 | +function wfProfileIn( $functionname ) { |
| | 19 | + global $wgProfiler; |
| | 20 | + $wgProfiler->profileIn( $functionname ); |
| | 21 | +} |
| | 22 | + |
| | 23 | +/** |
| | 24 | + * Stop profiling of a function |
| | 25 | + * @param $functionname String: name of the function we have profiled |
| | 26 | + */ |
| | 27 | +function wfProfileOut( $functionname = 'missing' ) { |
| | 28 | + global $wgProfiler; |
| | 29 | + $wgProfiler->profileOut( $functionname ); |
| | 30 | +} |
| | 31 | + |
| | 32 | +/** |
| | 33 | + * Returns a profiling output to be stored in debug file |
| | 34 | + * |
| | 35 | + * @param $start Float |
| | 36 | + * @param $elapsed Float: time elapsed since the beginning of the request |
| | 37 | + */ |
| | 38 | +function wfGetProfilingOutput( $start, $elapsed ) { |
| | 39 | + global $wgProfiler; |
| | 40 | + return $wgProfiler->getOutput( $start, $elapsed ); |
| | 41 | +} |
| | 42 | + |
| | 43 | +/** |
| | 44 | + * Close opened profiling sections |
| | 45 | + */ |
| | 46 | +function wfProfileClose() { |
| | 47 | + global $wgProfiler; |
| | 48 | + $wgProfiler->close(); |
| | 49 | +} |
| | 50 | + |
| | 51 | +if (!function_exists('memory_get_usage')) { |
| | 52 | + # Old PHP or --enable-memory-limit not compiled in |
| | 53 | + function memory_get_usage() { |
| | 54 | + return 0; |
| | 55 | + } |
| | 56 | +} |
| | 57 | + |
| | 58 | +/** |
| | 59 | + * @ingroup Profiler |
| | 60 | + * @todo document |
| | 61 | + */ |
| | 62 | +class Profiler { |
| | 63 | + var $mStack = array (), $mWorkStack = array (), $mCollated = array (); |
| | 64 | + var $mCalls = array (), $mTotals = array (); |
| | 65 | + var $mTemplated = false; |
| | 66 | + |
| | 67 | + function __construct() { |
| | 68 | + // Push an entry for the pre-profile setup time onto the stack |
| | 69 | + global $wgRequestTime; |
| | 70 | + if ( !empty( $wgRequestTime ) ) { |
| | 71 | + $this->mWorkStack[] = array( '-total', 0, $wgRequestTime, 0 ); |
| | 72 | + $this->mStack[] = array( '-setup', 1, $wgRequestTime, 0, microtime(true), 0 ); |
| | 73 | + } else { |
| | 74 | + $this->profileIn( '-total' ); |
| | 75 | + } |
| | 76 | + } |
| | 77 | + |
| | 78 | + /** |
| | 79 | + * Called by wfProfieIn() |
| | 80 | + * |
| | 81 | + * @param $functionname String |
| | 82 | + */ |
| | 83 | + function profileIn( $functionname ) { |
| | 84 | + global $wgDebugFunctionEntry, $wgProfiling; |
| | 85 | + if( !$wgProfiling ) return; |
| | 86 | + if( $wgDebugFunctionEntry ){ |
| | 87 | + $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Entering ' . $functionname . "\n" ); |
| | 88 | + } |
| | 89 | + |
| | 90 | + $this->mWorkStack[] = array( $functionname, count( $this->mWorkStack ), $this->getTime(), memory_get_usage() ); |
| | 91 | + } |
| | 92 | + |
| | 93 | + /** |
| | 94 | + * Called by wfProfieOut() |
| | 95 | + * |
| | 96 | + * @param $functionname String |
| | 97 | + */ |
| | 98 | + function profileOut($functionname) { |
| | 99 | + global $wgDebugFunctionEntry, $wgProfiling; |
| | 100 | + if( !$wgProfiling ) return; |
| | 101 | + $memory = memory_get_usage(); |
| | 102 | + $time = $this->getTime(); |
| | 103 | + |
| | 104 | + if( $wgDebugFunctionEntry ){ |
| | 105 | + $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . 'Exiting ' . $functionname . "\n" ); |
| | 106 | + } |
| | 107 | + |
| | 108 | + $bit = array_pop($this->mWorkStack); |
| | 109 | + |
| | 110 | + if (!$bit) { |
| | 111 | + $this->debug("Profiling error, !\$bit: $functionname\n"); |
| | 112 | + } else { |
| | 113 | + //if( $wgDebugProfiling ){ |
| | 114 | + if( $functionname == 'close' ){ |
| | 115 | + $message = "Profile section ended by close(): {$bit[0]}"; |
| | 116 | + $this->debug( "$message\n" ); |
| | 117 | + $this->mStack[] = array( $message, 0, '0 0', 0, '0 0', 0 ); |
| | 118 | + } |
| | 119 | + elseif( $bit[0] != $functionname ){ |
| | 120 | + $message = "Profiling error: in({$bit[0]}), out($functionname)"; |
| | 121 | + $this->debug( "$message\n" ); |
| | 122 | + $this->mStack[] = array( $message, 0, '0 0', 0, '0 0', 0 ); |
| | 123 | + } |
| | 124 | + //} |
| | 125 | + $bit[] = $time; |
| | 126 | + $bit[] = $memory; |
| | 127 | + $this->mStack[] = $bit; |
| | 128 | + } |
| | 129 | + } |
| | 130 | + |
| | 131 | + /** |
| | 132 | + * called by wfProfileClose() |
| | 133 | + */ |
| | 134 | + function close() { |
| | 135 | + global $wgProfiling; |
| | 136 | + |
| | 137 | + # Avoid infinite loop |
| | 138 | + if( !$wgProfiling ) |
| | 139 | + return; |
| | 140 | + |
| | 141 | + while( count( $this->mWorkStack ) ){ |
| | 142 | + $this->profileOut( 'close' ); |
| | 143 | + } |
| | 144 | + } |
| | 145 | + |
| | 146 | + /** |
| | 147 | + * Mark this call as templated or not |
| | 148 | + * |
| | 149 | + * @param $t Boolean |
| | 150 | + */ |
| | 151 | + function setTemplated( $t ) { |
| | 152 | + $this->mTemplated = $t; |
| | 153 | + } |
| | 154 | + |
| | 155 | + /** |
| | 156 | + * Called by wfGetProfilingOutput() |
| | 157 | + */ |
| | 158 | + function getOutput() { |
| | 159 | + global $wgDebugFunctionEntry, $wgProfileCallTree; |
| | 160 | + $wgDebugFunctionEntry = false; |
| | 161 | + |
| | 162 | + if( !count( $this->mStack ) && !count( $this->mCollated ) ){ |
| | 163 | + return "No profiling output\n"; |
| | 164 | + } |
| | 165 | + $this->close(); |
| | 166 | + |
| | 167 | + if( $wgProfileCallTree ) { |
| | 168 | + global $wgProfileToDatabase; |
| | 169 | + # XXX: We must call $this->getFunctionReport() to log to the DB |
| | 170 | + if( $wgProfileToDatabase ) { |
| | 171 | + $this->getFunctionReport(); |
| | 172 | + } |
| | 173 | + return $this->getCallTree(); |
| | 174 | + } else { |
| | 175 | + return $this->getFunctionReport(); |
| | 176 | + } |
| | 177 | + } |
| | 178 | + |
| | 179 | + /** |
| | 180 | + * Returns a tree of function call instead of a list of functions |
| | 181 | + */ |
| | 182 | + function getCallTree() { |
| | 183 | + return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) ) ); |
| | 184 | + } |
| | 185 | + |
| | 186 | + /** |
| | 187 | + * Recursive function the format the current profiling array into a tree |
| | 188 | + * |
| | 189 | + * @param $stack profiling array |
| | 190 | + */ |
| | 191 | + function remapCallTree( $stack ) { |
| | 192 | + if( count( $stack ) < 2 ){ |
| | 193 | + return $stack; |
| | 194 | + } |
| | 195 | + $outputs = array (); |
| | 196 | + for( $max = count( $stack ) - 1; $max > 0; ){ |
| | 197 | + /* Find all items under this entry */ |
| | 198 | + $level = $stack[$max][1]; |
| | 199 | + $working = array (); |
| | 200 | + for( $i = $max -1; $i >= 0; $i-- ){ |
| | 201 | + if( $stack[$i][1] > $level ){ |
| | 202 | + $working[] = $stack[$i]; |
| | 203 | + } else { |
| | 204 | + break; |
| | 205 | + } |
| | 206 | + } |
| | 207 | + $working = $this->remapCallTree( array_reverse( $working ) ); |
| | 208 | + $output = array(); |
| | 209 | + foreach( $working as $item ){ |
| | 210 | + array_push( $output, $item ); |
| | 211 | + } |
| | 212 | + array_unshift( $output, $stack[$max] ); |
| | 213 | + $max = $i; |
| | 214 | + |
| | 215 | + array_unshift( $outputs, $output ); |
| | 216 | + } |
| | 217 | + $final = array(); |
| | 218 | + foreach( $outputs as $output ){ |
| | 219 | + foreach( $output as $item ){ |
| | 220 | + $final[] = $item; |
| | 221 | + } |
| | 222 | + } |
| | 223 | + return $final; |
| | 224 | + } |
| | 225 | + |
| | 226 | + /** |
| | 227 | + * Callback to get a formatted line for the call tree |
| | 228 | + */ |
| | 229 | + function getCallTreeLine( $entry ) { |
| | 230 | + list( $fname, $level, $start, /* $x */, $end) = $entry; |
| | 231 | + $delta = $end - $start; |
| | 232 | + $space = str_repeat(' ', $level); |
| | 233 | + # The ugly double sprintf is to work around a PHP bug, |
| | 234 | + # which has been fixed in recent releases. |
| | 235 | + return sprintf( "%10s %s %s\n", trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname ); |
| | 236 | + } |
| | 237 | + |
| | 238 | + function getTime() { |
| | 239 | + return microtime(true); |
| | 240 | + #return $this->getUserTime(); |
| | 241 | + } |
| | 242 | + |
| | 243 | + function getUserTime() { |
| | 244 | + $ru = getrusage(); |
| | 245 | + return $ru['ru_utime.tv_sec'].' '.$ru['ru_utime.tv_usec'] / 1e6; |
| | 246 | + } |
| | 247 | + |
| | 248 | + /** |
| | 249 | + * Returns a list of profiled functions. |
| | 250 | + * Also log it into the database if $wgProfileToDatabase is set to true. |
| | 251 | + */ |
| | 252 | + function getFunctionReport() { |
| | 253 | + global $wgProfileToDatabase; |
| | 254 | + |
| | 255 | + $width = 140; |
| | 256 | + $nameWidth = $width - 65; |
| | 257 | + $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n"; |
| | 258 | + $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n"; |
| | 259 | + $prof = "\nProfiling data\n"; |
| | 260 | + $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' ); |
| | 261 | + $this->mCollated = array (); |
| | 262 | + $this->mCalls = array (); |
| | 263 | + $this->mMemory = array (); |
| | 264 | + |
| | 265 | + # Estimate profiling overhead |
| | 266 | + $profileCount = count($this->mStack); |
| | 267 | + wfProfileIn( '-overhead-total' ); |
| | 268 | + for( $i = 0; $i < $profileCount; $i ++ ){ |
| | 269 | + wfProfileIn( '-overhead-internal' ); |
| | 270 | + wfProfileOut( '-overhead-internal' ); |
| | 271 | + } |
| | 272 | + wfProfileOut( '-overhead-total' ); |
| | 273 | + |
| | 274 | + # First, subtract the overhead! |
| | 275 | + $overheadTotal = $overheadMemory = $overheadInternal = array(); |
| | 276 | + foreach( $this->mStack as $entry ){ |
| | 277 | + $fname = $entry[0]; |
| | 278 | + $start = $entry[2]; |
| | 279 | + $end = $entry[4]; |
| | 280 | + $elapsed = $end - $start; |
| | 281 | + $memory = $entry[5] - $entry[3]; |
| | 282 | + |
| | 283 | + if( $fname == '-overhead-total' ){ |
| | 284 | + $overheadTotal[] = $elapsed; |
| | 285 | + $overheadMemory[] = $memory; |
| | 286 | + } |
| | 287 | + elseif( $fname == '-overhead-internal' ){ |
| | 288 | + $overheadInternal[] = $elapsed; |
| | 289 | + } |
| | 290 | + } |
| | 291 | + $overheadTotal = $overheadTotal ? array_sum( $overheadTotal ) / count( $overheadInternal ) : 0; |
| | 292 | + $overheadMemory = $overheadMemory ? array_sum( $overheadMemory ) / count( $overheadInternal ) : 0; |
| | 293 | + $overheadInternal = $overheadInternal ? array_sum( $overheadInternal ) / count( $overheadInternal ) : 0; |
| | 294 | + |
| | 295 | + # Collate |
| | 296 | + foreach( $this->mStack as $index => $entry ){ |
| | 297 | + $fname = $entry[0]; |
| | 298 | + $start = $entry[2]; |
| | 299 | + $end = $entry[4]; |
| | 300 | + $elapsed = $end - $start; |
| | 301 | + |
| | 302 | + $memory = $entry[5] - $entry[3]; |
| | 303 | + $subcalls = $this->calltreeCount( $this->mStack, $index ); |
| | 304 | + |
| | 305 | + if( !preg_match( '/^-overhead/', $fname ) ){ |
| | 306 | + # Adjust for profiling overhead (except special values with elapsed=0 |
| | 307 | + if( $elapsed ) { |
| | 308 | + $elapsed -= $overheadInternal; |
| | 309 | + $elapsed -= ($subcalls * $overheadTotal); |
| | 310 | + $memory -= ($subcalls * $overheadMemory); |
| | 311 | + } |
| | 312 | + } |
| | 313 | + |
| | 314 | + if( !array_key_exists( $fname, $this->mCollated ) ){ |
| | 315 | + $this->mCollated[$fname] = 0; |
| | 316 | + $this->mCalls[$fname] = 0; |
| | 317 | + $this->mMemory[$fname] = 0; |
| | 318 | + $this->mMin[$fname] = 1 << 24; |
| | 319 | + $this->mMax[$fname] = 0; |
| | 320 | + $this->mOverhead[$fname] = 0; |
| | 321 | + } |
| | 322 | + |
| | 323 | + $this->mCollated[$fname] += $elapsed; |
| | 324 | + $this->mCalls[$fname]++; |
| | 325 | + $this->mMemory[$fname] += $memory; |
| | 326 | + $this->mMin[$fname] = min($this->mMin[$fname], $elapsed); |
| | 327 | + $this->mMax[$fname] = max($this->mMax[$fname], $elapsed); |
| | 328 | + $this->mOverhead[$fname] += $subcalls; |
| | 329 | + } |
| | 330 | + |
| | 331 | + $total = @$this->mCollated['-total']; |
| | 332 | + $this->mCalls['-overhead-total'] = $profileCount; |
| | 333 | + |
| | 334 | + # Output |
| | 335 | + arsort( $this->mCollated, SORT_NUMERIC ); |
| | 336 | + foreach( $this->mCollated as $fname => $elapsed ){ |
| | 337 | + $calls = $this->mCalls[$fname]; |
| | 338 | + $percent = $total ? 100. * $elapsed / $total : 0; |
| | 339 | + $memory = $this->mMemory[$fname]; |
| | 340 | + $prof .= sprintf($format, substr($fname, 0, $nameWidth), $calls, (float) ($elapsed * 1000), (float) ($elapsed * 1000) / $calls, $percent, $memory, ($this->mMin[$fname] * 1000.0), ($this->mMax[$fname] * 1000.0), $this->mOverhead[$fname]); |
| | 341 | + # Log to the DB |
| | 342 | + if( $wgProfileToDatabase ) { |
| | 343 | + self::logToDB($fname, (float) ($elapsed * 1000), $calls, (float) ($memory) ); |
| | 344 | + } |
| | 345 | + } |
| | 346 | + $prof .= "\nTotal: $total\n\n"; |
| | 347 | + |
| | 348 | + return $prof; |
| | 349 | + } |
| | 350 | + |
| | 351 | + /** |
| | 352 | + * Counts the number of profiled function calls sitting under |
| | 353 | + * the given point in the call graph. Not the most efficient algo. |
| | 354 | + * |
| | 355 | + * @param $stack Array: |
| | 356 | + * @param $start Integer: |
| | 357 | + * @return Integer |
| | 358 | + * @private |
| | 359 | + */ |
| | 360 | + function calltreeCount($stack, $start) { |
| | 361 | + $level = $stack[$start][1]; |
| | 362 | + $count = 0; |
| | 363 | + for ($i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i --) { |
| | 364 | + $count ++; |
| | 365 | + } |
| | 366 | + return $count; |
| | 367 | + } |
| | 368 | + |
| | 369 | + /** |
| | 370 | + * Log a function into the database. |
| | 371 | + * |
| | 372 | + * @param $name String: function name |
| | 373 | + * @param $timeSum Float |
| | 374 | + * @param $eventCount Integer: number of times that function was called |
| | 375 | + * @param $memorySum Integer: memory used by the function |
| | 376 | + */ |
| | 377 | + static function logToDB( $name, $timeSum, $eventCount, $memorySum ){ |
| | 378 | + # Do not log anything if database is readonly (bug 5375) |
| | 379 | + if( wfReadOnly() ) { return; } |
| | 380 | + |
| | 381 | + global $wgProfilePerHost; |
| | 382 | + |
| | 383 | + $dbw = wfGetDB( DB_MASTER ); |
| | 384 | + if( !is_object( $dbw ) ) |
| | 385 | + return false; |
| | 386 | + $errorState = $dbw->ignoreErrors( true ); |
| | 387 | + |
| | 388 | + $name = substr($name, 0, 255); |
| | 389 | + |
| | 390 | + if( $wgProfilePerHost ){ |
| | 391 | + $pfhost = wfHostname(); |
| | 392 | + } else { |
| | 393 | + $pfhost = ''; |
| | 394 | + } |
| | 395 | + |
| | 396 | + // Kludge |
| | 397 | + $timeSum = ($timeSum >= 0) ? $timeSum : 0; |
| | 398 | + $memorySum = ($memorySum >= 0) ? $memorySum : 0; |
| | 399 | + |
| | 400 | + $dbw->update( 'profiling', |
| | 401 | + array( |
| | 402 | + "pf_count=pf_count+{$eventCount}", |
| | 403 | + "pf_time=pf_time+{$timeSum}", |
| | 404 | + "pf_memory=pf_memory+{$memorySum}", |
| | 405 | + ), |
| | 406 | + array( |
| | 407 | + 'pf_name' => $name, |
| | 408 | + 'pf_server' => $pfhost, |
| | 409 | + ), |
| | 410 | + __METHOD__ ); |
| | 411 | + |
| | 412 | + |
| | 413 | + $rc = $dbw->affectedRows(); |
| | 414 | + if ($rc == 0) { |
| | 415 | + $dbw->insert('profiling', array ('pf_name' => $name, 'pf_count' => $eventCount, |
| | 416 | + 'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ), |
| | 417 | + __METHOD__, array ('IGNORE')); |
| | 418 | + } |
| | 419 | + // When we upgrade to mysql 4.1, the insert+update |
| | 420 | + // can be merged into just a insert with this construct added: |
| | 421 | + // "ON DUPLICATE KEY UPDATE ". |
| | 422 | + // "pf_count=pf_count + VALUES(pf_count), ". |
| | 423 | + // "pf_time=pf_time + VALUES(pf_time)"; |
| | 424 | + $dbw->ignoreErrors( $errorState ); |
| | 425 | + } |
| | 426 | + |
| | 427 | + /** |
| | 428 | + * Get the function name of the current profiling section |
| | 429 | + */ |
| | 430 | + function getCurrentSection() { |
| | 431 | + $elt = end( $this->mWorkStack ); |
| | 432 | + return $elt[0]; |
| | 433 | + } |
| | 434 | + |
| | 435 | + /** |
| | 436 | + * Get function caller |
| | 437 | + * |
| | 438 | + * @param $level Integer |
| | 439 | + */ |
| | 440 | + static function getCaller( $level ) { |
| | 441 | + $backtrace = wfDebugBacktrace(); |
| | 442 | + if ( isset( $backtrace[$level] ) ) { |
| | 443 | + if ( isset( $backtrace[$level]['class'] ) ) { |
| | 444 | + $caller = $backtrace[$level]['class'] . '::' . $backtrace[$level]['function']; |
| | 445 | + } else { |
| | 446 | + $caller = $backtrace[$level]['function']; |
| | 447 | + } |
| | 448 | + } else { |
| | 449 | + $caller = 'unknown'; |
| | 450 | + } |
| | 451 | + return $caller; |
| | 452 | + } |
| | 453 | + |
| | 454 | + /** |
| | 455 | + * Add an entry in the debug log file |
| | 456 | + * |
| | 457 | + * @param $s String to output |
| | 458 | + */ |
| | 459 | + function debug( $s ) { |
| | 460 | + if( function_exists( 'wfDebug' ) ) { |
| | 461 | + wfDebug( $s ); |
| | 462 | + } |
| | 463 | + } |
| | 464 | +} |
| Property changes on: trunk/phase3/includes/Profiler.php |
| ___________________________________________________________________ |
| Added: svn:eol-style |
| 1 | 465 | + native |
| Added: svn:keywords |
| 2 | 466 | + Author Date Id Revision |
| Index: trunk/phase3/includes/AutoLoader.php |
| — | — | @@ -183,10 +183,10 @@ |
| 184 | 184 | 'PoolCounterWork' => 'includes/PoolCounter.php', |
| 185 | 185 | 'Preferences' => 'includes/Preferences.php', |
| 186 | 186 | 'PrefixSearch' => 'includes/PrefixSearch.php', |
| 187 | | - 'Profiler' => 'includes/profiler/Profiler.php', |
| 188 | | - 'ProfilerSimple' => 'includes/profiler/ProfilerSimple.php', |
| 189 | | - 'ProfilerSimpleText' => 'includes/profiler/ProfilerSimpleText.php', |
| 190 | | - 'ProfilerSimpleUDP' => 'includes/profiler/ProfilerSimpleUDP.php', |
| | 187 | + 'Profiler' => 'includes/Profiler.php', |
| | 188 | + 'ProfilerSimple' => 'includes/ProfilerSimple.php', |
| | 189 | + 'ProfilerSimpleText' => 'includes/ProfilerSimpleText.php', |
| | 190 | + 'ProfilerSimpleUDP' => 'includes/ProfilerSimpleUDP.php', |
| 191 | 191 | 'ProtectionForm' => 'includes/ProtectionForm.php', |
| 192 | 192 | 'QueryPage' => 'includes/QueryPage.php', |
| 193 | 193 | 'QuickTemplate' => 'includes/SkinTemplate.php', |
| Index: trunk/phase3/includes/ProfilerSimpleTrace.php |
| — | — | @@ -0,0 +1,72 @@ |
| | 2 | +<?php |
| | 3 | +/** |
| | 4 | + * @file |
| | 5 | + * @ingroup Profiler |
| | 6 | + */ |
| | 7 | + |
| | 8 | +if ( !class_exists( 'ProfilerSimple' ) ) { |
| | 9 | + require_once(dirname(__FILE__).'/ProfilerSimple.php'); |
| | 10 | +} |
| | 11 | + |
| | 12 | +/** |
| | 13 | + * Execution trace |
| | 14 | + * @todo document methods (?) |
| | 15 | + * @ingroup Profiler |
| | 16 | + */ |
| | 17 | +class ProfilerSimpleTrace extends ProfilerSimple { |
| | 18 | + var $mMinimumTime = 0; |
| | 19 | + var $mProfileID = false; |
| | 20 | + var $trace = ""; |
| | 21 | + var $memory = 0; |
| | 22 | + |
| | 23 | + function __construct() { |
| | 24 | + global $wgRequestTime, $wgRUstart; |
| | 25 | + if (!empty($wgRequestTime) && !empty($wgRUstart)) { |
| | 26 | + $this->mWorkStack[] = array( '-total', 0, $wgRequestTime,$this->getCpuTime($wgRUstart)); |
| | 27 | + $elapsedcpu = $this->getCpuTime() - $this->getCpuTime($wgRUstart); |
| | 28 | + $elapsedreal = microtime(true) - $wgRequestTime; |
| | 29 | + } |
| | 30 | + $this->trace .= "Beginning trace: \n"; |
| | 31 | + } |
| | 32 | + |
| | 33 | + function profileIn($functionname) { |
| | 34 | + $this->mWorkStack[] = array($functionname, count( $this->mWorkStack ), microtime(true), $this->getCpuTime()); |
| | 35 | + $this->trace .= " " . sprintf("%6.1f",$this->memoryDiff()) . str_repeat( " ", count($this->mWorkStack)) . " > " . $functionname . "\n"; |
| | 36 | + } |
| | 37 | + |
| | 38 | + function profileOut($functionname) { |
| | 39 | + global $wgDebugFunctionEntry; |
| | 40 | + |
| | 41 | + if ($wgDebugFunctionEntry) { |
| | 42 | + $this->debug(str_repeat(' ', count($this->mWorkStack) - 1).'Exiting '.$functionname."\n"); |
| | 43 | + } |
| | 44 | + |
| | 45 | + list($ofname, /* $ocount */ ,$ortime,$octime) = array_pop($this->mWorkStack); |
| | 46 | + |
| | 47 | + if (!$ofname) { |
| | 48 | + $this->trace .= "Profiling error: $functionname\n"; |
| | 49 | + } else { |
| | 50 | + if ($functionname == 'close') { |
| | 51 | + $message = "Profile section ended by close(): {$ofname}"; |
| | 52 | + $functionname = $ofname; |
| | 53 | + $this->trace .= $message . "\n"; |
| | 54 | + } |
| | 55 | + elseif ($ofname != $functionname) { |
| | 56 | + $this->trace .= "Profiling error: in({$ofname}), out($functionname)"; |
| | 57 | + } |
| | 58 | + $elapsedcpu = $this->getCpuTime() - $octime; |
| | 59 | + $elapsedreal = microtime(true) - $ortime; |
| | 60 | + $this->trace .= sprintf("%03.6f %6.1f",$elapsedreal,$this->memoryDiff()) . str_repeat(" ",count($this->mWorkStack)+1) . " < " . $functionname . "\n"; |
| | 61 | + } |
| | 62 | + } |
| | 63 | + |
| | 64 | + function memoryDiff() { |
| | 65 | + $diff = memory_get_usage() - $this->memory; |
| | 66 | + $this->memory = memory_get_usage(); |
| | 67 | + return $diff/1024; |
| | 68 | + } |
| | 69 | + |
| | 70 | + function getOutput() { |
| | 71 | + print "<!-- \n {$this->trace} \n -->"; |
| | 72 | + } |
| | 73 | +} |
| Property changes on: trunk/phase3/includes/ProfilerSimpleTrace.php |
| ___________________________________________________________________ |
| Added: svn:eol-style |
| 1 | 74 | + native |
| Index: trunk/phase3/includes/ProfilerSimple.php |
| — | — | @@ -0,0 +1,130 @@ |
| | 2 | +<?php |
| | 3 | +/** |
| | 4 | + * @file |
| | 5 | + * @ingroup Profiler |
| | 6 | + */ |
| | 7 | + |
| | 8 | +if ( !class_exists( 'Profiler' ) ) { |
| | 9 | + require_once(dirname(__FILE__).'/Profiler.php'); |
| | 10 | +} |
| | 11 | + |
| | 12 | +/** |
| | 13 | + * Simple profiler base class. |
| | 14 | + * @todo document methods (?) |
| | 15 | + * @ingroup Profiler |
| | 16 | + */ |
| | 17 | +class ProfilerSimple extends Profiler { |
| | 18 | + var $mMinimumTime = 0; |
| | 19 | + var $mProfileID = false; |
| | 20 | + |
| | 21 | + function __construct() { |
| | 22 | + global $wgRequestTime, $wgRUstart; |
| | 23 | + if (!empty($wgRequestTime) && !empty($wgRUstart)) { |
| | 24 | + $this->mWorkStack[] = array( '-total', 0, $wgRequestTime,$this->getCpuTime($wgRUstart)); |
| | 25 | + |
| | 26 | + $elapsedcpu = $this->getCpuTime() - $this->getCpuTime($wgRUstart); |
| | 27 | + $elapsedreal = microtime(true) - $wgRequestTime; |
| | 28 | + |
| | 29 | + $entry =& $this->mCollated["-setup"]; |
| | 30 | + if (!is_array($entry)) { |
| | 31 | + $entry = array('cpu'=> 0.0, 'cpu_sq' => 0.0, 'real' => 0.0, 'real_sq' => 0.0, 'count' => 0); |
| | 32 | + $this->mCollated["-setup"] =& $entry; |
| | 33 | + } |
| | 34 | + $entry['cpu'] += $elapsedcpu; |
| | 35 | + $entry['cpu_sq'] += $elapsedcpu*$elapsedcpu; |
| | 36 | + $entry['real'] += $elapsedreal; |
| | 37 | + $entry['real_sq'] += $elapsedreal*$elapsedreal; |
| | 38 | + $entry['count']++; |
| | 39 | + } |
| | 40 | + } |
| | 41 | + |
| | 42 | + function setMinimum( $min ) { |
| | 43 | + $this->mMinimumTime = $min; |
| | 44 | + } |
| | 45 | + |
| | 46 | + function setProfileID( $id ) { |
| | 47 | + $this->mProfileID = $id; |
| | 48 | + } |
| | 49 | + |
| | 50 | + function getProfileID() { |
| | 51 | + if ( $this->mProfileID === false ) { |
| | 52 | + return wfWikiID(); |
| | 53 | + } else { |
| | 54 | + return $this->mProfileID; |
| | 55 | + } |
| | 56 | + } |
| | 57 | + |
| | 58 | + function profileIn($functionname) { |
| | 59 | + global $wgDebugFunctionEntry; |
| | 60 | + if ($wgDebugFunctionEntry) { |
| | 61 | + $this->debug(str_repeat(' ', count($this->mWorkStack)).'Entering '.$functionname."\n"); |
| | 62 | + } |
| | 63 | + $this->mWorkStack[] = array($functionname, count( $this->mWorkStack ), microtime(true), $this->getCpuTime()); |
| | 64 | + } |
| | 65 | + |
| | 66 | + function profileOut($functionname) { |
| | 67 | + global $wgDebugFunctionEntry; |
| | 68 | + |
| | 69 | + if ($wgDebugFunctionEntry) { |
| | 70 | + $this->debug(str_repeat(' ', count($this->mWorkStack) - 1).'Exiting '.$functionname."\n"); |
| | 71 | + } |
| | 72 | + |
| | 73 | + list($ofname, /* $ocount */ ,$ortime,$octime) = array_pop($this->mWorkStack); |
| | 74 | + |
| | 75 | + if (!$ofname) { |
| | 76 | + $this->debug("Profiling error: $functionname\n"); |
| | 77 | + } else { |
| | 78 | + if ($functionname == 'close') { |
| | 79 | + $message = "Profile section ended by close(): {$ofname}"; |
| | 80 | + $functionname = $ofname; |
| | 81 | + $this->debug( "$message\n" ); |
| | 82 | + $this->mCollated[$message] = array( |
| | 83 | + 'real' => 0.0, 'count' => 1); |
| | 84 | + } |
| | 85 | + elseif ($ofname != $functionname) { |
| | 86 | + $message = "Profiling error: in({$ofname}), out($functionname)"; |
| | 87 | + $this->debug( "$message\n" ); |
| | 88 | + $this->mCollated[$message] = array( |
| | 89 | + 'real' => 0.0, 'count' => 1); |
| | 90 | + } |
| | 91 | + $entry =& $this->mCollated[$functionname]; |
| | 92 | + $elapsedcpu = $this->getCpuTime() - $octime; |
| | 93 | + $elapsedreal = microtime(true) - $ortime; |
| | 94 | + if (!is_array($entry)) { |
| | 95 | + $entry = array('cpu'=> 0.0, 'cpu_sq' => 0.0, 'real' => 0.0, 'real_sq' => 0.0, 'count' => 0); |
| | 96 | + $this->mCollated[$functionname] =& $entry; |
| | 97 | + } |
| | 98 | + $entry['cpu'] += $elapsedcpu; |
| | 99 | + $entry['cpu_sq'] += $elapsedcpu*$elapsedcpu; |
| | 100 | + $entry['real'] += $elapsedreal; |
| | 101 | + $entry['real_sq'] += $elapsedreal*$elapsedreal; |
| | 102 | + $entry['count']++; |
| | 103 | + |
| | 104 | + } |
| | 105 | + } |
| | 106 | + |
| | 107 | + function getFunctionReport() { |
| | 108 | + /* Implement in output subclasses */ |
| | 109 | + } |
| | 110 | + |
| | 111 | + function getCpuTime($ru=null) { |
| | 112 | + if ( function_exists( 'getrusage' ) ) { |
| | 113 | + if ( $ru == null ) { |
| | 114 | + $ru = getrusage(); |
| | 115 | + } |
| | 116 | + return ($ru['ru_utime.tv_sec'] + $ru['ru_stime.tv_sec'] + ($ru['ru_utime.tv_usec'] + |
| | 117 | + $ru['ru_stime.tv_usec']) * 1e-6); |
| | 118 | + } else { |
| | 119 | + return 0; |
| | 120 | + } |
| | 121 | + } |
| | 122 | + |
| | 123 | + /* If argument is passed, it assumes that it is dual-format time string, returns proper float time value */ |
| | 124 | + function getTime($time=null) { |
| | 125 | + if ($time==null) { |
| | 126 | + return microtime(true); |
| | 127 | + } |
| | 128 | + list($a,$b)=explode(" ",$time); |
| | 129 | + return (float)($a+$b); |
| | 130 | + } |
| | 131 | +} |
| Property changes on: trunk/phase3/includes/ProfilerSimple.php |
| ___________________________________________________________________ |
| Added: svn:eol-style |
| 1 | 132 | + native |
| Added: svn:keywords |
| 2 | 133 | + Author Date Id Revision |
| Index: trunk/phase3/includes/ProfilerSimpleUDP.php |
| — | — | @@ -0,0 +1,41 @@ |
| | 2 | +<?php |
| | 3 | +/** |
| | 4 | + * @file |
| | 5 | + * @ingroup Profiler |
| | 6 | + */ |
| | 7 | + |
| | 8 | +require_once(dirname(__FILE__).'/ProfilerSimple.php'); |
| | 9 | + |
| | 10 | +/** |
| | 11 | + * ProfilerSimpleUDP class, that sends out messages for 'udpprofile' daemon |
| | 12 | + * (the one from mediawiki/trunk/udpprofile SVN ) |
| | 13 | + * @ingroup Profiler |
| | 14 | + */ |
| | 15 | +class ProfilerSimpleUDP extends ProfilerSimple { |
| | 16 | + function getFunctionReport() { |
| | 17 | + global $wgUDPProfilerHost, $wgUDPProfilerPort; |
| | 18 | + |
| | 19 | + if ( $this->mCollated['-total']['real'] < $this->mMinimumTime ) { |
| | 20 | + # Less than minimum, ignore |
| | 21 | + return; |
| | 22 | + } |
| | 23 | + |
| | 24 | + $sock = socket_create(AF_INET, SOCK_DGRAM, SOL_UDP); |
| | 25 | + $plength=0; |
| | 26 | + $packet=""; |
| | 27 | + foreach ($this->mCollated as $entry=>$pfdata) { |
| | 28 | + $pfline=sprintf ("%s %s %d %f %f %f %f %s\n", $this->getProfileID(),"-",$pfdata['count'], |
| | 29 | + $pfdata['cpu'],$pfdata['cpu_sq'],$pfdata['real'],$pfdata['real_sq'],$entry); |
| | 30 | + $length=strlen($pfline); |
| | 31 | + /* printf("<!-- $pfline -->"); */ |
| | 32 | + if ($length+$plength>1400) { |
| | 33 | + socket_sendto($sock,$packet,$plength,0,$wgUDPProfilerHost,$wgUDPProfilerPort); |
| | 34 | + $packet=""; |
| | 35 | + $plength=0; |
| | 36 | + } |
| | 37 | + $packet.=$pfline; |
| | 38 | + $plength+=$length; |
| | 39 | + } |
| | 40 | + socket_sendto($sock,$packet,$plength,0x100,$wgUDPProfilerHost,$wgUDPProfilerPort); |
| | 41 | + } |
| | 42 | +} |
| Property changes on: trunk/phase3/includes/ProfilerSimpleUDP.php |
| ___________________________________________________________________ |
| Added: svn:eol-style |
| 1 | 43 | + native |
| Added: svn:keywords |
| 2 | 44 | + Author Date Id Revision |