TransactionProfiler.php

Go to the documentation of this file.

<?php
use Psr\Log\LoggerInterface;
use Psr\Log\LoggerAwareInterface;
use Psr\Log\NullLogger;

class TransactionProfiler implements LoggerAwareInterface {
    protected $dbLockThreshold = 3.0;
    protected $eventThreshold = .25;

    protected $dbTrxHoldingLocks = [];
    protected $dbTrxMethodTimes = [];

    protected $hits = [
        'writes'      => 0,
        'queries'     => 0,
        'conns'       => 0,
        'masterConns' => 0
    ];
    protected $expect = [
        'writes'         => INF,
        'queries'        => INF,
        'conns'          => INF,
        'masterConns'    => INF,
        'maxAffected'    => INF,
        'readQueryTime'  => INF,
        'writeQueryTime' => INF
    ];
    protected $expectBy = [];

    private $logger;

    public function __construct() {
        $this->setLogger( new NullLogger() );
    }

    public function setLogger( LoggerInterface $logger ) {
        $this->logger = $logger;
    }

    public function setExpectation( $event, $value, $fname ) {
        $this->expect[$event] = isset( $this->expect[$event] )
            ? min( $this->expect[$event], $value )
            : $value;
        if ( $this->expect[$event] == $value ) {
            $this->expectBy[$event] = $fname;
        }
    }

    public function setExpectations( array $expects, $fname ) {
        foreach ( $expects as $event => $value ) {
            $this->setExpectation( $event, $value, $fname );
        }
    }

    public function resetExpectations() {
        foreach ( $this->hits as &$val ) {
            $val = 0;
        }
        unset( $val );
        foreach ( $this->expect as &$val ) {
            $val = INF;
        }
        unset( $val );
        $this->expectBy = [];
    }

    public function recordConnection( $server, $db, $isMaster ) {
        // Report when too many connections happen...
        if ( $this->hits['conns']++ == $this->expect['conns'] ) {
            $this->reportExpectationViolated( 'conns', "[connect to $server ($db)]" );
        }
        if ( $isMaster && $this->hits['masterConns']++ == $this->expect['masterConns'] ) {
            $this->reportExpectationViolated( 'masterConns', "[connect to $server ($db)]" );
        }
    }

    public function transactionWritingIn( $server, $db, $id ) {
        $name = "{$server} ({$db}) (TRX#$id)";
        if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
            $this->logger->info( "Nested transaction for '$name' - out of sync." );
        }
        $this->dbTrxHoldingLocks[$name] = [
            'start' => microtime( true ),
            'conns' => [], // all connections involved
        ];
        $this->dbTrxMethodTimes[$name] = [];

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

    public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
        $eTime = microtime( true );
        $elapsed = ( $eTime - $sTime );

        if ( $isWrite && $n > $this->expect['maxAffected'] ) {
            $this->logger->info( "Query affected $n row(s):\n" . $query . "\n" .
                wfBacktrace( true ) );
        }

        // Report when too many writes/queries happen...
        if ( $this->hits['queries']++ == $this->expect['queries'] ) {
            $this->reportExpectationViolated( 'queries', $query );
        }
        if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) {
            $this->reportExpectationViolated( 'writes', $query );
        }
        // Report slow queries...
        if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
            $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
        }
        if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
            $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
        }

        if ( !$this->dbTrxHoldingLocks ) {
            // Short-circuit
            return;
        } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
            // Not an important query nor slow enough
            return;
        }

        foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
            $lastQuery = end( $this->dbTrxMethodTimes[$name] );
            if ( $lastQuery ) {
                // Additional query in the trx...
                $lastEnd = $lastQuery[2];
                if ( $sTime >= $lastEnd ) { // sanity check
                    if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
                        // Add an entry representing the time spent doing non-queries
                        $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
                    }
                    $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
                }
            } else {
                // First query in the trx...
                if ( $sTime >= $info['start'] ) { // sanity check
                    $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
                }
            }
        }
    }

    public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0 ) {
        $name = "{$server} ({$db}) (TRX#$id)";
        if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
            $this->logger->info( "Detected no transaction for '$name' - out of sync." );
            return;
        }

        $slow = false;

        // Warn if too much time was spend writing...
        if ( $writeTime > $this->expect['writeQueryTime'] ) {
            $this->reportExpectationViolated(
                'writeQueryTime',
                "[transaction $id writes to {$server} ({$db})]",
                $writeTime
            );
            $slow = true;
        }
        // Fill in the last non-query period...
        $lastQuery = end( $this->dbTrxMethodTimes[$name] );
        if ( $lastQuery ) {
            $now = microtime( true );
            $lastEnd = $lastQuery[2];
            if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
                $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
            }
        }
        // Check for any slow queries or non-query periods...
        foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
            $elapsed = ( $info[2] - $info[1] );
            if ( $elapsed >= $this->dbLockThreshold ) {
                $slow = true;
                break;
            }
        }
        if ( $slow ) {
            $dbs = implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) );
            $msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n";
            foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
                list( $query, $sTime, $end ) = $info;
                $msg .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
            }
            $this->logger->info( $msg );
        }
        unset( $this->dbTrxHoldingLocks[$name] );
        unset( $this->dbTrxMethodTimes[$name] );
    }

    protected function reportExpectationViolated( $expect, $query, $actual = null ) {
        $n = $this->expect[$expect];
        $by = $this->expectBy[$expect];
        $actual = ( $actual !== null ) ? " (actual: $actual)" : "";

        $this->logger->info(
            "Expectation ($expect <= $n) by $by not met$actual:\n$query\n" .
            wfBacktrace( true )
        );
    }
}