From e447f908960660aeff60a39f707f881ad748da80 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Thu, 22 Jun 2017 13:56:02 -0700 Subject: [PATCH] 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 --- includes/libs/rdbms/TransactionProfiler.php | 18 ++- .../libs/rdbms/TransactionProfilerTest.php | 141 ++++++++++++++++++ 2 files changed, 151 insertions(+), 8 deletions(-) create mode 100644 tests/phpunit/includes/libs/rdbms/TransactionProfilerTest.php 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 ); + } +} -- 2.20.1