profiler: log slow methods that worsen DB locks in transactions

Change-Id: I1aa13c29837fa655c13ef324d02cd1be1739edea

diff --git a/includes/db/Database.php b/includes/db/Database.php
index 04f1f97..f9f4d5d 100644 (file)
--- a/includes/db/Database.php
+++ b/includes/db/Database.php
@@ -938,6 +938,7 @@ abstract class DatabaseBase implements IDatabase, DatabaseType {
                # Keep track of whether the transaction has write queries pending
                if ( $this->mTrxLevel && !$this->mTrxDoneWrites && $this->isWriteQuery( $sql ) ) {
                        $this->mTrxDoneWrites = true;
+                       Profiler::instance()->transactionWritingIn( $this->mServer, $this->mDBname );
                }
 
                if ( $this->debug() ) {
@@ -3172,6 +3173,9 @@ abstract class DatabaseBase implements IDatabase, DatabaseType {
 
                        $this->runOnTransactionPreCommitCallbacks();
                        $this->doCommit( $fname );
+                       if ( $this->mTrxDoneWrites ) {
+                               Profiler::instance()->transactionWritingOut( $this->mServer, $this->mDBname );
+                       }
                        $this->runOnTransactionIdleCallbacks();
                }
 
@@ -3221,6 +3225,9 @@ abstract class DatabaseBase implements IDatabase, DatabaseType {
 
                $this->runOnTransactionPreCommitCallbacks();
                $this->doCommit( $fname );
+               if ( $this->mTrxDoneWrites ) {
+                       Profiler::instance()->transactionWritingOut( $this->mServer, $this->mDBname );
+               }
                $this->runOnTransactionIdleCallbacks();
        }
 
@@ -3252,6 +3259,9 @@ abstract class DatabaseBase implements IDatabase, DatabaseType {
                $this->doRollback( $fname );
                $this->mTrxIdleCallbacks = array(); // cancel
                $this->mTrxPreCommitCallbacks = array(); // cancel
+               if ( $this->mTrxDoneWrites ) {
+                       Profiler::instance()->transactionWritingOut( $this->mServer, $this->mDBname );
+               }
        }
 
        /**

diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php
index 7ca4c2d..0ef12ec 100644 (file)
--- a/includes/profiler/Profiler.php
+++ b/includes/profiler/Profiler.php
@@ -100,6 +100,12 @@ class Profiler {
        protected $mTimeMetric = 'wall';
        protected $mProfileID = false, $mCollateDone = false, $mTemplated = false;
 
+       protected $mDBLockThreshold = 5.0; // float; seconds
+       /** @var Array DB/server name => (active trx count,timestamp) */
+       protected $mDBTrxHoldingLocks = array();
+       /** @var Array DB/server name => list of (method, elapsed time) */
+       protected $mDBTrxMethodTimes = array();
+
        /** @var Profiler */
        public static $__instance = null; // do not call this outside Profiler and ProfileSection
 
@@ -223,20 +229,19 @@ class Profiler {
                if ( !$bit ) {
                        $this->debug( "Profiling error, !\$bit: $functionname\n" );
                } else {
-                       //if( $wgDebugProfiling ) {
-                               if ( $functionname == 'close' ) {
-                                       $message = "Profile section ended by close(): {$bit[0]}";
-                                       $this->debug( "$message\n" );
-                                       $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 );
-                               } elseif ( $bit[0] != $functionname ) {
-                                       $message = "Profiling error: in({$bit[0]}), out($functionname)";
-                                       $this->debug( "$message\n" );
-                                       $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 );
-                               }
-                       //}
+                       if ( $functionname == 'close' ) {
+                               $message = "Profile section ended by close(): {$bit[0]}";
+                               $this->debug( "$message\n" );
+                               $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 );
+                       } elseif ( $bit[0] != $functionname ) {
+                               $message = "Profiling error: in({$bit[0]}), out($functionname)";
+                               $this->debug( "$message\n" );
+                               $this->mStack[] = array( $message, 0, 0.0, 0, 0.0, 0 );
+                       }
                        $bit[] = $time;
                        $bit[] = $memory;
                        $this->mStack[] = $bit;
+                       $this->updateTrxProfiling( $functionname, $time );
                }
        }
 
@@ -249,6 +254,83 @@ class Profiler {
                }
        }
 
+       /**
+        * Mark a DB as in a transaction with one or more writes pending
+        *
+        * Note that there can be multiple connections to a single DB.
+        *
+        * @param string $server DB server
+        * @param string $db DB name
+        */
+       public function transactionWritingIn( $server, $db ) {
+               $name = "{$server} ({$db})";
+               if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
+                       ++$this->mDBTrxHoldingLocks[$name]['refs'];
+               } else {
+                       $this->mDBTrxHoldingLocks[$name] = array( 'refs' => 1, 'start' => microtime( true ) );
+                       $this->mDBTrxMethodTimes[$name] = array();
+               }
+       }
+
+       /**
+        * Register the name and time of a method for slow DB trx detection
+        *
+        * @param string $method Function name
+        * @param float $realtime Wal time ellapsed
+        */
+       protected function updateTrxProfiling( $method, $realtime ) {
+               if ( !$this->mDBTrxHoldingLocks ) {
+                       return; // short-circuit
+               // @TODO: hardcoded check is a tad janky (what about FOR UPDATE?)
+               } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
+                       && $realtime < $this->mDBLockThreshold )
+               {
+                       return; // not a DB master query nor slow enough
+               }
+               $now = microtime( true );
+               foreach ( $this->mDBTrxHoldingLocks as $name => $info ) {
+                       // Hacky check to exclude entries from before the first TRX write
+                       if ( ( $now - $realtime ) >= $info['start'] ) {
+                               $this->mDBTrxMethodTimes[$name][] = array( $method, $realtime );
+                       }
+               }
+       }
+
+       /**
+        * Mark a DB as no longer in a transaction
+        *
+        * This will check if locks are possibly held for longer than
+        * needed and log any affected transactions to a special DB log.
+        * Note that there can be multiple connections to a single DB.
+        *
+        * @param string $server DB server
+        * @param string $db DB name
+        */
+       public function transactionWritingOut( $server, $db ) {
+               $name = "{$server} ({$db})";
+               if ( --$this->mDBTrxHoldingLocks[$name]['refs'] <= 0 ) {
+                       $slow = false;
+                       foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
+                               list( $method, $realtime ) = $info;
+                               if ( $realtime >= $this->mDBLockThreshold ) {
+                                       $slow = true;
+                                       break;
+                               }
+                       }
+                       if ( $slow ) {
+                               $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks ) );
+                               $msg = "Sub-optimal transaction on DB(s) {$dbs}:\n";
+                               foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) {
+                                       list( $method, $realtime ) = $info;
+                                       $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
+                               }
+                               wfDebugLog( 'DBPerfomance', $msg );
+                       }
+                       unset( $this->mDBTrxHoldingLocks[$name] );
+                       unset( $this->mDBTrxMethodTimes[$name] );
+               }
+       }
+
        /**
         * Mark this call as templated or not
         *

diff --git a/includes/profiler/ProfilerSimple.php b/includes/profiler/ProfilerSimple.php
index b59c528..805c60f 100644 (file)
--- a/includes/profiler/ProfilerSimple.php
+++ b/includes/profiler/ProfilerSimple.php
@@ -101,6 +101,7 @@ class ProfilerSimple extends Profiler {
                        $entry['real_sq'] += $elapsedreal * $elapsedreal;
                        $entry['count']++;
 
+                       $this->updateTrxProfiling( $functionname, $elapsedreal );
                }
        }
 

diff --git a/includes/profiler/ProfilerSimpleTrace.php b/includes/profiler/ProfilerSimpleTrace.php
index d44dfe1..5588d1e 100644 (file)
--- a/includes/profiler/ProfilerSimpleTrace.php
+++ b/includes/profiler/ProfilerSimpleTrace.php
@@ -59,6 +59,8 @@ class ProfilerSimpleTrace extends ProfilerSimple {
                        $elapsedreal = $this->getTime() - $ortime;
                        $this->trace .= sprintf( "%03.6f %6.1f", $elapsedreal, $this->memoryDiff() ) .
                                        str_repeat( " ", count( $this->mWorkStack ) + 1 ) . " < " . $functionname . "\n";
+
+                       $this->updateTrxProfiling( $functionname, $elapsedreal );
                }
        }
 

diff --git a/includes/profiler/ProfilerStub.php b/includes/profiler/ProfilerStub.php
index c0eb0fb..3697f35 100644 (file)
--- a/includes/profiler/ProfilerStub.php
+++ b/includes/profiler/ProfilerStub.php
@@ -39,4 +39,6 @@ class ProfilerStub extends Profiler {
        public function close() {}
        public function logData() {}
        public function getCurrentSection() { return ''; }
+       public function transactionWritingIn( $server, $db ) {}
+       public function transactionWritingOut( $server, $db ) {}
 }