Log transaction that spend too much time in write queries

Change-Id: I9ba184601cfb1667291f7a29677cc5205344d5ad

diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php
index 2b3bce5..3ca54b5 100644 (file)
--- a/includes/DefaultSettings.php
+++ b/includes/DefaultSettings.php
@@ -5320,12 +5320,27 @@ $wgDebugDumpSqlLength = 500;
  */
 $wgTrxProfilerLimits = array(
        // Basic GET and POST requests
-       'GET'  => array( 'masterConns' => 0, 'writes' => 0, 'readQueryTime' => 5 ),
-       'POST' => array( 'maxAffected' => 500, 'readQueryTime' => 5, 'writeQueryTime' => 1 ),
+       'GET' => array(
+               'masterConns' => 0,
+               'writes' => 0,
+               'readQueryTime' => 5
+       ),
+       'POST' => array(
+               'readQueryTime' => 5,
+               'writeQueryTime' => 1,
+               'maxAffected' => 500
+       ),
        // Background job runner
-       'JobRunner' => array( 'maxAffected' => 500, 'readQueryTime' => 30, 'writeQueryTime' => 5 ),
+       'JobRunner' => array(
+               'readQueryTime' => 30,
+               'writeQueryTime' => 5,
+               'maxAffected' => 500
+       ),
        // Command-line scripts
-       'Maintenance' => array( 'maxAffected' => 1000, 'writeQueryTime' => 5 )
+       'Maintenance' => array(
+               'writeQueryTime' => 5,
+               'maxAffected' => 1000
+       )
 );
 
 /**

diff --git a/includes/db/Database.php b/includes/db/Database.php
index 5afff91..97073dd 100644 (file)
--- a/includes/db/Database.php
+++ b/includes/db/Database.php
@@ -3639,11 +3639,12 @@ abstract class DatabaseBase implements IDatabase {
                        }
 
                        $this->runOnTransactionPreCommitCallbacks();
+                       $writeTime = $this->pendingWriteQueryDuration();
                        $this->doCommit( $fname );
                        if ( $this->mTrxDoneWrites ) {
                                $this->mDoneWrites = microtime( true );
                                $this->getTransactionProfiler()->transactionWritingOut(
-                                       $this->mServer, $this->mDBname, $this->mTrxShortId );
+                                       $this->mServer, $this->mDBname, $this->mTrxShortId, $writeTime );
                        }
                        $this->runOnTransactionIdleCallbacks();
                }
@@ -3721,11 +3722,12 @@ abstract class DatabaseBase implements IDatabase {
                }
 
                $this->runOnTransactionPreCommitCallbacks();
+               $writeTime = $this->pendingWriteQueryDuration();
                $this->doCommit( $fname );
                if ( $this->mTrxDoneWrites ) {
                        $this->mDoneWrites = microtime( true );
                        $this->getTransactionProfiler()->transactionWritingOut(
-                               $this->mServer, $this->mDBname, $this->mTrxShortId );
+                               $this->mServer, $this->mDBname, $this->mTrxShortId, $writeTime );
                }
                $this->runOnTransactionIdleCallbacks();
        }

diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php
index 5f2a57a..3f4d58b 100644 (file)
--- a/includes/profiler/TransactionProfiler.php
+++ b/includes/profiler/TransactionProfiler.php
@@ -59,7 +59,7 @@ class TransactionProfiler implements LoggerAwareInterface {
                'masterConns'    => INF,
                'maxAffected'    => INF,
                'readQueryTime'  => INF,
-               'writeQueryTime' => INF,
+               'writeQueryTime' => INF
        );
        /** @var array */
        protected $expectBy = array();
@@ -246,13 +246,19 @@ class TransactionProfiler implements LoggerAwareInterface {
         * @param string $server DB server
         * @param string $db DB name
         * @param string $id ID string of transaction
+        * @param float $writeTime Time spent in write queries
         */
-       public function transactionWritingOut( $server, $db, $id ) {
+       public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0 ) {
                $name = "{$server} ({$db}) (TRX#$id)";
                if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
                        $this->logger->info( "Detected no transaction for '$name' - out of sync." );
                        return;
                }
+               // Warn if too much time was spend writing...
+               if ( $writeTime > $this->expect['writeQueryTime'] ) {
+                       $this->reportExpectationViolated( 'writeQueryTime',
+                               "[transaction $id writes to {$server} ({$db})]" );
+               }
                // Fill in the last non-query period...
                $lastQuery = end( $this->dbTrxMethodTimes[$name] );
                if ( $lastQuery ) {