X-Git-Url: http://git.cyclocoop.org/?a=blobdiff_plain;f=includes%2Fprofiler%2FTransactionProfiler.php;h=1aba71c3fa0291e1aa7e37336c0490dd00678a19;hb=515839fdad497581269311b74a01316601ff21a5;hp=5f2a57a5bcedde1df48bbac0789255df39e913dc;hpb=5ac40796cde0fbd9b552e28da2522bbe077191f8;p=lhc%2Fweb%2Fwiklou.git

diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php
index 5f2a57a5bc..1aba71c3fa 100644
--- a/includes/profiler/TransactionProfiler.php
+++ b/includes/profiler/TransactionProfiler.php
@@ -40,29 +40,29 @@ class TransactionProfiler implements LoggerAwareInterface {
 	protected $eventThreshold = .25;
 
 	/** @var array transaction ID => (write start time, list of DBs involved) */
-	protected $dbTrxHoldingLocks = array();
+	protected $dbTrxHoldingLocks = [];
 	/** @var array transaction ID => list of (query name, start time, end time) */
-	protected $dbTrxMethodTimes = array();
+	protected $dbTrxMethodTimes = [];
 
 	/** @var array */
-	protected $hits = array(
+	protected $hits = [
 		'writes'      => 0,
 		'queries'     => 0,
 		'conns'       => 0,
 		'masterConns' => 0
-	);
+	];
 	/** @var array */
-	protected $expect = array(
+	protected $expect = [
 		'writes'         => INF,
 		'queries'        => INF,
 		'conns'          => INF,
 		'masterConns'    => INF,
 		'maxAffected'    => INF,
 		'readQueryTime'  => INF,
-		'writeQueryTime' => INF,
-	);
+		'writeQueryTime' => INF
+	];
 	/** @var array */
-	protected $expectBy = array();
+	protected $expectBy = [];
 
 	/**
 	 * @var LoggerInterface
@@ -125,7 +125,7 @@ class TransactionProfiler implements LoggerAwareInterface {
 			$val = INF;
 		}
 		unset( $val );
-		$this->expectBy = array();
+		$this->expectBy = [];
 	}
 
 	/**
@@ -161,11 +161,11 @@ class TransactionProfiler implements LoggerAwareInterface {
 		if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
 			$this->logger->info( "Nested transaction for '$name' - out of sync." );
 		}
-		$this->dbTrxHoldingLocks[$name] = array(
+		$this->dbTrxHoldingLocks[$name] = [
 			'start' => microtime( true ),
-			'conns' => array(), // all connections involved
-		);
-		$this->dbTrxMethodTimes[$name] = array();
+			'conns' => [], // all connections involved
+		];
+		$this->dbTrxMethodTimes[$name] = [];
 
 		foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
 			// Track all DBs in transactions for this transaction
@@ -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 ) {
@@ -223,14 +223,14 @@ class TransactionProfiler implements LoggerAwareInterface {
 				if ( $sTime >= $lastEnd ) { // sanity check
 					if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
 						// Add an entry representing the time spent doing non-queries
-						$this->dbTrxMethodTimes[$name][] = array( '...delay...', $lastEnd, $sTime );
+						$this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
 					}
-					$this->dbTrxMethodTimes[$name][] = array( $query, $sTime, $eTime );
+					$this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
 				}
 			} else {
 				// First query in the trx...
 				if ( $sTime >= $info['start'] ) { // sanity check
-					$this->dbTrxMethodTimes[$name][] = array( $query, $sTime, $eTime );
+					$this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
 				}
 			}
 		}
@@ -246,24 +246,36 @@ class TransactionProfiler implements LoggerAwareInterface {
 	 * @param string $server DB server
 	 * @param string $db DB name
 	 * @param string $id ID string of transaction
+	 * @param float $writeTime Time spent in write queries
 	 */
-	public function transactionWritingOut( $server, $db, $id ) {
+	public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0 ) {
 		$name = "{$server} ({$db}) (TRX#$id)";
 		if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
 			$this->logger->info( "Detected no transaction for '$name' - out of sync." );
 			return;
 		}
+
+		$slow = false;
+
+		// Warn if too much time was spend writing...
+		if ( $writeTime > $this->expect['writeQueryTime'] ) {
+			$this->reportExpectationViolated(
+				'writeQueryTime',
+				"[transaction $id writes to {$server} ({$db})]",
+				$writeTime
+			);
+			$slow = true;
+		}
 		// Fill in the last non-query period...
 		$lastQuery = end( $this->dbTrxMethodTimes[$name] );
 		if ( $lastQuery ) {
 			$now = microtime( true );
 			$lastEnd = $lastQuery[2];
 			if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
-				$this->dbTrxMethodTimes[$name][] = array( '...delay...', $lastEnd, $now );
+				$this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
 			}
 		}
 		// Check for any slow queries or non-query periods...
-		$slow = false;
 		foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
 			$elapsed = ( $info[2] - $info[1] );
 			if ( $elapsed >= $this->dbLockThreshold ) {
@@ -287,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 )
 		);
 	}