From e241d2c7edff9f681bebae97926ccdcc3c31a525 Mon Sep 17 00:00:00 2001
From: Kunal Mehta <legoktm@gmail.com>
Date: Fri, 27 Mar 2015 21:30:53 -0700
Subject: [PATCH] Use structured logging/MWLoggerFactory for
 TransactionProfiler

Change-Id: Id78c41623641562abe57546dfeb027fd0f437a15
---
 includes/MediaWiki.php                    |  1 +
 includes/profiler/TransactionProfiler.php | 32 +++++++++++++++++------
 2 files changed, 25 insertions(+), 8 deletions(-)

diff --git a/includes/MediaWiki.php b/includes/MediaWiki.php
index c086a39d1e..c4af16d6af 100644
--- a/includes/MediaWiki.php
+++ b/includes/MediaWiki.php
@@ -478,6 +478,7 @@ class MediaWiki {
 		$wgTitle = $title;
 
 		$trxProfiler = Profiler::instance()->getTransactionProfiler();
+		$trxProfiler->setLogger( MWLoggerFactory::getInstance( 'DBPerformance' ) );
 
 		// Aside from rollback, master queries should not happen on GET requests.
 		// Periodic or "in passing" updates on GET should use the job queue.
diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php
index b3135585f9..baec181789 100644
--- a/includes/profiler/TransactionProfiler.php
+++ b/includes/profiler/TransactionProfiler.php
@@ -22,6 +22,9 @@
  * @author Aaron Schulz
  */
 
+use Psr\Log\LoggerInterface;
+use Psr\Log\LoggerAwareInterface;
+use Psr\Log\NullLogger;
 /**
  * Helper class that detects high-contention DB queries via profiling calls
  *
@@ -29,7 +32,7 @@
  *
  * @since 1.24
  */
-class TransactionProfiler {
+class TransactionProfiler implements LoggerAwareInterface {
 	/** @var float Seconds */
 	protected $dbLockThreshold = 3.0;
 	/** @var float Seconds */
@@ -58,6 +61,19 @@ class TransactionProfiler {
 	/** @var array */
 	protected $expectBy = array();
 
+	/**
+	 * @var LoggerInterface
+	 */
+	private $logger;
+
+	public function __construct() {
+		$this->setLogger( new NullLogger() );
+	}
+
+	public function setLogger( LoggerInterface $logger ) {
+		$this->logger = $logger;
+	}
+
 	/**
 	 * Set performance expectations
 	 *
@@ -125,7 +141,7 @@ class TransactionProfiler {
 	public function transactionWritingIn( $server, $db, $id ) {
 		$name = "{$server} ({$db}) (TRX#$id)";
 		if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
-			wfDebugLog( 'DBPerformance', "Nested transaction for '$name' - out of sync." );
+			$this->logger->info( "Nested transaction for '$name' - out of sync." );
 		}
 		$this->dbTrxHoldingLocks[$name] = array(
 			'start' => microtime( true ),
@@ -154,8 +170,7 @@ class TransactionProfiler {
 		$elapsed = ( $eTime - $sTime );
 
 		if ( $isWrite && $n > $this->expect['maxAffected'] ) {
-			wfDebugLog( 'DBPerformance',
-				"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...
@@ -209,7 +224,7 @@ class TransactionProfiler {
 	public function transactionWritingOut( $server, $db, $id ) {
 		$name = "{$server} ({$db}) (TRX#$id)";
 		if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
-			wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." );
+			$this->logger->info( "Detected no transaction for '$name' - out of sync." );
 			return;
 		}
 		// Fill in the last non-query period...
@@ -237,7 +252,7 @@ class TransactionProfiler {
 				list( $query, $sTime, $end ) = $info;
 				$msg .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
 			}
-			wfDebugLog( 'DBPerformance', $msg );
+			$this->logger->info( $msg );
 		}
 		unset( $this->dbTrxHoldingLocks[$name] );
 		unset( $this->dbTrxMethodTimes[$name] );
@@ -250,7 +265,8 @@ class TransactionProfiler {
 	protected function reportExpectationViolated( $expect, $query ) {
 		$n = $this->expect[$expect];
 		$by = $this->expectBy[$expect];
-		wfDebugLog( 'DBPerformance',
-			"Expectation ($expect <= $n) by $by not met:\n$query\n" . wfBacktrace( true ) );
+		$this->logger->info(
+			"Expectation ($expect <= $n) by $by not met:\n$query\n" . wfBacktrace( true )
+		);
 	}
 }
-- 
2.20.1