3 * Base class and functions for profiling.
5 * This program is free software; you can redistribute it and/or modify
6 * it under the terms of the GNU General Public License as published by
7 * the Free Software Foundation; either version 2 of the License, or
8 * (at your option) any later version.
10 * This program is distributed in the hope that it will be useful,
11 * but WITHOUT ANY WARRANTY; without even the implied warranty of
12 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
13 * GNU General Public License for more details.
15 * You should have received a copy of the GNU General Public License along
16 * with this program; if not, write to the Free Software Foundation, Inc.,
17 * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
18 * http://www.gnu.org/copyleft/gpl.html
22 * This file is only included if profiling is enabled
26 * @defgroup Profiler Profiler
30 * Begin profiling of a function
31 * @param string $functionname name of the function we will profile
33 function wfProfileIn( $functionname ) {
34 if ( Profiler
::$__instance === null ) { // use this directly to reduce overhead
37 if ( !( Profiler
::$__instance instanceof ProfilerStub
) ) {
38 Profiler
::$__instance->profileIn( $functionname );
43 * Stop profiling of a function
44 * @param string $functionname name of the function we have profiled
46 function wfProfileOut( $functionname = 'missing' ) {
47 if ( Profiler
::$__instance === null ) { // use this directly to reduce overhead
50 if ( !( Profiler
::$__instance instanceof ProfilerStub
) ) {
51 Profiler
::$__instance->profileOut( $functionname );
56 * Class for handling function-scope profiling
60 class ProfileSection
{
61 protected $name; // string; method name
62 protected $enabled = false; // boolean; whether profiling is enabled
65 * Begin profiling of a function and return an object that ends profiling of
66 * the function when that object leaves scope. As long as the object is not
67 * specifically linked to other objects, it will fall out of scope at the same
68 * moment that the function to be profiled terminates.
70 * This is typically called like:
71 * <code>$section = new ProfileSection( __METHOD__ );</code>
73 * @param string $name Name of the function to profile
75 public function __construct( $name ) {
77 if ( Profiler
::$__instance === null ) { // use this directly to reduce overhead
80 if ( !( Profiler
::$__instance instanceof ProfilerStub
) ) {
81 $this->enabled
= true;
82 Profiler
::$__instance->profileIn( $this->name
);
86 function __destruct() {
87 if ( $this->enabled
) {
88 Profiler
::$__instance->profileOut( $this->name
);
98 /** @var array List of resolved profile calls with start/end data */
99 protected $mStack = array();
100 /** @var array Queue of open profile calls with start data */
101 protected $mWorkStack = array();
103 /** @var array Map of (function name => aggregate data array) */
104 protected $mCollated = array();
106 protected $mCollateDone = false;
108 protected $mCollateOnly = false;
109 /** @var array Cache of a standard broken collation entry */
110 protected $mErrorEntry;
112 /** @var string wall|cpu|user */
113 protected $mTimeMetric = 'wall';
114 /** @var string|bool Profiler ID for bucketing data */
115 protected $mProfileID = false;
116 /** @var bool Whether MediaWiki is in a SkinTemplate output context */
117 protected $mTemplated = false;
119 /** @var float seconds */
120 protected $mDBLockThreshold = 5.0;
121 /** @var array DB/server name => (active trx count,timestamp) */
122 protected $mDBTrxHoldingLocks = array();
123 /** @var array DB/server name => list of (function name, elapsed time) */
124 protected $mDBTrxMethodTimes = array();
127 public static $__instance = null; // do not call this outside Profiler and ProfileSection
130 * @param array $params
132 public function __construct( array $params ) {
133 if ( isset( $params['timeMetric'] ) ) {
134 $this->mTimeMetric
= $params['timeMetric'];
136 if ( isset( $params['profileID'] ) ) {
137 $this->mProfileID
= $params['profileID'];
140 $this->mCollateOnly
= $this->collateOnly();
142 $this->addInitialStack();
149 public static function instance() {
150 if ( self
::$__instance === null ) {
152 if ( is_array( $wgProfiler ) ) {
153 if ( !isset( $wgProfiler['class'] ) ) {
154 $class = 'ProfilerStub';
156 $class = $wgProfiler['class'];
158 self
::$__instance = new $class( $wgProfiler );
159 } elseif ( $wgProfiler instanceof Profiler
) {
160 self
::$__instance = $wgProfiler; // back-compat
162 self
::$__instance = new ProfilerStub( $wgProfiler );
165 return self
::$__instance;
169 * Set the profiler to a specific profiler instance. Mostly for dumpHTML
172 public static function setInstance( Profiler
$p ) {
173 self
::$__instance = $p;
177 * Return whether this a stub profiler
181 public function isStub() {
186 * Return whether this profiler stores data
188 * @see Profiler::logData()
191 public function isPersistent() {
198 public function setProfileID( $id ) {
199 $this->mProfileID
= $id;
205 public function getProfileID() {
206 if ( $this->mProfileID
=== false ) {
209 return $this->mProfileID
;
214 * Whether to internally just track aggregates and ignore the full stack trace
218 protected function collateOnly() {
223 * Add the inital item in the stack.
225 protected function addInitialStack() {
226 $this->mErrorEntry
= $this->getErrorEntry();
228 $initialTime = $this->getInitialTime( 'wall' );
229 $initialCpu = $this->getInitialTime( 'cpu' );
230 if ( $initialTime !== null && $initialCpu !== null ) {
231 $this->mWorkStack
[] = array( '-total', 0, $initialTime, $initialCpu, 0 );
232 if ( $this->mCollateOnly
) {
233 $this->mWorkStack
[] = array( '-setup', 1, $initialTime, $initialCpu, 0 );
234 $this->profileOut( '-setup' );
236 $this->mStack
[] = array( '-setup', 1, $initialTime, $initialCpu, 0,
237 $this->getTime( 'wall' ), $this->getTime( 'cpu' ), 0 );
240 $this->profileIn( '-total' );
245 * @return array Initial collation entry
247 protected function getZeroEntry() {
259 'periods' => array(), // not filled if mCollateOnly
260 'overhead' => 0 // not filled if mCollateOnly
265 * @return array Initial collation entry for errors
267 protected function getErrorEntry() {
268 $entry = $this->getZeroEntry();
274 * Update the collation entry for a given method name
276 * @param string $name
277 * @param float $elapsedCpu
278 * @param float $elapsedReal
279 * @param int $memChange
280 * @param int $subcalls
281 * @param array|null $period Map of ('start','end','memory','subcalls')
283 protected function updateEntry(
284 $name, $elapsedCpu, $elapsedReal, $memChange, $subcalls = 0, $period = null
286 $entry =& $this->mCollated
[$name];
287 if ( !is_array( $entry ) ) {
288 $entry = $this->getZeroEntry();
289 $this->mCollated
[$name] =& $entry;
291 $entry['cpu'] +
= $elapsedCpu;
292 $entry['cpu_sq'] +
= $elapsedCpu * $elapsedCpu;
293 $entry['real'] +
= $elapsedReal;
294 $entry['real_sq'] +
= $elapsedReal * $elapsedReal;
295 $entry['memory'] +
= $memChange > 0 ?
$memChange : 0;
297 $entry['min_cpu'] = $elapsedCpu < $entry['min_cpu'] ?
$elapsedCpu : $entry['min_cpu'];
298 $entry['max_cpu'] = $elapsedCpu > $entry['max_cpu'] ?
$elapsedCpu : $entry['max_cpu'];
299 $entry['min_real'] = $elapsedReal < $entry['min_real'] ?
$elapsedReal : $entry['min_real'];
300 $entry['max_real'] = $elapsedReal > $entry['max_real'] ?
$elapsedReal : $entry['max_real'];
301 // Apply optional fields
302 $entry['overhead'] +
= $subcalls;
304 $entry['periods'][] = $period;
309 * Called by wfProfieIn()
311 * @param string $functionname
313 public function profileIn( $functionname ) {
314 global $wgDebugFunctionEntry;
316 if ( $wgDebugFunctionEntry ) {
317 $this->debug( str_repeat( ' ', count( $this->mWorkStack
) ) .
318 'Entering ' . $functionname . "\n" );
321 $this->mWorkStack
[] = array(
323 count( $this->mWorkStack
),
324 $this->getTime( 'time' ),
325 $this->getTime( 'cpu' ),
331 * Called by wfProfieOut()
333 * @param string $functionname
335 public function profileOut( $functionname ) {
336 global $wgDebugFunctionEntry;
338 if ( $wgDebugFunctionEntry ) {
339 $this->debug( str_repeat( ' ', count( $this->mWorkStack
) - 1 ) .
340 'Exiting ' . $functionname . "\n" );
343 $item = array_pop( $this->mWorkStack
);
344 list( $ofname, /* $ocount */, $ortime, $octime, $omem ) = $item;
346 if ( $item === null ) {
347 $this->debugGroup( 'profileerror', "Profiling error: $functionname" );
349 if ( $functionname === 'close' ) {
350 if ( $ofname !== '-total' ) {
351 $message = "Profile section ended by close(): {$ofname}";
352 $this->debugGroup( 'profileerror', $message );
353 if ( $this->mCollateOnly
) {
354 $this->mCollated
[$message] = $this->mErrorEntry
;
356 $this->mStack
[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 );
359 $functionname = $ofname;
360 } elseif ( $ofname !== $functionname ) {
361 $message = "Profiling error: in({$ofname}), out($functionname)";
362 $this->debugGroup( 'profileerror', $message );
363 if ( $this->mCollateOnly
) {
364 $this->mCollated
[$message] = $this->mErrorEntry
;
366 $this->mStack
[] = array( $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 );
369 $realTime = $this->getTime( 'wall' );
370 $cpuTime = $this->getTime( 'cpu' );
371 if ( $this->mCollateOnly
) {
372 $elapsedcpu = $cpuTime - $octime;
373 $elapsedreal = $realTime - $ortime;
374 $memchange = memory_get_usage() - $omem;
375 $this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
377 $this->mStack
[] = array_merge( $item,
378 array( $realTime, $cpuTime, memory_get_usage() ) );
380 $this->updateTrxProfiling( $functionname, $realTime - $ortime );
385 * Close opened profiling sections
387 public function close() {
388 while ( count( $this->mWorkStack
) ) {
389 $this->profileOut( 'close' );
394 * Log the data to some store or even the page output
396 public function logData() {
397 /* Implement in subclasses */
401 * Mark a DB as in a transaction with one or more writes pending
403 * Note that there can be multiple connections to a single DB.
405 * @param string $server DB server
406 * @param string $db DB name
408 public function transactionWritingIn( $server, $db ) {
409 $name = "{$server} ({$db})";
410 if ( isset( $this->mDBTrxHoldingLocks
[$name] ) ) {
411 ++
$this->mDBTrxHoldingLocks
[$name]['refs'];
413 $this->mDBTrxHoldingLocks
[$name] = array( 'refs' => 1, 'start' => microtime( true ) );
414 $this->mDBTrxMethodTimes
[$name] = array();
419 * Register the name and time of a method for slow DB trx detection
421 * @param string $method Function name
422 * @param float $realtime Wal time ellapsed
424 protected function updateTrxProfiling( $method, $realtime ) {
425 if ( !$this->mDBTrxHoldingLocks
) {
426 return; // short-circuit
427 // @TODO: hardcoded check is a tad janky (what about FOR UPDATE?)
428 } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
429 && $realtime < $this->mDBLockThreshold
431 return; // not a DB master query nor slow enough
433 $now = microtime( true );
434 foreach ( $this->mDBTrxHoldingLocks
as $name => $info ) {
435 // Hacky check to exclude entries from before the first TRX write
436 if ( ( $now - $realtime ) >= $info['start'] ) {
437 $this->mDBTrxMethodTimes
[$name][] = array( $method, $realtime );
443 * Mark a DB as no longer in a transaction
445 * This will check if locks are possibly held for longer than
446 * needed and log any affected transactions to a special DB log.
447 * Note that there can be multiple connections to a single DB.
449 * @param string $server DB server
450 * @param string $db DB name
452 public function transactionWritingOut( $server, $db ) {
453 $name = "{$server} ({$db})";
454 if ( --$this->mDBTrxHoldingLocks
[$name]['refs'] <= 0 ) {
456 foreach ( $this->mDBTrxMethodTimes
[$name] as $info ) {
457 list( $method, $realtime ) = $info;
458 if ( $realtime >= $this->mDBLockThreshold
) {
464 $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks
) );
465 $msg = "Sub-optimal transaction on DB(s) {$dbs}:\n";
466 foreach ( $this->mDBTrxMethodTimes
[$name] as $i => $info ) {
467 list( $method, $realtime ) = $info;
468 $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
470 $this->debugGroup( 'DBPerformance', $msg );
472 unset( $this->mDBTrxHoldingLocks
[$name] );
473 unset( $this->mDBTrxMethodTimes
[$name] );
478 * Mark this call as templated or not
482 public function setTemplated( $t ) {
483 $this->mTemplated
= $t;
487 * Returns a profiling output to be stored in debug file
491 public function getOutput() {
492 global $wgDebugFunctionEntry, $wgProfileCallTree;
494 $wgDebugFunctionEntry = false; // hack
496 if ( !count( $this->mStack
) && !count( $this->mCollated
) ) {
497 return "No profiling output\n";
500 if ( $wgProfileCallTree ) {
501 return $this->getCallTree();
503 return $this->getFunctionReport();
508 * Returns a tree of function call instead of a list of functions
511 protected function getCallTree() {
512 return implode( '', array_map(
513 array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack
)
518 * Recursive function the format the current profiling array into a tree
520 * @param array $stack profiling array
523 protected function remapCallTree( array $stack ) {
524 if ( count( $stack ) < 2 ) {
528 for ( $max = count( $stack ) - 1; $max > 0; ) {
529 /* Find all items under this entry */
530 $level = $stack[$max][1];
532 for ( $i = $max -1; $i >= 0; $i-- ) {
533 if ( $stack[$i][1] > $level ) {
534 $working[] = $stack[$i];
539 $working = $this->remapCallTree( array_reverse( $working ) );
541 foreach ( $working as $item ) {
542 array_push( $output, $item );
544 array_unshift( $output, $stack[$max] );
547 array_unshift( $outputs, $output );
550 foreach ( $outputs as $output ) {
551 foreach ( $output as $item ) {
559 * Callback to get a formatted line for the call tree
562 protected function getCallTreeLine( $entry ) {
563 list( $fname, $level, $startreal, , , $endreal ) = $entry;
564 $delta = $endreal - $startreal;
565 $space = str_repeat( ' ', $level );
566 # The ugly double sprintf is to work around a PHP bug,
567 # which has been fixed in recent releases.
568 return sprintf( "%10s %s %s\n",
569 trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
573 * Get the initial time of the request, based either on $wgRequestTime or
574 * $wgRUstart. Will return null if not able to find data.
576 * @param string|false $metric Metric to use, with the following possibilities:
577 * - user: User CPU time (without system calls)
578 * - cpu: Total CPU time (user and system calls)
579 * - wall (or any other string): elapsed time
580 * - false (default): will fall back to default metric
583 protected function getTime( $metric = false ) {
584 if ( $metric === false ) {
585 $metric = $this->mTimeMetric
;
588 if ( $metric === 'cpu' ||
$this->mTimeMetric
=== 'user' ) {
589 if ( !function_exists( 'getrusage' ) ) {
593 $time = $ru['ru_utime.tv_sec'] +
$ru['ru_utime.tv_usec'] / 1e6
;
594 if ( $metric === 'cpu' ) {
595 # This is the time of system calls, added to the user time
596 # it gives the total CPU time
597 $time +
= $ru['ru_stime.tv_sec'] +
$ru['ru_stime.tv_usec'] / 1e6
;
601 return microtime( true );
606 * Get the initial time of the request, based either on $wgRequestTime or
607 * $wgRUstart. Will return null if not able to find data.
609 * @param string|false $metric Metric to use, with the following possibilities:
610 * - user: User CPU time (without system calls)
611 * - cpu: Total CPU time (user and system calls)
612 * - wall (or any other string): elapsed time
613 * - false (default): will fall back to default metric
616 protected function getInitialTime( $metric = false ) {
617 global $wgRequestTime, $wgRUstart;
619 if ( $metric === false ) {
620 $metric = $this->mTimeMetric
;
623 if ( $metric === 'cpu' ||
$this->mTimeMetric
=== 'user' ) {
624 if ( !count( $wgRUstart ) ) {
628 $time = $wgRUstart['ru_utime.tv_sec'] +
$wgRUstart['ru_utime.tv_usec'] / 1e6
;
629 if ( $metric === 'cpu' ) {
630 # This is the time of system calls, added to the user time
631 # it gives the total CPU time
632 $time +
= $wgRUstart['ru_stime.tv_sec'] +
$wgRUstart['ru_stime.tv_usec'] / 1e6
;
636 if ( empty( $wgRequestTime ) ) {
639 return $wgRequestTime;
647 protected function collateData() {
648 if ( $this->mCollateDone
) {
651 $this->mCollateDone
= true;
652 $this->close(); // set "-total" entry
654 if ( $this->mCollateOnly
) {
655 return; // already collated as methods exited
658 $this->mCollated
= array();
660 # Estimate profiling overhead
661 $profileCount = count( $this->mStack
);
662 self
::calculateOverhead( $profileCount );
664 # First, subtract the overhead!
665 $overheadTotal = $overheadMemory = $overheadInternal = array();
666 foreach ( $this->mStack
as $entry ) {
667 // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
669 $elapsed = $entry[5] - $entry[2];
670 $memchange = $entry[7] - $entry[4];
672 if ( $fname === '-overhead-total' ) {
673 $overheadTotal[] = $elapsed;
674 $overheadMemory[] = max( 0, $memchange );
675 } elseif ( $fname === '-overhead-internal' ) {
676 $overheadInternal[] = $elapsed;
679 $overheadTotal = $overheadTotal ?
680 array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
681 $overheadMemory = $overheadMemory ?
682 array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
683 $overheadInternal = $overheadInternal ?
684 array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
687 foreach ( $this->mStack
as $index => $entry ) {
688 // $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
690 $elapsedCpu = $entry[6] - $entry[3];
691 $elapsedReal = $entry[5] - $entry[2];
692 $memchange = $entry[7] - $entry[4];
693 $subcalls = $this->calltreeCount( $this->mStack
, $index );
695 if ( substr( $fname, 0, 9 ) !== '-overhead' ) {
696 # Adjust for profiling overhead (except special values with elapsed=0
698 $elapsed -= $overheadInternal;
699 $elapsed -= ( $subcalls * $overheadTotal );
700 $memchange -= ( $subcalls * $overheadMemory );
704 $period = array( 'start' => $entry[2], 'end' => $entry[5],
705 'memory' => $memchange, 'subcalls' => $subcalls );
706 $this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange, $subcalls, $period );
709 $this->mCollated
['-overhead-total']['count'] = $profileCount;
710 arsort( $this->mCollated
, SORT_NUMERIC
);
714 * Returns a list of profiled functions.
718 protected function getFunctionReport() {
719 $this->collateData();
722 $nameWidth = $width - 65;
723 $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d (%13.3f -%13.3f) [%d]\n";
724 $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
725 $prof = "\nProfiling data\n";
726 $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );
728 $total = isset( $this->mCollated
['-total'] )
729 ?
$this->mCollated
['-total']['real']
732 foreach ( $this->mCollated
as $fname => $data ) {
733 $calls = $data['count'];
734 $percent = $total ?
100 * $data['real'] / $total : 0;
735 $memory = $data['memory'];
736 $prof .= sprintf( $format,
737 substr( $fname, 0, $nameWidth ),
739 (float)( $data['real'] * 1000 ),
740 (float)( $data['real'] * 1000 ) / $calls,
743 ( $data['min_real'] * 1000.0 ),
744 ( $data['max_real'] * 1000.0 ),
748 $prof .= "\nTotal: $total\n\n";
756 public function getRawData() {
757 // This method is called before shutdown in the footer method on Skins.
758 // If some outer methods have not yet called wfProfileOut(), work around
759 // that by clearing anything in the work stack to just the "-total" entry.
760 // Collate after doing this so the results do not include profile errors.
761 if ( count( $this->mWorkStack
) > 1 ) {
762 $oldWorkStack = $this->mWorkStack
;
763 $this->mWorkStack
= array( $this->mWorkStack
[0] ); // just the "-total" one
765 $oldWorkStack = null;
767 $this->collateData();
768 // If this trick is used, then the old work stack is swapped back afterwards
769 // and mCollateDone is reset to false. This means that logData() will still
770 // make use of all the method data since the missing wfProfileOut() calls
771 // should be made by the time it is called.
772 if ( $oldWorkStack ) {
773 $this->mWorkStack
= $oldWorkStack;
774 $this->mCollateDone
= false;
777 $total = isset( $this->mCollated
['-total'] )
778 ?
$this->mCollated
['-total']['real']
782 foreach ( $this->mCollated
as $fname => $data ) {
784 foreach ( $data['periods'] as $period ) {
785 $period['start'] *= 1000;
786 $period['end'] *= 1000;
787 $periods[] = $period;
791 'calls' => $data['count'],
792 'elapsed' => $data['real'] * 1000,
793 'percent' => $total ?
100 * $data['real'] / $total : 0,
794 'memory' => $data['memory'],
795 'min' => $data['min_real'] * 1000,
796 'max' => $data['max_real'] * 1000,
797 'overhead' => $data['overhead'],
798 'periods' => $periods
806 * Dummy calls to wfProfileIn/wfProfileOut to calculate its overhead
808 * @param int $profileCount
810 protected static function calculateOverhead( $profileCount ) {
811 wfProfileIn( '-overhead-total' );
812 for ( $i = 0; $i < $profileCount; $i++
) {
813 wfProfileIn( '-overhead-internal' );
814 wfProfileOut( '-overhead-internal' );
816 wfProfileOut( '-overhead-total' );
820 * Counts the number of profiled function calls sitting under
821 * the given point in the call graph. Not the most efficient algo.
823 * @param array $stack
827 protected function calltreeCount( $stack, $start ) {
828 $level = $stack[$start][1];
830 for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
837 * Add an entry in the debug log file
839 * @param string $s String to output
841 protected function debug( $s ) {
842 if ( function_exists( 'wfDebug' ) ) {
848 * Add an entry in the debug log group
850 * @param string $group Group to send the message to
851 * @param string $s String to output
853 protected function debugGroup( $group, $s ) {
854 if ( function_exists( 'wfDebugLog' ) ) {
855 wfDebugLog( $group, $s );
860 * Get the content type sent out to the client.
861 * Used for profilers that output instead of store data.
864 protected function getContentType() {
865 foreach ( headers_list() as $header ) {
866 if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {