Add logging context to database logs
[lhc/web/wiklou.git] / includes / db / LoadBalancer.php
index f79fde0..233c92f 100644 (file)
@@ -58,8 +58,8 @@ class LoadBalancer {
        private $mLaggedSlaveMode;
        /** @var string The last DB selection or connection error */
        private $mLastError = 'Unknown error';
-       /** @var array Process cache of LoadMonitor::getLagTimes() */
-       private $mLagTimes;
+       /** @var ProcessCacheLRU */
+       private $mProcCache;
 
        /**
         * @param array $params Array with keys:
@@ -108,6 +108,8 @@ class LoadBalancer {
                                }
                        }
                }
+
+               $this->mProcCache = new ProcessCacheLRU( 30 );
        }
 
        /**
@@ -313,20 +315,6 @@ class LoadBalancer {
                return $i;
        }
 
-       /**
-        * Wait for a specified number of microseconds, and return the period waited
-        * @param int $t
-        * @return int
-        */
-       function sleep( $t ) {
-               wfProfileIn( __METHOD__ );
-               wfDebug( __METHOD__ . ": waiting $t us\n" );
-               usleep( $t );
-               wfProfileOut( __METHOD__ );
-
-               return $t;
-       }
-
        /**
         * Set the master wait position
         * If a DB_SLAVE connection has been opened already, waits
@@ -394,7 +382,9 @@ class LoadBalancer {
         * @return bool
         */
        protected function doWait( $index, $open = false, $timeout = null ) {
-               # Find a connection to wait on
+               $close = false; // close the connection afterwards
+
+               # Find a connection to wait on, creating one if needed and allowed
                $conn = $this->getAnyOpenConnection( $index );
                if ( !$conn ) {
                        if ( !$open ) {
@@ -408,6 +398,9 @@ class LoadBalancer {
 
                                        return false;
                                }
+                               // Avoid connection spam in waitForAll() when connections
+                               // are made just for the sake of doing this lag check.
+                               $close = true;
                        }
                }
 
@@ -417,14 +410,21 @@ class LoadBalancer {
 
                if ( $result == -1 || is_null( $result ) ) {
                        # Timed out waiting for slave, use master instead
-                       wfDebug( __METHOD__ . ": Timed out waiting for slave #$index pos {$this->mWaitForPos}\n" );
-
-                       return false;
+                       $server = $this->mServers[$index];
+                       $msg = __METHOD__ . ": Timed out waiting on $server pos {$this->mWaitForPos}";
+                       wfDebug( "$msg\n" );
+                       wfDebugLog( 'DBPerformance', "$msg:\n" . wfBacktrace( true ) );
+                       $ok = false;
                } else {
                        wfDebug( __METHOD__ . ": Done\n" );
+                       $ok = true;
+               }
 
-                       return true;
+               if ( $close ) {
+                       $this->closeConnection( $conn );
                }
+
+               return $ok;
        }
 
        /**
@@ -658,7 +658,9 @@ class LoadBalancer {
                        $conn = reset( $this->mConns['foreignFree'][$i] );
                        $oldWiki = key( $this->mConns['foreignFree'][$i] );
 
-                       if ( !$conn->selectDB( $dbName ) ) {
+                       // The empty string as a DB name means "don't care".
+                       // DatabaseMysqlBase::open() already handle this on connection.
+                       if ( $dbName !== '' && !$conn->selectDB( $dbName ) ) {
                                $this->mLastError = "Error selecting database $dbName on server " .
                                        $conn->getServer() . " from client host " . wfHostname() . "\n";
                                $this->mErrorConnection = $conn;
@@ -758,17 +760,27 @@ class LoadBalancer {
         */
        private function reportConnectionError() {
                $conn = $this->mErrorConnection; // The connection which caused the error
+               $context = array(
+                       'method' => __METHOD__,
+                       'last_error' => $this->mLastError,
+               );
 
                if ( !is_object( $conn ) ) {
                        // No last connection, probably due to all servers being too busy
-                       wfLogDBError( "LB failure with no last connection. Connection error: {$this->mLastError}" );
+                       wfLogDBError(
+                               "LB failure with no last connection. Connection error: {last_error}",
+                               $context
+                       );
 
                        // If all servers were busy, mLastError will contain something sensible
                        throw new DBConnectionError( null, $this->mLastError );
                } else {
-                       $server = $conn->getProperty( 'mServer' );
-                       wfLogDBError( "Connection error: {$this->mLastError} ({$server})" );
-                       $conn->reportConnectionError( "{$this->mLastError} ({$server})" ); // throws DBConnectionError
+                       $context['db_server'] = $conn->getProperty( 'mServer' );
+                       wfLogDBError(
+                               "Connection error: {last_error} ({db_server})",
+                               $context
+                       );
+                       $conn->reportConnectionError( "{$this->mLastError} ({$context['db_server']})" ); // throws DBConnectionError
                }
 
                return false; /* not reached */
@@ -1071,7 +1083,8 @@ class LoadBalancer {
        }
 
        /**
-        * Get the hostname and lag time of the most-lagged slave.
+        * Get the hostname and lag time of the most-lagged slave
+        *
         * This is useful for maintenance scripts that need to throttle their updates.
         * May attempt to open connections to slaves on the default DB. If there is
         * no lag, the maximum lag will be reported as -1.
@@ -1084,67 +1097,45 @@ class LoadBalancer {
                $host = '';
                $maxIndex = 0;
 
-               if ( $this->getServerCount() <= 1 ) { // no replication = no lag
-                       return array( $host, $maxLag, $maxIndex );
+               if ( $this->getServerCount() <= 1 ) {
+                       return array( $host, $maxLag, $maxIndex ); // no replication = no lag
                }
 
-               // Try to get the max lag info from the server cache
-               $key = 'loadbalancer:maxlag:cluster:' . $this->mServers[0]['host'];
-               $cache = ObjectCache::newAccelerator( array(), 'hash' );
-               $maxLagInfo = $cache->get( $key ); // (host, lag, index)
-
-               // Fallback to connecting to each slave and getting the lag
-               if ( !$maxLagInfo ) {
-                       foreach ( $this->mServers as $i => $conn ) {
-                               if ( $i == $this->getWriterIndex() ) {
-                                       continue; // nothing to check
-                               }
-                               $conn = false;
-                               if ( $wiki === false ) {
-                                       $conn = $this->getAnyOpenConnection( $i );
-                               }
-                               if ( !$conn ) {
-                                       $conn = $this->openConnection( $i, $wiki );
-                               }
-                               if ( !$conn ) {
-                                       continue;
-                               }
-                               $lag = $conn->getLag();
-                               if ( $lag > $maxLag ) {
-                                       $maxLag = $lag;
-                                       $host = $this->mServers[$i]['host'];
-                                       $maxIndex = $i;
-                               }
+               $lagTimes = $this->getLagTimes( $wiki );
+               foreach ( $lagTimes as $i => $lag ) {
+                       if ( $lag > $maxLag ) {
+                               $maxLag = $lag;
+                               $host = $this->mServers[$i]['host'];
+                               $maxIndex = $i;
                        }
-                       $maxLagInfo = array( $host, $maxLag, $maxIndex );
-                       $cache->set( $key, $maxLagInfo, 5 );
                }
 
-               return $maxLagInfo;
+               return array( $host, $maxLag, $maxIndex );
        }
 
        /**
         * Get lag time for each server
-        * Results are cached for a short time in memcached, and indefinitely in the process cache
+        *
+        * Results are cached for a short time in memcached/process cache
         *
         * @param string|bool $wiki
         * @return array Map of (server index => seconds)
         */
        function getLagTimes( $wiki = false ) {
-               # Try process cache
-               if ( isset( $this->mLagTimes ) ) {
-                       return $this->mLagTimes;
+               if ( $this->getServerCount() <= 1 ) {
+                       return array( 0 => 0 ); // no replication = no lag
                }
-               if ( $this->getServerCount() == 1 ) {
-                       # No replication
-                       $this->mLagTimes = array( 0 => 0 );
-               } else {
-                       # Send the request to the load monitor
-                       $this->mLagTimes = $this->getLoadMonitor()->getLagTimes(
-                               array_keys( $this->mServers ), $wiki );
+
+               if ( $this->mProcCache->has( 'slave_lag', 'times', 1 ) ) {
+                       return $this->mProcCache->get( 'slave_lag', 'times' );
                }
 
-               return $this->mLagTimes;
+               # Send the request to the load monitor
+               $times = $this->getLoadMonitor()->getLagTimes( array_keys( $this->mServers ), $wiki );
+
+               $this->mProcCache->set( 'slave_lag', 'times', $times );
+
+               return $times;
        }
 
        /**
@@ -1170,15 +1161,15 @@ class LoadBalancer {
        }
 
        /**
-        * Clear the cache for getLagTimes
+        * Clear the cache for slag lag delay times
         */
        function clearLagTimeCache() {
-               $this->mLagTimes = null;
+               $this->mProcCache->clear( 'slave_lag' );
        }
 }
 
 /**
- * Helper class to handle automatically marking connectons as reusable (via RAII pattern)
+ * Helper class to handle automatically marking connections as reusable (via RAII pattern)
  * as well handling deferring the actual network connection until the handle is used
  *
  * @ingroup Database