From 38bb2dc30e0a02d18f0f61fbcddd58cea89acee3 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Wed, 21 Oct 2015 23:30:23 -0700 Subject: [PATCH] Make TransactionProfiler show the actual query times Also removed HTTP method from the message as logstash gets those from the logger already Change-Id: I7a6d9cb3ec8c7fcb53a081ee2bd055ff8c1c72c1 --- includes/profiler/TransactionProfiler.php | 20 ++++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php index 46d6119ba9..2c9d108c9b 100644 --- a/includes/profiler/TransactionProfiler.php +++ b/includes/profiler/TransactionProfiler.php @@ -201,10 +201,10 @@ class TransactionProfiler implements LoggerAwareInterface { } // Report slow queries... if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) { - $this->reportExpectationViolated( 'readQueryTime', $query ); + $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed ); } if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) { - $this->reportExpectationViolated( 'writeQueryTime', $query ); + $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed ); } if ( !$this->dbTrxHoldingLocks ) { @@ -259,8 +259,11 @@ class TransactionProfiler implements LoggerAwareInterface { // Warn if too much time was spend writing... if ( $writeTime > $this->expect['writeQueryTime'] ) { - $this->reportExpectationViolated( 'writeQueryTime', - "[transaction $id writes to {$server} ({$db})]" ); + $this->reportExpectationViolated( + 'writeQueryTime', + "[transaction $id writes to {$server} ({$db})]", + $writeTime + ); $slow = true; } // Fill in the last non-query period... @@ -296,14 +299,15 @@ class TransactionProfiler implements LoggerAwareInterface { /** * @param string $expect * @param string $query + * @param string|float|int $actual [optional] */ - protected function reportExpectationViolated( $expect, $query ) { - global $wgRequest; - + protected function reportExpectationViolated( $expect, $query, $actual = null ) { $n = $this->expect[$expect]; $by = $this->expectBy[$expect]; + $actual = ( $actual !== null ) ? " (actual: $actual)" : ""; + $this->logger->info( - "[{$wgRequest->getMethod()}] Expectation ($expect <= $n) by $by not met:\n$query\n" . + "Expectation ($expect <= $n) by $by not met$actual:\n$query\n" . wfBacktrace( true ) ); } -- 2.20.1