TransactionProfiler.php

Go to the documentation of this file.

<?php
namespace Wikimedia\Rdbms;

use Psr\Log\LoggerInterface;
use Psr\Log\LoggerAwareInterface;
use Psr\Log\NullLogger;
use RuntimeException;

class TransactionProfiler implements LoggerAwareInterface {
    protected $dbLockThreshold = 3.0;
    protected $eventThreshold = 0.25;
    protected $silenced = false;

    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,
        'readQueryRows'  => 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 setSilenced( $value ) {
        $old = $this->silenced;
        $this->silenced = $value;

        return $old;
    }

    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 redefineExpectations( array $expects, $fname ) {
        $this->resetExpectations();
        $this->setExpectations( $expects, $fname );
    }

    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)]", $this->hits['conns'] );
        }
        if ( $isMaster && $this->hits['masterConns']++ >= $this->expect['masterConns'] ) {
            $this->reportExpectationViolated(
                'masterConns', "[connect to $server ($db)]", $this->hits['masterConns'] );
        }
    }

    public function transactionWritingIn( $server, $db, $id ) {
        $name = "{$server} ({$db}) (TRX#$id)";
        if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
            $this->logger->warning( "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->warning(
                "Query affected $n row(s):\n" . self::queryString( $query ) . "\n" .
                ( new RuntimeException() )->getTraceAsString() );
        } elseif ( !$isWrite && $n > $this->expect['readQueryRows'] ) {
            $this->logger->warning(
                "Query returned $n row(s):\n" . self::queryString( $query ) . "\n" .
                ( new RuntimeException() )->getTraceAsString() );
        }

        // Report when too many writes/queries happen...
        if ( $this->hits['queries']++ >= $this->expect['queries'] ) {
            $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
        }
        if ( $isWrite && $this->hits['writes']++ >= $this->expect['writes'] ) {
            $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
        }
        // 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, $affected = 0 ) {
        $name = "{$server} ({$db}) (TRX#$id)";
        if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
            $this->logger->warning( "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;
        }
        // Warn if too many rows were changed...
        if ( $affected > $this->expect['maxAffected'] ) {
            $this->reportExpectationViolated(
                'maxAffected',
                "[transaction $id writes to {$server} ({$db})]",
                $affected
            );
        }
        // 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 ) {
            $trace = '';
            foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
                list( $query, $sTime, $end ) = $info;
                $trace .= sprintf(
                    "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self::queryString( $query ) );
            }
            $this->logger->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
                'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
                'trace' => $trace
            ] );
        }
        unset( $this->dbTrxHoldingLocks[$name] );
        unset( $this->dbTrxMethodTimes[$name] );
    }

    protected function reportExpectationViolated( $expect, $query, $actual ) {
        if ( $this->silenced ) {
            return;
        }

        $this->logger->warning(
            "Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n" .
            ( new RuntimeException() )->getTraceAsString(),
            [
                'measure' => $expect,
                'max' => $this->expect[$expect],
                'by' => $this->expectBy[$expect],
                'actual' => $actual,
                'query' => self::queryString( $query )
            ]
        );
    }

    private static function queryString( $query ) {
        return $query instanceof GeneralizedSql ? $query->stringify() : $query;
    }
}