From 7ea13643f5884dcfb2a8b4e22ae45858a81940b6 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Sun, 26 Apr 2015 11:26:49 -0700 Subject: [PATCH] Added $wgTrxProfilerLimits and slow query limits * Limits are now configurable instead of being hard-coded Change-Id: I99133586eb82e8e9e84061548c8d1a99695fde5c --- includes/DefaultSettings.php | 15 ++++++++ includes/MediaWiki.php | 7 ++-- includes/jobqueue/JobRunner.php | 4 +-- includes/profiler/TransactionProfiler.php | 43 ++++++++++++++++++----- maintenance/Maintenance.php | 5 ++- 5 files changed, 57 insertions(+), 17 deletions(-) diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php index a16a1f02b6..d35683e43d 100644 --- a/includes/DefaultSettings.php +++ b/includes/DefaultSettings.php @@ -5295,6 +5295,21 @@ $wgDebugDumpSql = false; */ $wgDebugDumpSqlLength = 500; +/** + * Performance expectations for DB usage + * + * @since 1.26 + */ +$wgTrxProfilerLimits = array( + // Basic GET and POST requests + 'GET' => array( 'masterConns' => 0, 'writes' => 0, 'readQueryTime' => 5 ), + 'POST' => array( 'maxAffected' => 500, 'readQueryTime' => 5, 'writeQueryTime' => 1 ), + // Background job runner + 'JobRunner' => array( 'maxAffected' => 500, 'readQueryTime' => 30, 'writeQueryTime' => 5 ), + // Command-line scripts + 'Maintenance' => array( 'maxAffected' => 1000, 'writeQueryTime' => 5 ) +); + /** * Map of string log group names to log destinations. * diff --git a/includes/MediaWiki.php b/includes/MediaWiki.php index ec2f40f626..d0e81cffc6 100644 --- a/includes/MediaWiki.php +++ b/includes/MediaWiki.php @@ -457,7 +457,7 @@ class MediaWiki { } private function main() { - global $wgTitle; + global $wgTitle, $wgTrxProfilerLimits; $request = $this->context->getRequest(); @@ -489,10 +489,9 @@ class MediaWiki { if ( !$request->wasPosted() && in_array( $action, array( 'view', 'edit', 'history' ) ) ) { - $trxProfiler->setExpectation( 'masterConns', 0, __METHOD__ ); - $trxProfiler->setExpectation( 'writes', 0, __METHOD__ ); + $trxProfiler->setExpectations( $wgTrxProfilerLimits['GET'], __METHOD__ ); } else { - $trxProfiler->setExpectation( 'maxAffected', 500, __METHOD__ ); + $trxProfiler->setExpectations( $wgTrxProfilerLimits['POST'], __METHOD__ ); } // If the user has forceHTTPS set to true, or if the user diff --git a/includes/jobqueue/JobRunner.php b/includes/jobqueue/JobRunner.php index 94254239c1..e9ae30e1e0 100644 --- a/includes/jobqueue/JobRunner.php +++ b/includes/jobqueue/JobRunner.php @@ -88,7 +88,7 @@ class JobRunner implements LoggerAwareInterface { * @return array Summary response that can easily be JSON serialized */ public function run( array $options ) { - global $wgJobClasses; + global $wgJobClasses, $wgTrxProfilerLimits; $response = array( 'jobs' => array(), 'reached' => 'none-ready' ); @@ -120,7 +120,7 @@ class JobRunner implements LoggerAwareInterface { // Catch huge single updates that lead to slave lag $trxProfiler = Profiler::instance()->getTransactionProfiler(); $trxProfiler->setLogger( LoggerFactory::getInstance( 'DBPerformance' ) ); - $trxProfiler->setExpectation( 'maxAffected', 500, __METHOD__ ); + $trxProfiler->setExpectations( $wgTrxProfilerLimits['JobRunner'], __METHOD__ ); // Bail out if there is too much DB lag. // This check should not block as we want to try other wiki queues. diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php index f02d66f8d3..5f2a57a5bc 100644 --- a/includes/profiler/TransactionProfiler.php +++ b/includes/profiler/TransactionProfiler.php @@ -25,6 +25,7 @@ use Psr\Log\LoggerInterface; use Psr\Log\LoggerAwareInterface; use Psr\Log\NullLogger; + /** * Helper class that detects high-contention DB queries via profiling calls * @@ -52,11 +53,13 @@ class TransactionProfiler implements LoggerAwareInterface { ); /** @var array */ protected $expect = array( - 'writes' => INF, - 'queries' => INF, - 'conns' => INF, - 'masterConns' => INF, - 'maxAffected' => INF + 'writes' => INF, + 'queries' => INF, + 'conns' => INF, + 'masterConns' => INF, + 'maxAffected' => INF, + 'readQueryTime' => INF, + 'writeQueryTime' => INF, ); /** @var array */ protected $expectBy = array(); @@ -77,7 +80,7 @@ class TransactionProfiler implements LoggerAwareInterface { /** * Set performance expectations * - * With conflicting expect, the most specific ones will be used + * With conflicting expectations, the most narrow ones will be used * * @param string $event (writes,queries,conns,mConns) * @param integer $value Maximum count of the event @@ -93,6 +96,21 @@ class TransactionProfiler implements LoggerAwareInterface { } } + /** + * Set multiple performance expectations + * + * With conflicting expectations, the most narrow ones will be used + * + * @param array $expects Map of (event => limit) + * @param $fname + * @since 1.26 + */ + public function setExpectations( array $expects, $fname ) { + foreach ( $expects as $event => $value ) { + $this->setExpectation( $event, $value, $fname ); + } + } + /** * Reset performance expectations and hit counters * @@ -170,7 +188,8 @@ class TransactionProfiler implements LoggerAwareInterface { $elapsed = ( $eTime - $sTime ); if ( $isWrite && $n > $this->expect['maxAffected'] ) { - $this->logger->info( "Query affected $n row(s):\n" . $query . "\n" . wfBacktrace( true ) ); + $this->logger->info( "Query affected $n row(s):\n" . $query . "\n" . + wfBacktrace( true ) ); } // Report when too many writes/queries happen... @@ -180,6 +199,13 @@ class TransactionProfiler implements LoggerAwareInterface { if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) { $this->reportExpectationViolated( 'writes', $query ); } + // Report slow queries... + if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) { + $this->reportExpectationViolated( 'readQueryTime', $query ); + } + if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) { + $this->reportExpectationViolated( 'writeQueryTime', $query ); + } if ( !$this->dbTrxHoldingLocks ) { // Short-circuit @@ -268,7 +294,8 @@ class TransactionProfiler implements LoggerAwareInterface { $n = $this->expect[$expect]; $by = $this->expectBy[$expect]; $this->logger->info( - "[{$wgRequest->getMethod()}] Expectation ($expect <= $n) by $by not met:\n$query\n" . wfBacktrace( true ) + "[{$wgRequest->getMethod()}] Expectation ($expect <= $n) by $by not met:\n$query\n" . + wfBacktrace( true ) ); } } diff --git a/maintenance/Maintenance.php b/maintenance/Maintenance.php index f97f6dca9c..50b8a01275 100644 --- a/maintenance/Maintenance.php +++ b/maintenance/Maintenance.php @@ -603,7 +603,7 @@ abstract class Maintenance { * Activate the profiler (assuming $wgProfiler is set) */ protected function activateProfiler() { - global $wgProfiler; + global $wgProfiler, $wgTrxProfilerLimits; $output = $this->getOption( 'profiler' ); if ( $output && is_array( $wgProfiler ) && isset( $wgProfiler['class'] ) ) { @@ -617,8 +617,7 @@ abstract class Maintenance { $trxProfiler = Profiler::instance()->getTransactionProfiler(); $trxProfiler->setLogger( LoggerFactory::getInstance( 'DBPerformance' ) ); - # Catch huge single updates that lead to slave lag - $trxProfiler->setExpectation( 'maxAffected', 1000, __METHOD__ ); + $trxProfiler->setExpectations( $wgTrxProfilerLimits['Maintenance'], __METHOD__ ); } /** -- 2.20.1