Hello Krinkle, Hashar,
I'd like you to do a code review. Please visit
https://gerrit.wikimedia.org/r/289368
to review the following change.
Change subject: Make it TransactionProfiler's job to report query times to the
profiler
......................................................................
Make it TransactionProfiler's job to report query times to the profiler
* Move DatabaseBase::generalizeSQL() -> TransactionProfiler::generalizeSQL()
* Only generalize SQL if we need to log the query (that is, if an expectation
has been violated, or if a profiler is running.) This gets rid of a lot of
pointless DatabaseBase::generalizeSQL() calls, especially in the unit tests.
* Use TransactionProfiler::reportExpectationViolated() to report maxAffected
violations. Do this by making 'expectBy' optional.
* Make it TransactionProfiler's job to report the query to the Profiler
instance.
This required adding $isMaster and $id parameters to
TransactionProfiler::reportExpectationViolated(), but it has no callers
outside core, and there are already other methods on TransactionProfilers
that take these parameters.
Change-Id: Ib927376a73cef8b51d8e97bf28e4766a399f29c4
---
M includes/db/Database.php
M includes/profiler/TransactionProfiler.php
2 files changed, 70 insertions(+), 63 deletions(-)
git pull ssh://gerrit.wikimedia.org:29418/mediawiki/core
refs/changes/68/289368/1
diff --git a/includes/db/Database.php b/includes/db/Database.php
index 92e89b0..3c87899 100644
--- a/includes/db/Database.php
+++ b/includes/db/Database.php
@@ -820,23 +820,6 @@
}
$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(
DatabaseBase::generalizeSQL( $sql ), 0, 255 );
- $totalProf = 'DatabaseBase::query-master';
- } else {
- $queryProf = 'query: ' . substr(
DatabaseBase::generalizeSQL( $sql ), 0, 255 );
- $totalProf = 'DatabaseBase::query';
- }
- # Include query transaction state
- $queryProf .= $this->mTrxShortId ? "
[TRX#{$this->mTrxShortId}]" : "";
-
- $profiler = Profiler::instance();
- if ( !$profiler instanceof ProfilerStub ) {
- $totalProfSection = $profiler->scopedProfileIn(
$totalProf );
- $queryProfSection = $profiler->scopedProfileIn(
$queryProf );
- }
if ( $this->debug() ) {
wfDebugLog( 'queries', sprintf( "%s: %s",
$this->mDBname, $commentedSql ) );
@@ -853,7 +836,7 @@
$queryRuntime = microtime( true ) - $startTime;
# Log the query time and feed it into the DB trx profiler
$this->getTransactionProfiler()->recordQueryCompletion(
- $queryProf, $startTime, $isWriteQuery,
$this->affectedRows() );
+ $sql, $startTime, $isWriteQuery, $this->affectedRows(),
$isMaster, $this->mTrxShortId );
MWDebug::queryTime( $queryId );
@@ -889,7 +872,7 @@
$queryRuntime = microtime( true ) -
$startTime;
# Log the query time and feed it into
the DB trx profiler
$this->getTransactionProfiler()->recordQueryCompletion(
- $queryProf, $startTime,
$isWriteQuery, $this->affectedRows() );
+ $sql, $startTime,
$isWriteQuery, $this->affectedRows(), $isMaster );
}
} else {
wfDebug( "Failed\n" );
@@ -902,10 +885,6 @@
}
$res = $this->resultObject( $ret );
-
- // Destroy profile sections in the opposite order to their
creation
- ScopedCallback::consume( $queryProfSection );
- ScopedCallback::consume( $totalProfSection );
if ( $isWriteQuery && $this->mTrxLevel ) {
$this->mTrxWriteDuration += $queryRuntime;
@@ -1334,35 +1313,6 @@
return $rows;
}
- /**
- * 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 );
diff --git a/includes/profiler/TransactionProfiler.php
b/includes/profiler/TransactionProfiler.php
index 1aba71c..37817d5 100644
--- a/includes/profiler/TransactionProfiler.php
+++ b/includes/profiler/TransactionProfiler.php
@@ -129,6 +129,36 @@
}
/**
+ * 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;
+ }
+
+ /**
* Mark a DB as having been connected to with a new handle
*
* Note that there can be multiple connections to a single DB.
@@ -178,18 +208,41 @@
*
* This assumes that all queries are synchronous (non-overlapping)
*
- * @param string $query Function name or generalized SQL
+ * @param string $query SQL query
* @param float $sTime Starting UNIX wall time
* @param bool $isWrite Whether this is a write query
* @param integer $n Number of affected rows
+ * @param bool $isMaster Whether this is a query of the master database
+ * @param string $id ID string of transaction, if any
*/
- public function recordQueryCompletion( $query, $sTime, $isWrite =
false, $n = 0 ) {
+ public function recordQueryCompletion( $query, $sTime, $isWrite, $n =
0, $isMaster = false, $id = '' ) {
$eTime = microtime( true );
$elapsed = ( $eTime - $sTime );
+ $profiler = Profiler::instance();
+ if ( !$profiler instanceof ProfilerStub ) {
+ // 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: ';
+ $totalProf = 'DatabaseBase::query-master';
+ } else {
+ $queryProf = 'query: ';
+ $totalProf = 'DatabaseBase::query';
+ }
+ $queryProf .= substr( self::generalizeSQL( $sql ), 0,
255 );
+ // Include query transaction state
+ $queryProf .= $id ? " [TRX#{$id}]" : "";
+ $totalProfSection = $profiler->scopedProfileIn(
$totalProf );
+ $queryProfSection = $profiler->scopedProfileIn(
$queryProf );
+ // Destroy profile sections in the opposite order to
their creation
+ ScopedCallback::consume( $queryProfSection );
+ ScopedCallback::consume( $totalProfSection );
+
+ }
+
if ( $isWrite && $n > $this->expect['maxAffected'] ) {
- $this->logger->info( "Query affected $n row(s):\n" .
$query . "\n" .
- wfBacktrace( true ) );
+ $this->reportExpectationViolated( 'maxAffected',
$query, $n );
}
// Report when too many writes/queries happen...
@@ -302,13 +355,17 @@
* @param string|float|int $actual [optional]
*/
protected function reportExpectationViolated( $expect, $query, $actual
= null ) {
- $n = $this->expect[$expect];
- $by = $this->expectBy[$expect];
- $actual = ( $actual !== null ) ? " (actual: $actual)" : "";
+ $query = self::generalizeSQL( $query );
- $this->logger->info(
- "Expectation ($expect <= $n) by $by not
met$actual:\n$query\n" .
- wfBacktrace( true )
- );
+ $msg = "Expectation ($expect <= {$this->expect[$expect]})";
+ if ( isset( $this->expectBy[$expect] ) ) {
+ $msg .= " by {$this->expectBy[$expect]}";
+ }
+ $msg .= ' not met';
+ if ( $actual !== null ) {
+ $msg .= " (actual: $actual)";
+ }
+ $msg .= ":\n$query\n" . wfBacktrace( true );
+ $this->logger->info( $msg );
}
}
--
To view, visit https://gerrit.wikimedia.org/r/289368
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: Ib927376a73cef8b51d8e97bf28e4766a399f29c4
Gerrit-PatchSet: 1
Gerrit-Project: mediawiki/core
Gerrit-Branch: master
Gerrit-Owner: Ori.livneh <[email protected]>
Gerrit-Reviewer: Hashar <[email protected]>
Gerrit-Reviewer: Krinkle <[email protected]>
_______________________________________________
MediaWiki-commits mailing list
[email protected]
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
