From: Aaron Schulz <aschulz@wikimedia.org>
Date: Fri, 26 May 2017 18:42:05 +0000 (-0700)
Subject: Log when transactions affect many rows in TransactionProfiler
X-Git-Tag: 1.31.0-rc.0~3004^2
X-Git-Url: http://git.cyclocoop.org/%22%2C%20generer_url_ecrire%28?a=commitdiff_plain;h=8f297550d28d10c6b3ab5342d3bbc9d50f2625c5;p=lhc%2Fweb%2Fwiklou.git

Log when transactions affect many rows in TransactionProfiler

This augments the logging which detect single large write queries

Bug: T95501
Change-Id: I4eac35c56a472e5ba64270ea10c48bf33138417b
---

diff --git a/includes/libs/rdbms/TransactionProfiler.php b/includes/libs/rdbms/TransactionProfiler.php
index 5d3534ffaa..823e0dc5cd 100644
--- a/includes/libs/rdbms/TransactionProfiler.php
+++ b/includes/libs/rdbms/TransactionProfiler.php
@@ -265,8 +265,9 @@ class TransactionProfiler implements LoggerAwareInterface {
 	 * @param string $db DB name
 	 * @param string $id ID string of transaction
 	 * @param float $writeTime Time spent in write queries
+	 * @param integer $affected Number of rows affected by writes
 	 */
-	public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0 ) {
+	public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
 		$name = "{$server} ({$db}) (TRX#$id)";
 		if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
 			$this->logger->info( "Detected no transaction for '$name' - out of sync." );
@@ -284,6 +285,14 @@ class TransactionProfiler implements LoggerAwareInterface {
 			);
 			$slow = true;
 		}
+		// Warn if too many rows were changed...
+		if ( $affected > $this->expect['maxAffected'] ) {
+			$this->reportExpectationViolated(
+				'maxAffected',
+				"[transaction $id writes to {$server} ({$db})]",
+				$affected
+			);
+		}
 		// Fill in the last non-query period...
 		$lastQuery = end( $this->dbTrxMethodTimes[$name] );
 		if ( $lastQuery ) {
diff --git a/includes/libs/rdbms/database/DBConnRef.php b/includes/libs/rdbms/database/DBConnRef.php
index b6167aa7ab..5b59d2a4a5 100644
--- a/includes/libs/rdbms/database/DBConnRef.php
+++ b/includes/libs/rdbms/database/DBConnRef.php
@@ -124,6 +124,10 @@ class DBConnRef implements IDatabase {
 		return $this->__call( __FUNCTION__, func_get_args() );
 	}
 
+	public function pendingWriteRowsAffected() {
+		return $this->__call( __FUNCTION__, func_get_args() );
+	}
+
 	public function isOpen() {
 		return $this->__call( __FUNCTION__, func_get_args() );
 	}
diff --git a/includes/libs/rdbms/database/Database.php b/includes/libs/rdbms/database/Database.php
index ee7644febb..8bea8cc5a9 100644
--- a/includes/libs/rdbms/database/Database.php
+++ b/includes/libs/rdbms/database/Database.php
@@ -200,6 +200,10 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 	 * @var integer Number of write queries for the current transaction
 	 */
 	private $mTrxWriteQueryCount = 0;
+	/**
+	 * @var integer Number of rows affected by write queries for the current transaction
+	 */
+	private $mTrxWriteAffectedRows = 0;
 	/**
 	 * @var float Like mTrxWriteQueryCount but excludes lock-bound, easy to replicate, queries
 	 */
@@ -583,6 +587,10 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 		return $this->mTrxLevel ? $this->mTrxWriteCallers : [];
 	}
 
+	public function pendingWriteRowsAffected() {
+		return $this->mTrxWriteAffectedRows;
+	}
+
 	/**
 	 * Get the list of method names that have pending write queries or callbacks
 	 * for this transaction
@@ -1011,7 +1019,7 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 		if ( $ret !== false ) {
 			$this->lastPing = $startTime;
 			if ( $isWrite && $this->mTrxLevel ) {
-				$this->updateTrxWriteQueryTime( $sql, $queryRuntime );
+				$this->updateTrxWriteQueryTime( $sql, $queryRuntime, $this->affectedRows() );
 				$this->mTrxWriteCallers[] = $fname;
 			}
 		}
@@ -1042,8 +1050,9 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 	 *
 	 * @param string $sql A SQL write query
 	 * @param float $runtime Total runtime, including RTT
+	 * @param integer $affected Affected row count
 	 */
-	private function updateTrxWriteQueryTime( $sql, $runtime ) {
+	private function updateTrxWriteQueryTime( $sql, $runtime, $affected ) {
 		// Whether this is indicative of replica DB runtime (except for RBR or ws_repl)
 		$indicativeOfReplicaRuntime = true;
 		if ( $runtime > self::SLOW_WRITE_SEC ) {
@@ -1058,6 +1067,7 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 
 		$this->mTrxWriteDuration += $runtime;
 		$this->mTrxWriteQueryCount += 1;
+		$this->mTrxWriteAffectedRows += $affected;
 		if ( $indicativeOfReplicaRuntime ) {
 			$this->mTrxWriteAdjDuration += $runtime;
 			$this->mTrxWriteAdjQueryCount += 1;
@@ -2805,6 +2815,7 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 		$this->mTrxShortId = sprintf( '%06x', mt_rand( 0, 0xffffff ) );
 		$this->mTrxWriteDuration = 0.0;
 		$this->mTrxWriteQueryCount = 0;
+		$this->mTrxWriteAffectedRows = 0;
 		$this->mTrxWriteAdjDuration = 0.0;
 		$this->mTrxWriteAdjQueryCount = 0;
 		$this->mTrxWriteCallers = [];
@@ -2871,7 +2882,12 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 		if ( $this->mTrxDoneWrites ) {
 			$this->mLastWriteTime = microtime( true );
 			$this->trxProfiler->transactionWritingOut(
-				$this->mServer, $this->mDBname, $this->mTrxShortId, $writeTime );
+				$this->mServer,
+				$this->mDBname,
+				$this->mTrxShortId,
+				$writeTime,
+				$this->mTrxWriteAffectedRows
+			);
 		}
 
 		$this->runOnTransactionIdleCallbacks( self::TRIGGER_COMMIT );
@@ -2916,7 +2932,10 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 		$this->mTrxAtomicLevels = [];
 		if ( $this->mTrxDoneWrites ) {
 			$this->trxProfiler->transactionWritingOut(
-				$this->mServer, $this->mDBname, $this->mTrxShortId );
+				$this->mServer,
+				$this->mDBname,
+				$this->mTrxShortId
+			);
 		}
 
 		$this->mTrxIdleCallbacks = []; // clear
diff --git a/includes/libs/rdbms/database/IDatabase.php b/includes/libs/rdbms/database/IDatabase.php
index bec26a617a..617982c46e 100644
--- a/includes/libs/rdbms/database/IDatabase.php
+++ b/includes/libs/rdbms/database/IDatabase.php
@@ -274,6 +274,14 @@ interface IDatabase {
 	 */
 	public function pendingWriteCallers();
 
+	/**
+	 * Get the number of affected rows from pending write queries
+	 *
+	 * @return integer
+	 * @since 1.30
+	 */
+	public function pendingWriteRowsAffected();
+
 	/**
 	 * Is a connection to the database open?
 	 * @return bool