Log multi-DB write transactions

Bug: T122387
Change-Id: I03447f8c8465775a70c6a94f24ce196973703ce3

diff --git a/includes/db/DBConnRef.php b/includes/db/DBConnRef.php
index 3cac22a..f09de4f 100644 (file)
--- 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 c58e9bd..1835958 100644 (file)
--- 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 31b2758..c72218a 100644 (file)
--- 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 4a13522..37ab9ca 100644 (file)
--- 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 3fe9638..b5a79a9 100644 (file)
--- 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