From 505394a5a93524cdc0b449bba64d4940c330631d Mon Sep 17 00:00:00 2001
From: Aaron Schulz <aschulz@wikimedia.org>
Date: Thu, 15 Jan 2015 15:55:17 -0800
Subject: [PATCH] Added query/connection expectation support to
 TransactionProfiler

* Master connections and writes on read requests will now be logged to
  get visibility into code that reduces performance and site availability.

bug: T88445
bug: T86862
Change-Id: Ic2ae95c33facbb54e062aef2ce67d6182caa044a
---
 includes/MediaWiki.php                    | 14 ++++
 includes/db/Database.php                  |  4 +
 includes/profiler/TransactionProfiler.php | 91 +++++++++++++++++++++++
 3 files changed, 109 insertions(+)

diff --git a/includes/MediaWiki.php b/includes/MediaWiki.php
index 431397fb40..669d8e945f 100644
--- a/includes/MediaWiki.php
+++ b/includes/MediaWiki.php
@@ -485,6 +485,16 @@ class MediaWiki {
 		$action = $this->getAction();
 		$wgTitle = $title;
 
+		// Aside from rollback, master queries should not happen on GET requests.
+		// Periodic or "in passing" updates on GET should use the job queue.
+		if ( !$request->wasPosted()
+			&& in_array( $action, array( 'view', 'edit', 'history' ) )
+		) {
+			$trxProfiler = Profiler::instance()->getTransactionProfiler();
+			$trxProfiler->setExpectation( 'masterConns', 0, __METHOD__ );
+			$trxProfiler->setExpectation( 'writes', 0, __METHOD__ );
+		}
+
 		// If the user has forceHTTPS set to true, or if the user
 		// is in a group requiring HTTPS, or if they have the HTTPS
 		// preference set, redirect them to HTTPS.
@@ -571,6 +581,10 @@ class MediaWiki {
 	 * Ends this task peacefully
 	 */
 	public function restInPeace() {
+		// Ignore things like master queries/connections on GET requests
+		// as long as they are in deferred updates (which catch errors).
+		Profiler::instance()->getTransactionProfiler()->resetExpectations();
+
 		// Do any deferred jobs
 		DeferredUpdates::doUpdates( 'commit' );
 
diff --git a/includes/db/Database.php b/includes/db/Database.php
index e95f134c01..edf13789bf 100644
--- a/includes/db/Database.php
+++ b/includes/db/Database.php
@@ -814,6 +814,10 @@ abstract class DatabaseBase implements IDatabase {
 		if ( $user ) {
 			$this->open( $server, $user, $password, $dbName );
 		}
+
+		$isMaster = !is_null( $this->getLBInfo( 'master' ) );
+		$trxProf = Profiler::instance()->getTransactionProfiler();
+		$trxProf->recordConnection( $this->mServer, $this->mDBname, $isMaster );
 	}
 
 	/**
diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php
index 3637781050..9609bd318f 100644
--- a/includes/profiler/TransactionProfiler.php
+++ b/includes/profiler/TransactionProfiler.php
@@ -42,6 +42,78 @@ class TransactionProfiler {
 	/** @var array transaction ID => list of (query name, start time, end time) */
 	protected $dbTrxMethodTimes = array();
 
+	/** @var array */
+	protected $hits = array(
+		'writes'      => 0,
+		'queries'     => 0,
+		'conns'       => 0,
+		'masterConns' => 0
+	);
+	/** @var array */
+	protected $expect = array(
+		'writes'      => INF,
+		'queries'     => INF,
+		'conns'       => INF,
+		'masterConns' => INF
+	);
+	/** @var array */
+	protected $expectBy = array();
+
+	/**
+	 * Set performance expectations
+	 *
+	 * With conflicting expect, the most specific ones will be used
+	 *
+	 * @param string $event (writes,queries,conns,mConns)
+	 * @param integer $value Maximum count of the event
+	 * @param string $fname Caller
+	 * @since 1.25
+	 */
+	public function setExpectation( $event, $value, $fname ) {
+		$this->expect[$event] = isset( $this->expect[$event] )
+			? min( $this->expect[$event], $value )
+			: $value;
+		if ( $this->expect[$event] == $value ) {
+			$this->expectBy[$event] = $fname;
+		}
+	}
+
+	/**
+	 * Reset performance expectations and hit counters
+	 *
+	 * @since 1.25
+	 */
+	public function resetExpectations() {
+		foreach ( $this->hits as &$val ) {
+			$val = 0;
+		}
+		unset( $val );
+		foreach ( $this->expect as &$val ) {
+			$val = INF;
+		}
+		unset( $val );
+		$this->expectBy = array();
+	}
+
+	/**
+	 * Mark a DB as having been connected to with a new handle
+	 *
+	 * Note that there can be multiple connections to a single DB.
+	 *
+	 * @param string $server DB server
+	 * @param string $db DB name
+	 * @param bool $isMaster
+	 */
+	public function recordConnection( $server, $db, $isMaster ) {
+		// Report when too many connections happen...
+		if ( $this->hits['conns']++ == $this->expect['conns'] ) {
+			$this->reportExpectationViolated( 'conns', "[connect to $server ($db)]" );
+		}
+		if ( $isMaster && $this->hits['masterConns']++ == $this->expect['masterConns'] ) {
+			$this->reportExpectationViolated( 'masterConns', "[connect to $server ($db)]" );
+		}
+	}
+
 	/**
 	 * Mark a DB as in a transaction with one or more writes pending
 	 *
@@ -87,6 +159,14 @@ class TransactionProfiler {
 				"Query affected $n rows:\n" . $query . "\n" . wfBacktrace( true ) );
 		}
 
+		// Report when too many writes/queries happen...
+		if ( $this->hits['queries']++ == $this->expect['queries'] ) {
+			$this->reportExpectationViolated( 'queries', $query );
+		}
+		if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) {
+			$this->reportExpectationViolated( 'writes', $query );
+		}
+
 		if ( !$this->dbTrxHoldingLocks ) {
 			// Short-circuit
 			return;
@@ -163,4 +243,15 @@ class TransactionProfiler {
 		unset( $this->dbTrxHoldingLocks[$name] );
 		unset( $this->dbTrxMethodTimes[$name] );
 	}
+
+	/**
+	 * @param string $expect
+	 * @param string $query
+	 */
+	protected function reportExpectationViolated( $expect, $query ) {
+		$n = $this->expect[$expect];
+		$by = $this->expectBy[$expect];
+		wfDebugLog( 'DBPerformance',
+			"Expectation ($expect <= $n) by $by not met:\n$query\n" . wfBacktrace( true ) );
+	}
 }
-- 
2.20.1