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

diff --git a/includes/MediaWiki.php b/includes/MediaWiki.php
index 431397f..669d8e9 100644 (file)
--- 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 e95f134..edf1378 100644 (file)
--- 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 3637781..9609bd3 100644 (file)
--- 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 ) );
+       }
 }