Handle edge case in WikiPage::lock()

[lhc/web/wiklou.git] / includes / profiler / TransactionProfiler.php

diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php
index f02d66f..46d6119 100644 (file)
--- 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
@@ -220,13 +246,23 @@ 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})]" );
+                       $slow = true;
+               }
                // Fill in the last non-query period...
                $lastQuery = end( $this->dbTrxMethodTimes[$name] );
                if ( $lastQuery ) {
@@ -237,7 +273,6 @@ class TransactionProfiler implements LoggerAwareInterface {
                        }
                }
                // 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 ) {
@@ -268,7 +303,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 )
                );
        }
 }