From be8b4d4d286c3419a25d81541044fde677cc4bbc Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Wed, 19 Nov 2014 11:58:40 -0800 Subject: [PATCH] TransactionProfiler now shows the delay periods between queries * Also tweaked the slave query display threshold to show them more Change-Id: I0d9002b2f12e846a7355992443287d4ec43a7e88 --- includes/db/Database.php | 11 ++-- includes/profiler/TransactionProfiler.php | 69 ++++++++++++++++------- 2 files changed, 54 insertions(+), 26 deletions(-) diff --git a/includes/db/Database.php b/includes/db/Database.php index aa0e4de59d..e5332d2bba 100644 --- a/includes/db/Database.php +++ b/includes/db/Database.php @@ -1002,11 +1002,12 @@ abstract class DatabaseBase implements IDatabase { # Log the query time and feed it into the DB trx profiler if ( $queryProf != '' ) { $queryStartTime = microtime( true ); - $queryProfile = new ScopedCallback( function() use ( $queryStartTime, $queryProf ) { - $elapsed = microtime( true ) - $queryStartTime; - $trxProfiler = Profiler::instance()->getTransactionProfiler(); - $trxProfiler->recordFunctionCompletion( $queryProf, $elapsed ); - } ); + $queryProfile = new ScopedCallback( + function() use ( $queryStartTime, $queryProf, $isMaster ) { + $trxProfiler = Profiler::instance()->getTransactionProfiler(); + $trxProfiler->recordQueryCompletion( $queryProf, $queryStartTime, $isMaster ); + } + ); } # Do the query and handle errors diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php index 7843ac18f1..886bc5a0b4 100644 --- a/includes/profiler/TransactionProfiler.php +++ b/includes/profiler/TransactionProfiler.php @@ -1,6 +1,6 @@ (active trx count, time, DBs involved) */ + /** @var float Seconds */ + protected $eventThreshold = .25; + + /** @var array transaction ID => (write start time, list of DBs involved) */ protected $dbTrxHoldingLocks = array(); - /** @var array DB/server name => list of (function name, elapsed time) */ + /** @var array transaction ID => list of (query name, start time, end time) */ protected $dbTrxMethodTimes = array(); /** @@ -54,7 +56,7 @@ class TransactionProfiler { } $this->dbTrxHoldingLocks[$name] = array( 'start' => microtime( true ), - 'conns' => array(), + 'conns' => array(), // all connections involved ); $this->dbTrxMethodTimes[$name] = array(); @@ -67,26 +69,41 @@ class TransactionProfiler { /** * Register the name and time of a method for slow DB trx detection * - * This method is only to be called by the Profiler class as methods finish + * This assumes that all queries are synchronous (non-overlapping) * - * @param string $method Function name - * @param float $realtime Wall time ellapsed + * @param string $query Function name + * @param float $sTime Starting UNIX wall time + * @param bool $isWrite Whether this is a write query */ - public function recordFunctionCompletion( $method, $realtime ) { + public function recordQueryCompletion( $query, $sTime, $isWrite = false ) { + $eTime = microtime( true ); + $elapsed = ( $eTime - $sTime ); + if ( !$this->dbTrxHoldingLocks ) { // Short-circuit return; - // @todo hardcoded check is a tad janky - } elseif ( !preg_match( '/^query-m: /', $method ) && $realtime < 1.0 ) { - // Not a DB master query nor slow enough + } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) { + // Not an important query nor slow enough return; } - $now = microtime( true ); foreach ( $this->dbTrxHoldingLocks as $name => $info ) { - // Hacky check to exclude entries from before the first TRX write - if ( ( $now - $realtime ) >= $info['start'] ) { - $this->dbTrxMethodTimes[$name][] = array( $method, $realtime ); + $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][] = array( '...delay...', $lastEnd, $sTime ); + } + $this->dbTrxMethodTimes[$name][] = array( $query, $sTime, $eTime ); + } + } else { + // First query in the trx... + if ( $sTime >= $info['start'] ) { // sanity check + $this->dbTrxMethodTimes[$name][] = array( $query, $sTime, $eTime ); + } } } } @@ -108,10 +125,20 @@ class TransactionProfiler { wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." ); return; } + // 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][] = array( '...delay...', $lastEnd, $now ); + } + } + // Check for any slow queries or non-query periods... $slow = false; foreach ( $this->dbTrxMethodTimes[$name] as $info ) { - $realtime = $info[1]; - if ( $realtime >= $this->dbLockThreshold ) { + $elapsed = ( $info[2] - $info[1] ); + if ( $elapsed >= $this->dbLockThreshold ) { $slow = true; break; } @@ -120,8 +147,8 @@ class TransactionProfiler { $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( $method, $realtime ) = $info; - $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method ); + list( $query, $sTime, $end ) = $info; + $msg .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query ); } wfDebugLog( 'DBPerformance', $msg ); } -- 2.20.1