From b527783de953891bacfdcf4138265cbbc20dbff6 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Tue, 5 Jan 2016 18:19:40 -0800 Subject: [PATCH] Log multi-DB write transactions Bug: T122387 Change-Id: I03447f8c8465775a70c6a94f24ce196973703ce3 --- includes/db/DBConnRef.php | 4 +++ includes/db/Database.php | 13 +++++++++ includes/db/IDatabase.php | 10 ++++++- includes/db/loadbalancer/LBFactory.php | 35 +++++++++++++++++++++++ includes/db/loadbalancer/LoadBalancer.php | 23 +++++++++++++++ 5 files changed, 84 insertions(+), 1 deletion(-) diff --git a/includes/db/DBConnRef.php b/includes/db/DBConnRef.php index 3cac22a13c..f09de4fb39 100644 --- a/includes/db/DBConnRef.php +++ b/includes/db/DBConnRef.php @@ -103,6 +103,10 @@ class DBConnRef implements IDatabase { return $this->__call( __FUNCTION__, func_get_args() ); } + public function pendingWriteCallers() { + return $this->__call( __FUNCTION__, func_get_args() ); + } + public function isOpen() { return $this->__call( __FUNCTION__, func_get_args() ); } diff --git a/includes/db/Database.php b/includes/db/Database.php index c58e9bdea8..183595820c 100644 --- a/includes/db/Database.php +++ b/includes/db/Database.php @@ -141,6 +141,13 @@ abstract class DatabaseBase implements IDatabase { */ private $mTrxAutomaticAtomic = false; + /** + * Track the write query callers of the current transaction + * + * @var string[] + */ + private $mTrxWriteCallers = array(); + /** * Track the seconds spent in write queries for the current transaction * @@ -387,6 +394,10 @@ abstract class DatabaseBase implements IDatabase { return $this->mTrxLevel ? $this->mTrxWriteDuration : false; } + public function pendingWriteCallers() { + return $this->mTrxLevel ? $this->mTrxWriteCallers : array(); + } + public function isOpen() { return $this->mOpened; } @@ -891,6 +902,7 @@ abstract class DatabaseBase implements IDatabase { if ( $isWriteQuery && $this->mTrxLevel ) { $this->mTrxWriteDuration += $queryRuntime; + $this->mTrxWriteCallers[] = $fname; } return $res; @@ -2610,6 +2622,7 @@ abstract class DatabaseBase implements IDatabase { $this->mTrxPreCommitCallbacks = array(); $this->mTrxShortId = wfRandomString( 12 ); $this->mTrxWriteDuration = 0.0; + $this->mTrxWriteCallers = array(); // First SELECT after BEGIN will establish the snapshot in REPEATABLE-READ. // Get an estimate of the slave lag before then, treating estimate staleness // as lag itself just to be safe diff --git a/includes/db/IDatabase.php b/includes/db/IDatabase.php index 31b2758c33..c72218aad1 100644 --- a/includes/db/IDatabase.php +++ b/includes/db/IDatabase.php @@ -174,7 +174,7 @@ interface IDatabase { public function writesOrCallbacksPending(); /** - * Get the time spend running write queries for this + * Get the time spend running write queries for this transaction * * High times could be due to scanning, updates, locking, and such * @@ -183,6 +183,14 @@ interface IDatabase { */ public function pendingWriteQueryDuration(); + /** + * Get the list of method names that did write queries for this transaction + * + * @return array + * @since 1.27 + */ + public function pendingWriteCallers(); + /** * Is a connection to the database open? * @return bool diff --git a/includes/db/loadbalancer/LBFactory.php b/includes/db/loadbalancer/LBFactory.php index 4a135222bf..37ab9ca729 100644 --- a/includes/db/loadbalancer/LBFactory.php +++ b/includes/db/loadbalancer/LBFactory.php @@ -21,6 +21,9 @@ * @ingroup Database */ +use Psr\Log\LoggerInterface; +use MediaWiki\Logger\LoggerFactory; + /** * An interface for generating database load balancers * @ingroup Database @@ -28,9 +31,13 @@ abstract class LBFactory { /** @var ChronologyProtector */ protected $chronProt; + /** @var TransactionProfiler */ protected $trxProfiler; + /** @var LoggerInterface */ + protected $logger; + /** @var LBFactory */ private static $instance; @@ -50,6 +57,7 @@ abstract class LBFactory { $this->chronProt = $this->newChronologyProtector(); $this->trxProfiler = Profiler::instance()->getTransactionProfiler(); + $this->logger = LoggerFactory::getInstance( 'DBTransaction' ); } /** @@ -208,6 +216,8 @@ abstract class LBFactory { * @param string $fname Caller name */ public function commitAll( $fname = __METHOD__ ) { + $this->logMultiDbTransaction(); + $start = microtime( true ); $this->forEachLBCallMethod( 'commitAll', array( $fname ) ); $timeMs = 1000 * ( microtime( true ) - $start ); @@ -220,6 +230,8 @@ abstract class LBFactory { * @param string $fname Caller name */ public function commitMasterChanges( $fname = __METHOD__ ) { + $this->logMultiDbTransaction(); + $start = microtime( true ); $this->forEachLBCallMethod( 'commitMasterChanges', array( $fname ) ); $timeMs = 1000 * ( microtime( true ) - $start ); @@ -236,6 +248,29 @@ abstract class LBFactory { $this->forEachLBCallMethod( 'rollbackMasterChanges', array( $fname ) ); } + /** + * Log query info if multi DB transactions are going to be committed now + */ + private function logMultiDbTransaction() { + $callersByDB = array(); + $this->forEachLB( function ( LoadBalancer $lb ) use ( &$callersByDB ) { + $masterName = $lb->getServerName( $lb->getWriterIndex() ); + $callers = $lb->pendingMasterChangeCallers(); + if ( $callers ) { + $callersByDB[$masterName] = $callers; + } + } ); + + if ( count( $callersByDB ) >= 2 ) { + $dbs = implode( ', ', array_keys( $callersByDB ) ); + $msg = "Multi-DB transaction [{$dbs}]:\n"; + foreach ( $callersByDB as $db => $callers ) { + $msg .= "$db: " . implode( '; ', $callers ) . "\n"; + } + $this->logger->info( $msg ); + } + } + /** * Determine if any master connection has pending changes * @return bool diff --git a/includes/db/loadbalancer/LoadBalancer.php b/includes/db/loadbalancer/LoadBalancer.php index 3fe963890e..b5a79a94fa 100644 --- a/includes/db/loadbalancer/LoadBalancer.php +++ b/includes/db/loadbalancer/LoadBalancer.php @@ -1168,6 +1168,29 @@ class LoadBalancer { || $this->lastMasterChangeTimestamp() > microtime( true ) - $age ); } + /** + * Get the list of callers that have pending master changes + * + * @return array + * @since 1.27 + */ + public function pendingMasterChangeCallers() { + $fnames = array(); + + $masterIndex = $this->getWriterIndex(); + foreach ( $this->mConns as $conns2 ) { + if ( empty( $conns2[$masterIndex] ) ) { + continue; + } + /** @var DatabaseBase $conn */ + foreach ( $conns2[$masterIndex] as $conn ) { + $fnames = array_merge( $fnames, $conn->pendingWriteCallers() ); + } + } + + return $fnames; + } + /** * @param mixed $value * @return mixed -- 2.20.1