From: Aaron Schulz <aschulz@wikimedia.org>
Date: Fri, 8 May 2015 00:12:09 +0000 (-0700)
Subject: Log transaction that spend too much time in write queries
X-Git-Tag: 1.31.0-rc.0~11460^2
X-Git-Url: https://git.cyclocoop.org/%27.%24link.%27?a=commitdiff_plain;h=7936b94341ec5b67d4f212acc9b0721923b8c5c7;p=lhc%2Fweb%2Fwiklou.git

Log transaction that spend too much time in write queries

Change-Id: I9ba184601cfb1667291f7a29677cc5205344d5ad
---

diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php
index 2b3bce56e8..3ca54b5c0a 100644
--- 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 5afff91550..97073dde31 100644
--- 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 5f2a57a5bc..3f4d58b5d1 100644
--- 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 ) {