From: Aaron Schulz Date: Thu, 22 Jun 2017 20:56:02 +0000 (-0700) Subject: Record TransactionProfiler violations beyond the first-by-type X-Git-Tag: 1.31.0-rc.0~2861^2 X-Git-Url: https://git.heureux-cyclage.org/?p=lhc%2Fweb%2Fwiklou.git;a=commitdiff_plain;h=e447f908960660aeff60a39f707f881ad748da80 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 823e0dc5cd..aa38206917 100644 --- 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 index 0000000000..cb18fb3dc3 --- /dev/null +++ b/tests/phpunit/includes/libs/rdbms/TransactionProfilerTest.php @@ -0,0 +1,141 @@ +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 ); + } +}