From e0cc49ce3971e19ef7b18c3e89897979564d3a01 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Mon, 6 May 2019 17:01:03 -0700 Subject: [PATCH] rdbms: improve query logging logic in Database * Merge the two debug() calls in attemptQuery() into one single call which checks DBO_DEBUG. This avoids pointless SPI logger overhead. * Avoid calling generalizeSQL() unless actually necessary. This works via a lazy-loading object. * Make lastQuery() a bit more consistent in terms of when it gets updated. * Add DBQueryDisconnectedError class for dropped connections. * Clean up visbility and names of last query/error fields. Change-Id: Ie8df3434d23b18f7a0f4c056d71388192cc52c6b --- autoload.php | 2 + includes/db/MWLBFactory.php | 2 + includes/libs/rdbms/TransactionProfiler.php | 21 +++- includes/libs/rdbms/database/Database.php | 103 ++++++------------ includes/libs/rdbms/database/IDatabase.php | 4 +- .../rdbms/database/utils/GeneralizedSql.php | 95 ++++++++++++++++ .../exception/DBQueryDisconnectedError.php | 30 +++++ 7 files changed, 182 insertions(+), 75 deletions(-) create mode 100644 includes/libs/rdbms/database/utils/GeneralizedSql.php create mode 100644 includes/libs/rdbms/exception/DBQueryDisconnectedError.php diff --git a/autoload.php b/autoload.php index 5d3e578b20..96b0ce8979 100644 --- a/autoload.php +++ b/autoload.php @@ -1637,6 +1637,7 @@ $wgAutoloadLocalClasses = [ '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', @@ -1655,6 +1656,7 @@ $wgAutoloadLocalClasses = [ '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', diff --git a/includes/db/MWLBFactory.php b/includes/db/MWLBFactory.php index be4f6ba57c..5b629844b4 100644 --- a/includes/db/MWLBFactory.php +++ b/includes/db/MWLBFactory.php @@ -56,6 +56,7 @@ abstract class MWLBFactory { 'DBuser', 'DBWindowsAuthentication', 'DebugDumpSql', + 'DebugLogFile', 'ExternalServers', 'SQLiteDataDir', 'SQLMode', @@ -206,6 +207,7 @@ abstract class MWLBFactory { $flags = DBO_DEFAULT; $flags |= $options->get( 'DebugDumpSql' ) ? DBO_DEBUG : 0; + $flags |= $options->get( 'DebugLogFile' ) ? DBO_DEBUG : 0; if ( $server['type'] === 'oracle' ) { $flags |= $options->get( 'DBOracleDRCP' ) ? DBO_PERSISTENT : 0; } diff --git a/includes/libs/rdbms/TransactionProfiler.php b/includes/libs/rdbms/TransactionProfiler.php index e4dad01dda..c89820d3ab 100644 --- a/includes/libs/rdbms/TransactionProfiler.php +++ b/includes/libs/rdbms/TransactionProfiler.php @@ -218,7 +218,7 @@ class TransactionProfiler implements LoggerAwareInterface { * * This assumes that all queries are synchronous (non-overlapping) * - * @param string $query Function name or generalized SQL + * @param string|GeneralizedSql $query Function name or generalized SQL * @param float $sTime Starting UNIX wall time * @param bool $isWrite Whether this is a write query * @param int $n Number of affected/read rows @@ -229,11 +229,11 @@ class TransactionProfiler implements LoggerAwareInterface { if ( $isWrite && $n > $this->expect['maxAffected'] ) { $this->logger->warning( - "Query affected $n row(s):\n" . $query . "\n" . + "Query affected $n row(s):\n" . self::queryString( $query ) . "\n" . ( new RuntimeException() )->getTraceAsString() ); } elseif ( !$isWrite && $n > $this->expect['readQueryRows'] ) { $this->logger->warning( - "Query returned $n row(s):\n" . $query . "\n" . + "Query returned $n row(s):\n" . self::queryString( $query ) . "\n" . ( new RuntimeException() )->getTraceAsString() ); } @@ -341,7 +341,8 @@ class TransactionProfiler implements LoggerAwareInterface { $trace = ''; foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) { list( $query, $sTime, $end ) = $info; - $trace .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query ); + $trace .= sprintf( + "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self::queryString( $query ) ); } $this->logger->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [ 'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ), @@ -354,7 +355,7 @@ class TransactionProfiler implements LoggerAwareInterface { /** * @param string $expect - * @param string $query + * @param string|GeneralizedSql $query * @param string|float|int $actual */ protected function reportExpectationViolated( $expect, $query, $actual ) { @@ -370,8 +371,16 @@ class TransactionProfiler implements LoggerAwareInterface { 'max' => $this->expect[$expect], 'by' => $this->expectBy[$expect], 'actual' => $actual, - 'query' => $query + 'query' => self::queryString( $query ) ] ); } + + /** + * @param GeneralizedSql|string $query + * @return string + */ + private static function queryString( $query ) { + return $query instanceof GeneralizedSql ? $query->stringify() : $query; + } } diff --git a/includes/libs/rdbms/database/Database.php b/includes/libs/rdbms/database/Database.php index 6e30d3fca4..a55d682266 100644 --- a/includes/libs/rdbms/database/Database.php +++ b/includes/libs/rdbms/database/Database.php @@ -71,12 +71,13 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware /** @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 */ @@ -874,7 +875,7 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware * 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' ] ); } @@ -897,8 +898,8 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware * @return string|bool Last PHP error for this DB (typically connection errors) */ protected function getLastPHPError() { - if ( $this->phpError ) { - $error = preg_replace( '!\[\]!', '', $this->phpError ); + if ( $this->lastPhpError ) { + $error = preg_replace( '!\[\]!', '', $this->lastPhpError ); $error = preg_replace( '!^.*?:\s?(.*)$!', '$1', $error ); return $error; @@ -915,7 +916,7 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware * @param string $errstr */ public function connectionErrorLogger( $errno, $errstr ) { - $this->phpError = $errstr; + $this->lastPhpError = $errstr; } /** @@ -1197,7 +1198,6 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware $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 @@ -1290,7 +1290,7 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware 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 ) { @@ -1300,25 +1300,15 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware } } - 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) @@ -1337,16 +1327,24 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware } $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; } @@ -1546,11 +1544,11 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware * @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 ); @@ -1580,9 +1578,10 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware ] ) ); $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 ); } @@ -2036,36 +2035,6 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware 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( '/(?fieldInfo( $table, $field ); diff --git a/includes/libs/rdbms/database/IDatabase.php b/includes/libs/rdbms/database/IDatabase.php index 05f787cfa9..0e75e015aa 100644 --- a/includes/libs/rdbms/database/IDatabase.php +++ b/includes/libs/rdbms/database/IDatabase.php @@ -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(); diff --git a/includes/libs/rdbms/database/utils/GeneralizedSql.php b/includes/libs/rdbms/database/utils/GeneralizedSql.php new file mode 100644 index 0000000000..db5c639c56 --- /dev/null +++ b/includes/libs/rdbms/database/utils/GeneralizedSql.php @@ -0,0 +1,95 @@ +rawSql = $rawSql; + $this->trxId = $trxId; + $this->prefix = $prefix; + } + + /** + * 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 + */ + private 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( '/(?genericSql !== null ) { + return $this->genericSql; + } + + $this->genericSql = $this->prefix . + substr( self::generalizeSQL( $this->rawSql ), 0, 255 ) . + ( $this->trxId ? " [TRX#{$this->trxId}]" : "" ); + + return $this->genericSql; + } +} diff --git a/includes/libs/rdbms/exception/DBQueryDisconnectedError.php b/includes/libs/rdbms/exception/DBQueryDisconnectedError.php new file mode 100644 index 0000000000..a142b4a21b --- /dev/null +++ b/includes/libs/rdbms/exception/DBQueryDisconnectedError.php @@ -0,0 +1,30 @@ +