From: Aaron Schulz <aschulz@wikimedia.org>
Date: Thu, 22 Oct 2015 06:30:23 +0000 (-0700)
Subject: Make TransactionProfiler show the actual query times
X-Git-Tag: 1.31.0-rc.0~9288^2
X-Git-Url: https://git.cyclocoop.org/%242?a=commitdiff_plain;h=38bb2dc30e0a02d18f0f61fbcddd58cea89acee3;p=lhc%2Fweb%2Fwiklou.git

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
---

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 )
 		);
 	}