Record TransactionProfiler violations beyond the first-by-type

Beyond giving a more complete picture, this can be used to adjust
the PostSend criteria to log master queries under the restInPeace()
entry point.

Bug: T166199
Change-Id: If5cf704ba10291d0eba63e66b388666fde3ca649

diff --git a/includes/libs/rdbms/TransactionProfiler.php b/includes/libs/rdbms/TransactionProfiler.php
index 823e0dc..aa38206 100644 (file)
--- a/includes/libs/rdbms/TransactionProfiler.php
+++ b/includes/libs/rdbms/TransactionProfiler.php
@@ -156,11 +156,13 @@ class TransactionProfiler implements LoggerAwareInterface {
         */
        public function recordConnection( $server, $db, $isMaster ) {
                // Report when too many connections happen...
-               if ( $this->hits['conns']++ == $this->expect['conns'] ) {
-                       $this->reportExpectationViolated( 'conns', "[connect to $server ($db)]" );
+               if ( $this->hits['conns']++ >= $this->expect['conns'] ) {
+                       $this->reportExpectationViolated(
+                               'conns', "[connect to $server ($db)]", $this->hits['conns'] );
                }
-               if ( $isMaster && $this->hits['masterConns']++ == $this->expect['masterConns'] ) {
-                       $this->reportExpectationViolated( 'masterConns', "[connect to $server ($db)]" );
+               if ( $isMaster && $this->hits['masterConns']++ >= $this->expect['masterConns'] ) {
+                       $this->reportExpectationViolated(
+                               'masterConns', "[connect to $server ($db)]", $this->hits['masterConns'] );
                }
        }
 
@@ -211,11 +213,11 @@ class TransactionProfiler implements LoggerAwareInterface {
                }
 
                // Report when too many writes/queries happen...
-               if ( $this->hits['queries']++ == $this->expect['queries'] ) {
-                       $this->reportExpectationViolated( 'queries', $query );
+               if ( $this->hits['queries']++ >= $this->expect['queries'] ) {
+                       $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
                }
-               if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) {
-                       $this->reportExpectationViolated( 'writes', $query );
+               if ( $isWrite && $this->hits['writes']++ >= $this->expect['writes'] ) {
+                       $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
                }
                // Report slow queries...
                if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {

diff --git a/tests/phpunit/includes/libs/rdbms/TransactionProfilerTest.php b/tests/phpunit/includes/libs/rdbms/TransactionProfilerTest.php
new file mode 100644 (file)
index 0000000..cb18fb3
--- /dev/null
+++ b/tests/phpunit/includes/libs/rdbms/TransactionProfilerTest.php
@@ -0,0 +1,141 @@
+<?php
+
+use Wikimedia\Rdbms\TransactionProfiler;
+use Psr\Log\LoggerInterface;
+
+class TransactionProfilerTest extends PHPUnit_Framework_TestCase {
+       public function testAffected() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               $logger->expects( $this->exactly( 3 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'maxAffected', 100, __METHOD__ );
+
+               $tp->transactionWritingIn( 'srv1', 'db1', '123' );
+               $tp->recordQueryCompletion( "SQL 1", microtime( true ) - 3, true, 200 );
+               $tp->recordQueryCompletion( "SQL 2", microtime( true ) - 3, true, 200 );
+               $tp->transactionWritingOut( 'srv1', 'db1', '123', 1, 400 );
+       }
+
+       public function testReadTime() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               // 1 per query
+               $logger->expects( $this->exactly( 2 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'readQueryTime', 5, __METHOD__ );
+
+               $tp->transactionWritingIn( 'srv1', 'db1', '123' );
+               $tp->recordQueryCompletion( "SQL 1", microtime( true ) - 10, false, 1 );
+               $tp->recordQueryCompletion( "SQL 2", microtime( true ) - 10, false, 1 );
+               $tp->transactionWritingOut( 'srv1', 'db1', '123', 0, 0 );
+       }
+
+       public function testWriteTime() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               // 1 per query, 1 per trx, and one "sub-optimal trx" entry
+               $logger->expects( $this->exactly( 4 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'writeQueryTime', 5, __METHOD__ );
+
+               $tp->transactionWritingIn( 'srv1', 'db1', '123' );
+               $tp->recordQueryCompletion( "SQL 1", microtime( true ) - 10, true, 1 );
+               $tp->recordQueryCompletion( "SQL 2", microtime( true ) - 10, true, 1 );
+               $tp->transactionWritingOut( 'srv1', 'db1', '123', 20, 1 );
+       }
+
+       public function testAffectedTrx() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               $logger->expects( $this->exactly( 1 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'maxAffected', 100, __METHOD__ );
+
+               $tp->transactionWritingIn( 'srv1', 'db1', '123' );
+               $tp->transactionWritingOut( 'srv1', 'db1', '123', 1, 200 );
+       }
+
+       public function testWriteTimeTrx() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               // 1 per trx, and one "sub-optimal trx" entry
+               $logger->expects( $this->exactly( 2 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'writeQueryTime', 5, __METHOD__ );
+
+               $tp->transactionWritingIn( 'srv1', 'db1', '123' );
+               $tp->transactionWritingOut( 'srv1', 'db1', '123', 10, 1 );
+       }
+
+       public function testConns() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               $logger->expects( $this->exactly( 2 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'conns', 2, __METHOD__ );
+
+               $tp->recordConnection( 'srv1', 'db1', false );
+               $tp->recordConnection( 'srv1', 'db2', false );
+               $tp->recordConnection( 'srv1', 'db3', false ); // warn
+               $tp->recordConnection( 'srv1', 'db4', false ); // warn
+       }
+
+       public function testMasterConns() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               $logger->expects( $this->exactly( 2 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'masterConns', 2, __METHOD__ );
+
+               $tp->recordConnection( 'srv1', 'db1', false );
+               $tp->recordConnection( 'srv1', 'db2', false );
+
+               $tp->recordConnection( 'srv1', 'db1', true );
+               $tp->recordConnection( 'srv1', 'db2', true );
+               $tp->recordConnection( 'srv1', 'db3', true ); // warn
+               $tp->recordConnection( 'srv1', 'db4', true ); // warn
+       }
+
+       public function testReadQueryCount() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               $logger->expects( $this->exactly( 2 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'queries', 2, __METHOD__ );
+
+               $tp->recordQueryCompletion( "SQL 1", microtime( true ) - .01, false, 0 );
+               $tp->recordQueryCompletion( "SQL 2", microtime( true ) - .01, false, 0 );
+               $tp->recordQueryCompletion( "SQL 3", microtime( true ) - .01, false, 0 ); // warn
+               $tp->recordQueryCompletion( "SQL 4", microtime( true ) - .01, false, 0 ); // warn
+       }
+
+       public function testWriteQueryCount() {
+               $logger = $this->getMockBuilder( LoggerInterface::class )->getMock();
+               $logger->expects( $this->exactly( 2 ) )->method( 'info' );
+
+               $tp = new TransactionProfiler();
+               $tp->setLogger( $logger );
+               $tp->setExpectation( 'writes', 2, __METHOD__ );
+
+               $tp->recordQueryCompletion( "SQL 1", microtime( true ) - .01, false, 0 );
+               $tp->recordQueryCompletion( "SQL 2", microtime( true ) - .01, false, 0 );
+               $tp->recordQueryCompletion( "SQL 3", microtime( true ) - .01, false, 0 );
+               $tp->recordQueryCompletion( "SQL 4", microtime( true ) - .01, false, 0 );
+
+               $tp->transactionWritingIn( 'srv1', 'db1', '123' );
+               $tp->recordQueryCompletion( "SQL 1w", microtime( true ) - .01, true, 2 );
+               $tp->recordQueryCompletion( "SQL 2w", microtime( true ) - .01, true, 5 );
+               $tp->recordQueryCompletion( "SQL 3w", microtime( true ) - .01, true, 3 );
+               $tp->recordQueryCompletion( "SQL 4w", microtime( true ) - .01, true, 1 );
+               $tp->transactionWritingOut( 'srv1', 'db1', '123', 1, 1 );
+       }
+}