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
This commit is contained in:
Aaron Schulz
parent
25ee9366b0
commit
e0cc49ce39
7 changed files with 182 additions and 75 deletions
|
|
@ -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',
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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( '!\[<a.*</a>\]!', '', $this->phpError );
|
||||
if ( $this->lastPhpError ) {
|
||||
$error = preg_replace( '!\[<a.*</a>\]!', '', $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( '/(?<![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 @@ 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();
|
||||
|
||||
|
|
|
|||
95
includes/libs/rdbms/database/utils/GeneralizedSql.php
Normal file
95
includes/libs/rdbms/database/utils/GeneralizedSql.php
Normal file
|
|
@ -0,0 +1,95 @@
|
|||
<?php
|
||||
/**
|
||||
* This program is free software; you can redistribute it and/or modify
|
||||
* it under the terms of the GNU General Public License as published by
|
||||
* the Free Software Foundation; either version 2 of the License, or
|
||||
* (at your option) any later version.
|
||||
*
|
||||
* This program is distributed in the hope that it will be useful,
|
||||
* but WITHOUT ANY WARRANTY; without even the implied warranty of
|
||||
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
|
||||
* GNU General Public License for more details.
|
||||
*
|
||||
* You should have received a copy of the GNU General Public License along
|
||||
* with this program; if not, write to the Free Software Foundation, Inc.,
|
||||
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
|
||||
* http://www.gnu.org/copyleft/gpl.html
|
||||
*
|
||||
* @file
|
||||
* @ingroup Profiler
|
||||
*/
|
||||
|
||||
namespace Wikimedia\Rdbms;
|
||||
|
||||
/**
|
||||
* Lazy-loaded wrapper for simplification and scrubbing of SQL queries for profiling
|
||||
*
|
||||
* @since 1.34
|
||||
*/
|
||||
class GeneralizedSql {
|
||||
/** @var string */
|
||||
private $rawSql;
|
||||
/** @var string */
|
||||
private $trxId;
|
||||
/** @var string */
|
||||
private $prefix;
|
||||
|
||||
/** @var string|null */
|
||||
private $genericSql;
|
||||
|
||||
/**
|
||||
* @param string $rawSql
|
||||
* @param string $trxId
|
||||
* @param string $prefix
|
||||
*/
|
||||
public function __construct( $rawSql, $trxId, $prefix ) {
|
||||
$this->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( '/(?<![a-zA-Z])-?\d+(?![a-zA-Z])/s', 'N', $sql );
|
||||
|
||||
return $sql;
|
||||
}
|
||||
|
||||
/**
|
||||
* @return string
|
||||
*/
|
||||
public function stringify() {
|
||||
if ( $this->genericSql !== null ) {
|
||||
return $this->genericSql;
|
||||
}
|
||||
|
||||
$this->genericSql = $this->prefix .
|
||||
substr( self::generalizeSQL( $this->rawSql ), 0, 255 ) .
|
||||
( $this->trxId ? " [TRX#{$this->trxId}]" : "" );
|
||||
|
||||
return $this->genericSql;
|
||||
}
|
||||
}
|
||||
30
includes/libs/rdbms/exception/DBQueryDisconnectedError.php
Normal file
30
includes/libs/rdbms/exception/DBQueryDisconnectedError.php
Normal file
|
|
@ -0,0 +1,30 @@
|
|||
<?php
|
||||
/**
|
||||
* This program is free software; you can redistribute it and/or modify
|
||||
* it under the terms of the GNU General Public License as published by
|
||||
* the Free Software Foundation; either version 2 of the License, or
|
||||
* (at your option) any later version.
|
||||
*
|
||||
* This program is distributed in the hope that it will be useful,
|
||||
* but WITHOUT ANY WARRANTY; without even the implied warranty of
|
||||
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
|
||||
* GNU General Public License for more details.
|
||||
*
|
||||
* You should have received a copy of the GNU General Public License along
|
||||
* with this program; if not, write to the Free Software Foundation, Inc.,
|
||||
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
|
||||
* http://www.gnu.org/copyleft/gpl.html
|
||||
*
|
||||
* @file
|
||||
* @ingroup Database
|
||||
*/
|
||||
|
||||
namespace Wikimedia\Rdbms;
|
||||
|
||||
/**
|
||||
* @ingroup Database
|
||||
* @since 1.34
|
||||
*/
|
||||
class DBQueryDisconnectedError extends DBQueryError {
|
||||
|
||||
}
|
||||
Loading…
Reference in a new issue