Profiler.php

Go to the documentation of this file.

<?php
function wfGetRusage() {
    if ( !function_exists( 'getrusage' ) ) {
        return false;
    } elseif ( defined ( 'HHVM_VERSION' ) ) {
        return getrusage( 2 /* RUSAGE_THREAD */ );
    } else {
        return getrusage( 0 /* RUSAGE_SELF */ );
    }
}

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 );
        }
    }
}

abstract class Profiler {
    protected $mProfileID = false;
    protected $mTemplated = false;

    protected $trxProfiler;

    // @codingStandardsIgnoreStart PSR2.Classes.PropertyDeclaration.Underscore
    public static $__instance = null;
    // @codingStandardsIgnoreEnd

    public function __construct( array $params ) {
        if ( isset( $params['profileID'] ) ) {
            $this->mProfileID = $params['profileID'];
        }
        $this->trxProfiler = new TransactionProfiler();
    }

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

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

    abstract public function isStub();

    abstract public function isPersistent();

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

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

    abstract public function profileIn( $functionname );

    abstract public function profileOut( $functionname );

    public function transactionWritingIn( $server, $db, $id = '' ) {
        $this->trxProfiler->transactionWritingIn( $server, $db, $id );
    }

    public function transactionWritingOut( $server, $db, $id = '' ) {
        $this->trxProfiler->transactionWritingOut( $server, $db, $id );
    }

    abstract public function close();

    abstract public function logData();

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

    abstract public function getOutput();

    abstract public function getRawData();

    protected function getTime( $metric = 'wall' ) {
        if ( $metric === 'cpu' || $metric === 'user' ) {
            $ru = wfGetRusage();
            if ( !$ru ) {
                return 0;
            }
            $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 = 'wall' ) {
        global $wgRequestTime, $wgRUstart;

        if ( $metric === 'cpu' || $metric === '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 debug( $s ) {
        if ( function_exists( 'wfDebug' ) ) {
            wfDebug( $s );
        }
    }

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

class TransactionProfiler {
    protected $mDBLockThreshold = 3.0;
    protected $mDBTrxHoldingLocks = array();
    protected $mDBTrxMethodTimes = array();

    public function transactionWritingIn( $server, $db, $id ) {
        $name = "{$server} ({$db}) (TRX#$id)";
        if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
            wfDebugLog( 'DBPerformance', "Nested transaction for '$name' - out of sync." );
        }
        $this->mDBTrxHoldingLocks[$name] =
            array( 'start' => microtime( true ), 'conns' => array() );
        $this->mDBTrxMethodTimes[$name] = array();

        foreach ( $this->mDBTrxHoldingLocks as $name => &$info ) {
            $info['conns'][$name] = 1; // track all DBs in transactions for this transaction
        }
    }

    public function recordFunctionCompletion( $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, $id ) {
        $name = "{$server} ({$db}) (TRX#$id)";
        if ( !isset( $this->mDBTrxMethodTimes[$name] ) ) {
            wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." );
            return;
        }
        $slow = false;
        foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
            $realtime = $info[1];
            if ( $realtime >= $this->mDBLockThreshold ) {
                $slow = true;
                break;
            }
        }
        if ( $slow ) {
            $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks[$name]['conns'] ) );
            $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 );
            }
            wfDebugLog( 'DBPerformance', $msg );
        }
        unset( $this->mDBTrxHoldingLocks[$name] );
        unset( $this->mDBTrxMethodTimes[$name] );
    }
}