Profiler.php

Go to the documentation of this file.

<?php
function wfProfileIn( $functionname ) {
    if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
        Profiler::instance();
    }
    if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
        Profiler::$__instance->profileIn( $functionname );
    }
}

function wfProfileOut( $functionname = 'missing' ) {
    if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
        Profiler::instance();
    }
    if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
        Profiler::$__instance->profileOut( $functionname );
    }
}

class ProfileSection {
    protected $name; // string; method name
    protected $enabled = false; // boolean; whether profiling is enabled

    public function __construct( $name ) {
        $this->name = $name;
        if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
            Profiler::instance();
        }
        if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
            $this->enabled = true;
            Profiler::$__instance->profileIn( $this->name );
        }
    }

    function __destruct() {
        if ( $this->enabled ) {
            Profiler::$__instance->profileOut( $this->name );
        }
    }
}

class Profiler {
    protected $mStack = array(), $mWorkStack = array(), $mCollated = array(),
        $mCalls = array(), $mTotals = array(), $mPeriods = array();
    protected $mTimeMetric = 'wall';
    protected $mProfileID = false, $mCollateDone = false, $mTemplated = false;

    protected $mDBLockThreshold = 5.0; // float; seconds
    protected $mDBTrxHoldingLocks = array();
    protected $mDBTrxMethodTimes = array();

    public static $__instance = null; // do not call this outside Profiler and ProfileSection

    function __construct( $params ) {
        if ( isset( $params['timeMetric'] ) ) {
            $this->mTimeMetric = $params['timeMetric'];
        }
        if ( isset( $params['profileID'] ) ) {
            $this->mProfileID = $params['profileID'];
        }

        $this->addInitialStack();
    }

    public static function instance() {
        if ( self::$__instance === null ) {
            global $wgProfiler;
            if ( is_array( $wgProfiler ) ) {
                if ( !isset( $wgProfiler['class'] ) ) {
                    $class = 'ProfilerStub';
                } else {
                    $class = $wgProfiler['class'];
                }
                self::$__instance = new $class( $wgProfiler );
            } elseif ( $wgProfiler instanceof Profiler ) {
                self::$__instance = $wgProfiler; // back-compat
            } else {
                self::$__instance = new ProfilerStub( $wgProfiler );
            }
        }
        return self::$__instance;
    }

    public static function setInstance( Profiler $p ) {
        self::$__instance = $p;
    }

    public function isStub() {
        return false;
    }

    public function isPersistent() {
        return true;
    }

    public function setProfileID( $id ) {
        $this->mProfileID = $id;
    }

    public function getProfileID() {
        if ( $this->mProfileID === false ) {
            return wfWikiID();
        } else {
            return $this->mProfileID;
        }
    }

    protected function addInitialStack() {
        // Push an entry for the pre-profile setup time onto the stack
        $initial = $this->getInitialTime();
        if ( $initial !== null ) {
            $this->mWorkStack[] = array( '-total', 0, $initial, 0 );
            $this->mStack[] = array( '-setup', 1, $initial, 0, $this->getTime(), 0 );
        } else {
            $this->profileIn( '-total' );
        }
    }

    public function profileIn( $functionname ) {
        global $wgDebugFunctionEntry;
        if ( $wgDebugFunctionEntry ) {
            $this->debug( str_repeat( ' ', count( $this->mWorkStack ) ) . 'Entering ' . $functionname . "\n" );
        }

        $this->mWorkStack[] = array( $functionname, count( $this->mWorkStack ), $this->getTime(), memory_get_usage() );
    }

    public function profileOut( $functionname ) {
        global $wgDebugFunctionEntry;
        $memory = memory_get_usage();
        $time = $this->getTime();

        if ( $wgDebugFunctionEntry ) {
            $this->debug( str_repeat( ' ', count( $this->mWorkStack ) - 1 ) . 'Exiting ' . $functionname . "\n" );
        }

        $bit = array_pop( $this->mWorkStack );

        if ( !$bit ) {
            $this->debugGroup( 'profileerror', "Profiling error, !\$bit: $functionname" );
        } else {
            if ( $functionname == 'close' ) {
                if ( $bit[0] != '-total' ) {
                    $message = "Profile section ended by close(): {$bit[0]}";
                    $this->debugGroup( 'profileerror', $message );
                    $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 );
                }
            } elseif ( $bit[0] != $functionname ) {
                $message = "Profiling error: in({$bit[0]}), out($functionname)";
                $this->debugGroup( 'profileerror', $message );
                $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 );
            }
            $bit[] = $time;
            $bit[] = $memory;
            $this->mStack[] = $bit;
            $this->updateTrxProfiling( $functionname, $time );
        }
    }

    public function close() {
        while ( count( $this->mWorkStack ) ) {
            $this->profileOut( 'close' );
        }
    }

    public function transactionWritingIn( $server, $db ) {
        $name = "{$server} ({$db})";
        if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
            ++$this->mDBTrxHoldingLocks[$name]['refs'];
        } else {
            $this->mDBTrxHoldingLocks[$name] = array( 'refs' => 1, 'start' => microtime( true ) );
            $this->mDBTrxMethodTimes[$name] = array();
        }
    }

    protected function updateTrxProfiling( $method, $realtime ) {
        if ( !$this->mDBTrxHoldingLocks ) {
            return; // short-circuit
        // @TODO: hardcoded check is a tad janky (what about FOR UPDATE?)
        } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
            && $realtime < $this->mDBLockThreshold
        ) {
            return; // not a DB master query nor slow enough
        }
        $now = microtime( true );
        foreach ( $this->mDBTrxHoldingLocks as $name => $info ) {
            // Hacky check to exclude entries from before the first TRX write
            if ( ( $now - $realtime ) >= $info['start'] ) {
                $this->mDBTrxMethodTimes[$name][] = array( $method, $realtime );
            }
        }
    }

    public function transactionWritingOut( $server, $db ) {
        $name = "{$server} ({$db})";
        if ( --$this->mDBTrxHoldingLocks[$name]['refs'] <= 0 ) {
            $slow = false;
            foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
                list( $method, $realtime ) = $info;
                if ( $realtime >= $this->mDBLockThreshold ) {
                    $slow = true;
                    break;
                }
            }
            if ( $slow ) {
                $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks ) );
                $msg = "Sub-optimal transaction on DB(s) {$dbs}:\n";
                foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) {
                    list( $method, $realtime ) = $info;
                    $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
                }
                $this->debugGroup( 'DBPerformance', $msg );
            }
            unset( $this->mDBTrxHoldingLocks[$name] );
            unset( $this->mDBTrxMethodTimes[$name] );
        }
    }

    function setTemplated( $t ) {
        $this->mTemplated = $t;
    }

    public function getOutput() {
        global $wgDebugFunctionEntry, $wgProfileCallTree;
        $wgDebugFunctionEntry = false;

        if ( !count( $this->mStack ) && !count( $this->mCollated ) ) {
            return "No profiling output\n";
        }

        if ( $wgProfileCallTree ) {
            return $this->getCallTree();
        } else {
            return $this->getFunctionReport();
        }
    }

    function getCallTree() {
        return implode( '', array_map( array( &$this, 'getCallTreeLine' ), $this->remapCallTree( $this->mStack ) ) );
    }

    function remapCallTree( $stack ) {
        if ( count( $stack ) < 2 ) {
            return $stack;
        }
        $outputs = array();
        for ( $max = count( $stack ) - 1; $max > 0; ) {
            /* Find all items under this entry */
            $level = $stack[$max][1];
            $working = array();
            for ( $i = $max -1; $i >= 0; $i-- ) {
                if ( $stack[$i][1] > $level ) {
                    $working[] = $stack[$i];
                } else {
                    break;
                }
            }
            $working = $this->remapCallTree( array_reverse( $working ) );
            $output = array();
            foreach ( $working as $item ) {
                array_push( $output, $item );
            }
            array_unshift( $output, $stack[$max] );
            $max = $i;

            array_unshift( $outputs, $output );
        }
        $final = array();
        foreach ( $outputs as $output ) {
            foreach ( $output as $item ) {
                $final[] = $item;
            }
        }
        return $final;
    }

    function getCallTreeLine( $entry ) {
        list( $fname, $level, $start, /* $x */, $end ) = $entry;
        $delta = $end - $start;
        $space = str_repeat( ' ', $level );
        # The ugly double sprintf is to work around a PHP bug,
        # which has been fixed in recent releases.
        return sprintf( "%10s %s %s\n", trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
    }

    function getTime( $metric = false ) {
        if ( $metric === false ) {
            $metric = $this->mTimeMetric;
        }

        if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) {
            if ( !function_exists( 'getrusage' ) ) {
                return 0;
            }
            $ru = getrusage();
            $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
            if ( $metric === 'cpu' ) {
                # This is the time of system calls, added to the user time
                # it gives the total CPU time
                $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
            }
            return $time;
        } else {
            return microtime( true );
        }
    }

    protected function getInitialTime( $metric = false ) {
        global $wgRequestTime, $wgRUstart;

        if ( $metric === false ) {
            $metric = $this->mTimeMetric;
        }

        if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) {
            if ( !count( $wgRUstart ) ) {
                return null;
            }

            $time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
            if ( $metric === 'cpu' ) {
                # This is the time of system calls, added to the user time
                # it gives the total CPU time
                $time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
            }
            return $time;
        } else {
            if ( empty( $wgRequestTime ) ) {
                return null;
            } else {
                return $wgRequestTime;
            }
        }
    }

    protected function collateData() {
        if ( $this->mCollateDone ) {
            return;
        }
        $this->mCollateDone = true;

        $this->close();

        $this->mCollated = array();
        $this->mCalls = array();
        $this->mMemory = array();

        # Estimate profiling overhead
        $profileCount = count( $this->mStack );
        self::calculateOverhead( $profileCount );

        # First, subtract the overhead!
        $overheadTotal = $overheadMemory = $overheadInternal = array();
        foreach ( $this->mStack as $entry ) {
            $fname = $entry[0];
            $start = $entry[2];
            $end = $entry[4];
            $elapsed = $end - $start;
            $memory = $entry[5] - $entry[3];

            if ( $fname == '-overhead-total' ) {
                $overheadTotal[] = $elapsed;
                $overheadMemory[] = $memory;
            } elseif ( $fname == '-overhead-internal' ) {
                $overheadInternal[] = $elapsed;
            }
        }
        $overheadTotal = $overheadTotal ? array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
        $overheadMemory = $overheadMemory ? array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
        $overheadInternal = $overheadInternal ? array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;

        # Collate
        foreach ( $this->mStack as $index => $entry ) {
            $fname = $entry[0];
            $start = $entry[2];
            $end = $entry[4];
            $elapsed = $end - $start;

            $memory = $entry[5] - $entry[3];
            $subcalls = $this->calltreeCount( $this->mStack, $index );

            if ( !preg_match( '/^-overhead/', $fname ) ) {
                # Adjust for profiling overhead (except special values with elapsed=0
                if ( $elapsed ) {
                    $elapsed -= $overheadInternal;
                    $elapsed -= ( $subcalls * $overheadTotal );
                    $memory -= ( $subcalls * $overheadMemory );
                }
            }

            if ( !array_key_exists( $fname, $this->mCollated ) ) {
                $this->mCollated[$fname] = 0;
                $this->mCalls[$fname] = 0;
                $this->mMemory[$fname] = 0;
                $this->mMin[$fname] = 1 << 24;
                $this->mMax[$fname] = 0;
                $this->mOverhead[$fname] = 0;
                $this->mPeriods[$fname] = array();
            }

            $this->mCollated[$fname] += $elapsed;
            $this->mCalls[$fname]++;
            $this->mMemory[$fname] += $memory;
            $this->mMin[$fname] = min( $this->mMin[$fname], $elapsed );
            $this->mMax[$fname] = max( $this->mMax[$fname], $elapsed );
            $this->mOverhead[$fname] += $subcalls;
            $this->mPeriods[$fname][] = compact( 'start', 'end', 'memory', 'subcalls' );
        }

        $this->mCalls['-overhead-total'] = $profileCount;
        arsort( $this->mCollated, SORT_NUMERIC );
    }

    function getFunctionReport() {
        $this->collateData();

        $width = 140;
        $nameWidth = $width - 65;
        $format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d  (%13.3f -%13.3f) [%d]\n";
        $titleFormat = "%-{$nameWidth}s %6s %13s %13s %13s %9s\n";
        $prof = "\nProfiling data\n";
        $prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total', 'Each', '%', 'Mem' );

        $total = isset( $this->mCollated['-total'] ) ? $this->mCollated['-total'] : 0;

        foreach ( $this->mCollated as $fname => $elapsed ) {
            $calls = $this->mCalls[$fname];
            $percent = $total ? 100. * $elapsed / $total : 0;
            $memory = $this->mMemory[$fname];
            $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]
            );
        }
        $prof .= "\nTotal: $total\n\n";

        return $prof;
    }

    public function getRawData() {
        $this->collateData();

        $profile = array();
        $total = isset( $this->mCollated['-total'] ) ? $this->mCollated['-total'] : 0;
        foreach ( $this->mCollated as $fname => $elapsed ) {
            $periods = array();
            foreach ( $this->mPeriods[$fname] as $period ) {
                $period['start'] *= 1000;
                $period['end'] *= 1000;
                $periods[] = $period;
            }
            $profile[] = array(
                'name' => $fname,
                'calls' => $this->mCalls[$fname],
                'elapsed' => $elapsed * 1000,
                'percent' => $total ? 100. * $elapsed / $total : 0,
                'memory' => $this->mMemory[$fname],
                'min' => $this->mMin[$fname] * 1000,
                'max' => $this->mMax[$fname] * 1000,
                'overhead' => $this->mOverhead[$fname],
                'periods' => $periods,
            );
        }

        return $profile;
    }

    protected static function calculateOverhead( $profileCount ) {
        wfProfileIn( '-overhead-total' );
        for ( $i = 0; $i < $profileCount; $i++ ) {
            wfProfileIn( '-overhead-internal' );
            wfProfileOut( '-overhead-internal' );
        }
        wfProfileOut( '-overhead-total' );
    }

    function calltreeCount( $stack, $start ) {
        $level = $stack[$start][1];
        $count = 0;
        for ( $i = $start -1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
            $count ++;
        }
        return $count;
    }

    public function logData() {
        global $wgProfilePerHost, $wgProfileToDatabase;

        # Do not log anything if database is readonly (bug 5375)
        if ( wfReadOnly() || !$wgProfileToDatabase ) {
            return;
        }

        $dbw = wfGetDB( DB_MASTER );
        if ( !is_object( $dbw ) ) {
            return;
        }

        if ( $wgProfilePerHost ) {
            $pfhost = wfHostname();
        } else {
            $pfhost = '';
        }

        try {
            $this->collateData();

            foreach ( $this->mCollated as $name => $elapsed ) {
                $eventCount = $this->mCalls[$name];
                $timeSum = (float)( $elapsed * 1000 );
                $memorySum = (float)$this->mMemory[$name];
                $name = substr( $name, 0, 255 );

                // Kludge
                $timeSum = $timeSum >= 0 ? $timeSum : 0;
                $memorySum = $memorySum >= 0 ? $memorySum : 0;

                $dbw->update( 'profiling',
                    array(
                        "pf_count=pf_count+{$eventCount}",
                        "pf_time=pf_time+{$timeSum}",
                        "pf_memory=pf_memory+{$memorySum}",
                    ),
                    array(
                        'pf_name' => $name,
                        'pf_server' => $pfhost,
                    ),
                    __METHOD__ );

                $rc = $dbw->affectedRows();
                if ( $rc == 0 ) {
                    $dbw->insert( 'profiling', array( 'pf_name' => $name, 'pf_count' => $eventCount,
                        'pf_time' => $timeSum, 'pf_memory' => $memorySum, 'pf_server' => $pfhost ),
                        __METHOD__, array( 'IGNORE' ) );
                }
                // When we upgrade to mysql 4.1, the insert+update
                // can be merged into just a insert with this construct added:
                //     "ON DUPLICATE KEY UPDATE ".
                //     "pf_count=pf_count + VALUES(pf_count), ".
                //     "pf_time=pf_time + VALUES(pf_time)";
            }
        } catch ( DBError $e ) {}
    }

    function getCurrentSection() {
        $elt = end( $this->mWorkStack );
        return $elt[0];
    }

    function debug( $s ) {
        if ( function_exists( 'wfDebug' ) ) {
            wfDebug( $s );
        }
    }

    function debugGroup( $group, $s ) {
        if ( function_exists( 'wfDebugLog' ) ) {
            wfDebugLog( $group, $s );
        }
    }

    protected function getContentType() {
        foreach ( headers_list() as $header ) {
            if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {
                return $m[1];
            }
        }
        return null;
    }
}