Merge "rdbms: improve query logging logic in Database"
authorjenkins-bot <jenkins-bot@gerrit.wikimedia.org>
Tue, 21 May 2019 22:12:32 +0000 (22:12 +0000)
committerGerrit Code Review <gerrit@wikimedia.org>
Tue, 21 May 2019 22:12:32 +0000 (22:12 +0000)
1  2 
autoload.php
includes/libs/rdbms/database/Database.php
includes/libs/rdbms/database/IDatabase.php

diff --combined autoload.php
@@@ -528,6 -528,7 +528,6 @@@ $wgAutoloadLocalClasses = 
        'FileOpBatch' => __DIR__ . '/includes/libs/filebackend/FileOpBatch.php',
        'FileOpPerfTest' => __DIR__ . '/maintenance/fileOpPerfTest.php',
        'FileRepo' => __DIR__ . '/includes/filerepo/FileRepo.php',
 -      'FileRepoStatus' => __DIR__ . '/includes/filerepo/FileRepoStatus.php',
        'FindDeprecated' => __DIR__ . '/maintenance/findDeprecated.php',
        'FindHooks' => __DIR__ . '/maintenance/findHooks.php',
        'FindMissingFiles' => __DIR__ . '/maintenance/findMissingFiles.php',
        'SearchUpdate' => __DIR__ . '/includes/deferred/SearchUpdate.php',
        'SectionProfileCallback' => __DIR__ . '/includes/profiler/SectionProfileCallback.php',
        'SectionProfiler' => __DIR__ . '/includes/profiler/SectionProfiler.php',
 -      'SevenZipStream' => __DIR__ . '/maintenance/7zip.inc',
 +      'SevenZipStream' => __DIR__ . '/maintenance/includes/SevenZipStream.php',
        'ShiConverter' => __DIR__ . '/languages/classes/LanguageShi.php',
        'ShortPagesPage' => __DIR__ . '/includes/specials/SpecialShortpages.php',
        'ShowJobs' => __DIR__ . '/maintenance/showJobs.php',
        'TemplatesOnThisPageFormatter' => __DIR__ . '/includes/TemplatesOnThisPageFormatter.php',
        'TextContent' => __DIR__ . '/includes/content/TextContent.php',
        'TextContentHandler' => __DIR__ . '/includes/content/TextContentHandler.php',
 -      'TextPassDumper' => __DIR__ . '/maintenance/dumpTextPass.php',
 +      'TextPassDumper' => __DIR__ . '/maintenance/includes/TextPassDumper.php',
        'TextSlotDiffRenderer' => __DIR__ . '/includes/diff/TextSlotDiffRenderer.php',
        'TextStatsOutput' => __DIR__ . '/maintenance/language/StatOutputs.php',
        'TgConverter' => __DIR__ . '/languages/classes/LanguageTg.php',
        'Wikimedia\\Rdbms\\DBError' => __DIR__ . '/includes/libs/rdbms/exception/DBError.php',
        'Wikimedia\\Rdbms\\DBExpectedError' => __DIR__ . '/includes/libs/rdbms/exception/DBExpectedError.php',
        'Wikimedia\\Rdbms\\DBMasterPos' => __DIR__ . '/includes/libs/rdbms/database/position/DBMasterPos.php',
+       'Wikimedia\\Rdbms\\DBQueryDisconnectedError' => __DIR__ . '/includes/libs/rdbms/exception/DBQueryDisconnectedError.php',
        'Wikimedia\\Rdbms\\DBQueryError' => __DIR__ . '/includes/libs/rdbms/exception/DBQueryError.php',
        'Wikimedia\\Rdbms\\DBQueryTimeoutError' => __DIR__ . '/includes/libs/rdbms/exception/DBQueryTimeoutError.php',
        'Wikimedia\\Rdbms\\DBReadOnlyError' => __DIR__ . '/includes/libs/rdbms/exception/DBReadOnlyError.php',
        'Wikimedia\\Rdbms\\DatabaseSqlite' => __DIR__ . '/includes/libs/rdbms/database/DatabaseSqlite.php',
        'Wikimedia\\Rdbms\\FakeResultWrapper' => __DIR__ . '/includes/libs/rdbms/database/resultwrapper/FakeResultWrapper.php',
        'Wikimedia\\Rdbms\\Field' => __DIR__ . '/includes/libs/rdbms/field/Field.php',
+       'Wikimedia\\Rdbms\\GeneralizedSql' => __DIR__ . '/includes/libs/rdbms/database/utils/GeneralizedSql.php',
        'Wikimedia\\Rdbms\\IBlob' => __DIR__ . '/includes/libs/rdbms/encasing/IBlob.php',
        'Wikimedia\\Rdbms\\IDatabase' => __DIR__ . '/includes/libs/rdbms/database/IDatabase.php',
        'Wikimedia\\Rdbms\\ILBFactory' => __DIR__ . '/includes/libs/rdbms/lbfactory/ILBFactory.php',
        'Wikimedia\\Rdbms\\PostgresField' => __DIR__ . '/includes/libs/rdbms/field/PostgresField.php',
        'Wikimedia\\Rdbms\\ResultWrapper' => __DIR__ . '/includes/libs/rdbms/database/resultwrapper/ResultWrapper.php',
        'Wikimedia\\Rdbms\\SQLiteField' => __DIR__ . '/includes/libs/rdbms/field/SQLiteField.php',
 -      'Wikimedia\\Rdbms\\SavepointPostgres' => __DIR__ . '/includes/libs/rdbms/database/utils/SavepointPostgres.php',
        'Wikimedia\\Rdbms\\SessionConsistentConnectionManager' => __DIR__ . '/includes/libs/rdbms/connectionmanager/SessionConsistentConnectionManager.php',
        'Wikimedia\\Rdbms\\Subquery' => __DIR__ . '/includes/libs/rdbms/encasing/Subquery.php',
        'Wikimedia\\Rdbms\\TransactionProfiler' => __DIR__ . '/includes/libs/rdbms/TransactionProfiler.php',
@@@ -71,12 -71,13 +71,13 @@@ abstract class Database implements IDat
        /** @var int New Database instance will already be connected when returned */
        const NEW_CONNECTED = 1;
  
-       /** @var string SQL query */
-       protected $lastQuery = '';
+       /** @var string The last SQL query attempted */
+       private $lastQuery = '';
        /** @var float|bool UNIX timestamp of last write query */
-       protected $lastWriteTime = false;
+       private $lastWriteTime = false;
        /** @var string|bool */
-       protected $phpError = false;
+       private $lastPhpError = false;
        /** @var string Server that this instance is currently connected to */
        protected $server;
        /** @var string User that this instance is currently connected under the name of */
         * Set a custom error handler for logging errors during database connection
         */
        protected function installErrorHandler() {
-               $this->phpError = false;
+               $this->lastPhpError = false;
                $this->htmlErrors = ini_set( 'html_errors', '0' );
                set_error_handler( [ $this, 'connectionErrorLogger' ] );
        }
         * @return string|bool Last PHP error for this DB (typically connection errors)
         */
        protected function getLastPHPError() {
-               if ( $this->phpError ) {
-                       $error = preg_replace( '!\[<a.*</a>\]!', '', $this->phpError );
+               if ( $this->lastPhpError ) {
+                       $error = preg_replace( '!\[<a.*</a>\]!', '', $this->lastPhpError );
                        $error = preg_replace( '!^.*?:\s?(.*)$!', '$1', $error );
  
                        return $error;
         * @param string $errstr
         */
        public function connectionErrorLogger( $errno, $errstr ) {
-               $this->phpError = $errstr;
+               $this->lastPhpError = $errstr;
        }
  
        /**
  
                $priorTransaction = $this->trxLevel;
                $priorWritesPending = $this->writesOrCallbacksPending();
-               $this->lastQuery = $sql;
  
                if ( $this->isWriteQuery( $sql ) ) {
                        # In theory, non-persistent writes are allowed in read-only mode, but due to things
        private function attemptQuery( $sql, $commentedSql, $isEffectiveWrite, $fname ) {
                $this->beginIfImplied( $sql, $fname );
  
-               # Keep track of whether the transaction has write queries pending
+               // Keep track of whether the transaction has write queries pending
                if ( $isEffectiveWrite ) {
                        $this->lastWriteTime = microtime( true );
                        if ( $this->trxLevel && !$this->trxDoneWrites ) {
                        }
                }
  
-               if ( $this->getFlag( self::DBO_DEBUG ) ) {
-                       $this->queryLogger->debug( "{$this->getDomainID()} {$commentedSql}" );
-               }
-               $isMaster = !is_null( $this->getLBInfo( 'master' ) );
-               # generalizeSQL() will probably cut down the query to reasonable
-               # logging size most of the time. The substr is really just a sanity check.
-               if ( $isMaster ) {
-                       $queryProf = 'query-m: ' . substr( self::generalizeSQL( $sql ), 0, 255 );
-               } else {
-                       $queryProf = 'query: ' . substr( self::generalizeSQL( $sql ), 0, 255 );
-               }
-               # Include query transaction state
-               $queryProf .= $this->trxShortId ? " [TRX#{$this->trxShortId}]" : "";
+               $prefix = !is_null( $this->getLBInfo( 'master' ) ) ? 'query-m: ' : 'query: ';
+               $generalizedSql = new GeneralizedSql( $sql, $this->trxShortId, $prefix );
  
                $startTime = microtime( true );
-               $ps = $this->profiler ? ( $this->profiler )( $queryProf ) : null;
+               $ps = $this->profiler
+                       ? ( $this->profiler )( $generalizedSql->stringify() )
+                       : null;
                $this->affectedRowCount = null;
+               $this->lastQuery = $sql;
                $ret = $this->doQuery( $commentedSql );
                $this->affectedRowCount = $this->affectedRows();
                unset( $ps ); // profile out (if set)
                }
  
                $this->trxProfiler->recordQueryCompletion(
-                       $queryProf,
+                       $generalizedSql,
                        $startTime,
                        $isEffectiveWrite,
                        $isEffectiveWrite ? $this->affectedRows() : $this->numRows( $ret )
                );
-               $this->queryLogger->debug( $sql, [
-                       'method' => $fname,
-                       'master' => $isMaster,
-                       'runtime' => $queryRuntime,
-               ] );
+               // Avoid the overhead of logging calls unless debug mode is enabled
+               if ( $this->getFlag( self::DBO_DEBUG ) ) {
+                       $this->queryLogger->debug(
+                               "{method} [{runtime}s]: $sql",
+                               [
+                                       'method' => $fname,
+                                       'db_host' => $this->getServer(),
+                                       'domain' => $this->getDomainID(),
+                                       'runtime' => round( $queryRuntime, 3 )
+                               ]
+                       );
+               }
  
                return $ret;
        }
         * @param int $errno
         * @param string $sql
         * @param string $fname
-        * @param bool $ignoreErrors
+        * @param bool $ignore
         * @throws DBQueryError
         */
-       public function reportQueryError( $error, $errno, $sql, $fname, $ignoreErrors = false ) {
-               if ( $ignoreErrors ) {
+       public function reportQueryError( $error, $errno, $sql, $fname, $ignore = false ) {
+               if ( $ignore ) {
                        $this->queryLogger->debug( "SQL ERROR (ignored): $error\n" );
                } else {
                        $exception = $this->getQueryExceptionAndLog( $error, $errno, $sql, $fname );
                        ] )
                );
                $this->queryLogger->debug( "SQL ERROR: " . $error . "\n" );
-               $wasQueryTimeout = $this->wasQueryTimeout( $error, $errno );
-               if ( $wasQueryTimeout ) {
+               if ( $this->wasQueryTimeout( $error, $errno ) ) {
                        $e = new DBQueryTimeoutError( $this, $error, $errno, $sql, $fname );
+               } elseif ( $this->wasConnectionError( $errno ) ) {
+                       $e = new DBQueryDisconnectedError( $this, $error, $errno, $sql, $fname );
                } else {
                        $e = new DBQueryError( $this, $error, $errno, $sql, $fname );
                }
                $options['LIMIT'] = 1;
  
                $res = $this->select( $table, $var, $cond, $fname, $options, $join_conds );
 -              if ( $res === false || !$this->numRows( $res ) ) {
 -                      return false;
 +              if ( $res === false ) {
 +                      throw new DBUnexpectedError( $this, "Got false from select()" );
                }
  
                $row = $this->fetchRow( $res );
 -
 -              if ( $row !== false ) {
 -                      return reset( $row );
 -              } else {
 +              if ( $row === false ) {
                        return false;
                }
 +
 +              return reset( $row );
        }
  
        public function selectFieldValues(
  
                $res = $this->select( $table, [ 'value' => $var ], $cond, $fname, $options, $join_conds );
                if ( $res === false ) {
 -                      return false;
 +                      throw new DBUnexpectedError( $this, "Got false from select()" );
                }
  
                $values = [];
        ) {
                $options = (array)$options;
                $options['LIMIT'] = 1;
 -              $res = $this->select( $table, $vars, $conds, $fname, $options, $join_conds );
  
 +              $res = $this->select( $table, $vars, $conds, $fname, $options, $join_conds );
                if ( $res === false ) {
 -                      return false;
 +                      throw new DBUnexpectedError( $this, "Got false from select()" );
                }
  
                if ( !$this->numRows( $res ) ) {
                        return false;
                }
  
 -              $obj = $this->fetchObject( $res );
 -
 -              return $obj;
 +              return $this->fetchObject( $res );
        }
  
        public function estimateRowCount(
                return $this->selectRowCount( $table, '*', $conds, $fname, $options, $join_conds );
        }
  
-       /**
-        * Removes most variables from an SQL query and replaces them with X or N for numbers.
-        * It's only slightly flawed. Don't use for anything important.
-        *
-        * @param string $sql A SQL Query
-        *
-        * @return string
-        */
-       protected static function generalizeSQL( $sql ) {
-               # This does the same as the regexp below would do, but in such a way
-               # as to avoid crashing php on some large strings.
-               # $sql = preg_replace( "/'([^\\\\']|\\\\.)*'|\"([^\\\\\"]|\\\\.)*\"/", "'X'", $sql );
-               $sql = str_replace( "\\\\", '', $sql );
-               $sql = str_replace( "\\'", '', $sql );
-               $sql = str_replace( "\\\"", '', $sql );
-               $sql = preg_replace( "/'.*'/s", "'X'", $sql );
-               $sql = preg_replace( '/".*"/s', "'X'", $sql );
-               # All newlines, tabs, etc replaced by single space
-               $sql = preg_replace( '/\s+/', ' ', $sql );
-               # All numbers => N,
-               # except the ones surrounded by characters, e.g. l10n
-               $sql = preg_replace( '/-?\d+(,-?\d+)+/s', 'N,...,N', $sql );
-               $sql = preg_replace( '/(?<![a-zA-Z])-?\d+(?![a-zA-Z])/s', 'N', $sql );
-               return $sql;
-       }
        public function fieldExists( $table, $field, $fname = __METHOD__ ) {
                $info = $this->fieldInfo( $table, $field );
  
@@@ -247,8 -247,8 +247,8 @@@ interface IDatabase 
        public function implicitOrderby();
  
        /**
-        * Return the last query that went through IDatabase::query()
-        * @return string
+        * Return the last query that sent on account of IDatabase::query()
+        * @return string SQL text or empty string if there was no such query
         */
        public function lastQuery();
  
         *     is applied to a result set after OFFSET.
         *
         *   - FOR UPDATE: Boolean: lock the returned rows so that they can't be
 -       *     changed until the next COMMIT.
 +       *     changed until the next COMMIT. Cannot be used with aggregate functions
 +       *     (COUNT, MAX, etc., but also DISTINCT).
         *
         *   - DISTINCT: Boolean: return only unique result rows.
         *