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 c353a22..c89820d 100644 (file)
--- a/includes/libs/rdbms/TransactionProfiler.php
+++ b/includes/libs/rdbms/TransactionProfiler.php
@@ -62,6 +62,7 @@ class TransactionProfiler implements LoggerAwareInterface {
                'conns'          => INF,
                'masterConns'    => INF,
                'maxAffected'    => INF,
+               'readQueryRows'  => INF,
                'readQueryTime'  => INF,
                'writeQueryTime' => INF
        ];
@@ -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
         *
@@ -196,10 +218,10 @@ 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 );
@@ -207,7 +229,11 @@ class TransactionProfiler implements LoggerAwareInterface {
 
                if ( $isWrite && $n > $this->expect['maxAffected'] ) {
                        $this->logger->warning(
-                               "Query affected $n row(s):\n" . $query . "\n" .
+                               "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() );
                }
 
@@ -315,7 +341,8 @@ 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->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
                                'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
@@ -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 ) {
@@ -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;
+       }
 }