rdbms: improve query logging logic in Database

[lhc/web/wiklou.git] / includes / libs / rdbms / TransactionProfiler.php

diff --git a/includes/libs/rdbms/TransactionProfiler.php b/includes/libs/rdbms/TransactionProfiler.php
index af431a6..c89820d 100644 (file)
--- a/includes/libs/rdbms/TransactionProfiler.php
+++ b/includes/libs/rdbms/TransactionProfiler.php
@@ -39,7 +39,7 @@ class TransactionProfiler implements LoggerAwareInterface {
        /** @var float Seconds */
        protected $dbLockThreshold = 3.0;
        /** @var float Seconds */
-       protected $eventThreshold = .25;
+       protected $eventThreshold = 0.25;
        /** @var bool */
        protected $silenced = false;
 
@@ -62,6 +62,7 @@ class TransactionProfiler implements LoggerAwareInterface {
                'conns'          => INF,
                'masterConns'    => INF,
                'maxAffected'    => INF,
+               'readQueryRows'  => INF,
                'readQueryTime'  => INF,
                'writeQueryTime' => INF
        ];
@@ -82,7 +83,7 @@ class TransactionProfiler implements LoggerAwareInterface {
        }
 
        /**
-        * @param bool $value New value
+        * @param bool $value
         * @return bool Old value
         * @since 1.28
         */
@@ -113,10 +114,12 @@ class TransactionProfiler implements LoggerAwareInterface {
        }
 
        /**
-        * Set multiple performance expectations
+        * Set one or multiple performance expectations
         *
         * With conflicting expectations, the most narrow ones will be used
         *
+        * Use this to initialize expectations or make them stricter mid-request
+        *
         * @param array $expects Map of (event => limit)
         * @param string $fname
         * @since 1.26
@@ -128,7 +131,11 @@ class TransactionProfiler implements LoggerAwareInterface {
        }
 
        /**
-        * Reset performance expectations and hit counters
+        * Reset all performance expectations and hit counters
+        *
+        * Use this for unit testing or before applying a totally different set of expectations
+        * for a different part of the request, such as during "post-send" (execution after HTTP
+        * response completion)
         *
         * @since 1.25
         */
@@ -144,6 +151,21 @@ class TransactionProfiler implements LoggerAwareInterface {
                $this->expectBy = [];
        }
 
+       /**
+        * Clear all expectations and hit counters and set new performance expectations
+        *
+        * Use this to apply a totally different set of expectations for a different part
+        * of the request, such as during "post-send" (execution after HTTP response completion)
+        *
+        * @param array $expects Map of (event => limit)
+        * @param string $fname
+        * @since 1.33
+        */
+       public function redefineExpectations( array $expects, $fname ) {
+               $this->resetExpectations();
+               $this->setExpectations( $expects, $fname );
+       }
+
        /**
         * Mark a DB as having been connected to with a new handle
         *
@@ -177,7 +199,7 @@ class TransactionProfiler implements LoggerAwareInterface {
        public function transactionWritingIn( $server, $db, $id ) {
                $name = "{$server} ({$db}) (TRX#$id)";
                if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
-                       $this->logger->info( "Nested transaction for '$name' - out of sync." );
+                       $this->logger->warning( "Nested transaction for '$name' - out of sync." );
                }
                $this->dbTrxHoldingLocks[$name] = [
                        'start' => microtime( true ),
@@ -196,18 +218,22 @@ class TransactionProfiler implements LoggerAwareInterface {
         *
         * This assumes that all queries are synchronous (non-overlapping)
         *
-        * @param string $query Function name or generalized SQL
+        * @param string|GeneralizedSql $query Function name or generalized SQL
         * @param float $sTime Starting UNIX wall time
         * @param bool $isWrite Whether this is a write query
-        * @param int $n Number of affected rows
+        * @param int $n Number of affected/read rows
         */
        public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
                $eTime = microtime( true );
                $elapsed = ( $eTime - $sTime );
 
                if ( $isWrite && $n > $this->expect['maxAffected'] ) {
-                       $this->logger->info(
-                               "Query affected $n row(s):\n" . $query . "\n" .
+                       $this->logger->warning(
+                               "Query affected $n row(s):\n" . self::queryString( $query ) . "\n" .
+                               ( new RuntimeException() )->getTraceAsString() );
+               } elseif ( !$isWrite && $n > $this->expect['readQueryRows'] ) {
+                       $this->logger->warning(
+                               "Query returned $n row(s):\n" . self::queryString( $query ) . "\n" .
                                ( new RuntimeException() )->getTraceAsString() );
                }
 
@@ -271,7 +297,7 @@ class TransactionProfiler implements LoggerAwareInterface {
        public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
                $name = "{$server} ({$db}) (TRX#$id)";
                if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
-                       $this->logger->info( "Detected no transaction for '$name' - out of sync." );
+                       $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
                        return;
                }
 
@@ -315,9 +341,10 @@ class TransactionProfiler implements LoggerAwareInterface {
                        $trace = '';
                        foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
                                list( $query, $sTime, $end ) = $info;
-                               $trace .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
+                               $trace .= sprintf(
+                                       "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self::queryString( $query ) );
                        }
-                       $this->logger->info( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
+                       $this->logger->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
                                'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
                                'trace' => $trace
                        ] );
@@ -328,7 +355,7 @@ class TransactionProfiler implements LoggerAwareInterface {
 
        /**
         * @param string $expect
-        * @param string $query
+        * @param string|GeneralizedSql $query
         * @param string|float|int $actual
         */
        protected function reportExpectationViolated( $expect, $query, $actual ) {
@@ -336,7 +363,7 @@ class TransactionProfiler implements LoggerAwareInterface {
                        return;
                }
 
-               $this->logger->info(
+               $this->logger->warning(
                        "Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n" .
                        ( new RuntimeException() )->getTraceAsString(),
                        [
@@ -344,8 +371,16 @@ class TransactionProfiler implements LoggerAwareInterface {
                                'max' => $this->expect[$expect],
                                'by' => $this->expectBy[$expect],
                                'actual' => $actual,
-                               'query' => $query
+                               'query' => self::queryString( $query )
                        ]
                );
        }
+
+       /**
+        * @param GeneralizedSql|string $query
+        * @return string
+        */
+       private static function queryString( $query ) {
+               return $query instanceof GeneralizedSql ? $query->stringify() : $query;
+       }
 }