3 * Transaction profiling for contention
5 * This program is free software; you can redistribute it and/or modify
6 * it under the terms of the GNU General Public License as published by
7 * the Free Software Foundation; either version 2 of the License, or
8 * (at your option) any later version.
10 * This program is distributed in the hope that it will be useful,
11 * but WITHOUT ANY WARRANTY; without even the implied warranty of
12 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
13 * GNU General Public License for more details.
15 * You should have received a copy of the GNU General Public License along
16 * with this program; if not, write to the Free Software Foundation, Inc.,
17 * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
18 * http://www.gnu.org/copyleft/gpl.html
22 * @author Aaron Schulz
25 use Psr\Log\LoggerInterface
;
26 use Psr\Log\LoggerAwareInterface
;
27 use Psr\Log\NullLogger
;
29 * Helper class that detects high-contention DB queries via profiling calls
31 * This class is meant to work with a DatabaseBase object, which manages queries
35 class TransactionProfiler
implements LoggerAwareInterface
{
36 /** @var float Seconds */
37 protected $dbLockThreshold = 3.0;
38 /** @var float Seconds */
39 protected $eventThreshold = .25;
41 /** @var array transaction ID => (write start time, list of DBs involved) */
42 protected $dbTrxHoldingLocks = array();
43 /** @var array transaction ID => list of (query name, start time, end time) */
44 protected $dbTrxMethodTimes = array();
47 protected $hits = array(
54 protected $expect = array(
62 protected $expectBy = array();
65 * @var LoggerInterface
69 public function __construct() {
70 $this->setLogger( new NullLogger() );
73 public function setLogger( LoggerInterface
$logger ) {
74 $this->logger
= $logger;
78 * Set performance expectations
80 * With conflicting expect, the most specific ones will be used
82 * @param string $event (writes,queries,conns,mConns)
83 * @param integer $value Maximum count of the event
84 * @param string $fname Caller
87 public function setExpectation( $event, $value, $fname ) {
88 $this->expect
[$event] = isset( $this->expect
[$event] )
89 ?
min( $this->expect
[$event], $value )
91 if ( $this->expect
[$event] == $value ) {
92 $this->expectBy
[$event] = $fname;
97 * Reset performance expectations and hit counters
101 public function resetExpectations() {
102 foreach ( $this->hits
as &$val ) {
106 foreach ( $this->expect
as &$val ) {
110 $this->expectBy
= array();
114 * Mark a DB as having been connected to with a new handle
116 * Note that there can be multiple connections to a single DB.
118 * @param string $server DB server
119 * @param string $db DB name
120 * @param bool $isMaster
122 public function recordConnection( $server, $db, $isMaster ) {
123 // Report when too many connections happen...
124 if ( $this->hits
['conns']++
== $this->expect
['conns'] ) {
125 $this->reportExpectationViolated( 'conns', "[connect to $server ($db)]" );
127 if ( $isMaster && $this->hits
['masterConns']++
== $this->expect
['masterConns'] ) {
128 $this->reportExpectationViolated( 'masterConns', "[connect to $server ($db)]" );
133 * Mark a DB as in a transaction with one or more writes pending
135 * Note that there can be multiple connections to a single DB.
137 * @param string $server DB server
138 * @param string $db DB name
139 * @param string $id ID string of transaction
141 public function transactionWritingIn( $server, $db, $id ) {
142 $name = "{$server} ({$db}) (TRX#$id)";
143 if ( isset( $this->dbTrxHoldingLocks
[$name] ) ) {
144 $this->logger
->info( "Nested transaction for '$name' - out of sync." );
146 $this->dbTrxHoldingLocks
[$name] = array(
147 'start' => microtime( true ),
148 'conns' => array(), // all connections involved
150 $this->dbTrxMethodTimes
[$name] = array();
152 foreach ( $this->dbTrxHoldingLocks
as $name => &$info ) {
153 // Track all DBs in transactions for this transaction
154 $info['conns'][$name] = 1;
159 * Register the name and time of a method for slow DB trx detection
161 * This assumes that all queries are synchronous (non-overlapping)
163 * @param string $query Function name or generalized SQL
164 * @param float $sTime Starting UNIX wall time
165 * @param bool $isWrite Whether this is a write query
166 * @param integer $n Number of affected rows
168 public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
169 $eTime = microtime( true );
170 $elapsed = ( $eTime - $sTime );
172 if ( $isWrite && $n > $this->expect
['maxAffected'] ) {
173 $this->logger
->info( "Query affected $n row(s):\n" . $query . "\n" . wfBacktrace( true ) );
176 // Report when too many writes/queries happen...
177 if ( $this->hits
['queries']++
== $this->expect
['queries'] ) {
178 $this->reportExpectationViolated( 'queries', $query );
180 if ( $isWrite && $this->hits
['writes']++
== $this->expect
['writes'] ) {
181 $this->reportExpectationViolated( 'writes', $query );
184 if ( !$this->dbTrxHoldingLocks
) {
187 } elseif ( !$isWrite && $elapsed < $this->eventThreshold
) {
188 // Not an important query nor slow enough
192 foreach ( $this->dbTrxHoldingLocks
as $name => $info ) {
193 $lastQuery = end( $this->dbTrxMethodTimes
[$name] );
195 // Additional query in the trx...
196 $lastEnd = $lastQuery[2];
197 if ( $sTime >= $lastEnd ) { // sanity check
198 if ( ( $sTime - $lastEnd ) > $this->eventThreshold
) {
199 // Add an entry representing the time spent doing non-queries
200 $this->dbTrxMethodTimes
[$name][] = array( '...delay...', $lastEnd, $sTime );
202 $this->dbTrxMethodTimes
[$name][] = array( $query, $sTime, $eTime );
205 // First query in the trx...
206 if ( $sTime >= $info['start'] ) { // sanity check
207 $this->dbTrxMethodTimes
[$name][] = array( $query, $sTime, $eTime );
214 * Mark a DB as no longer in a transaction
216 * This will check if locks are possibly held for longer than
217 * needed and log any affected transactions to a special DB log.
218 * Note that there can be multiple connections to a single DB.
220 * @param string $server DB server
221 * @param string $db DB name
222 * @param string $id ID string of transaction
224 public function transactionWritingOut( $server, $db, $id ) {
225 $name = "{$server} ({$db}) (TRX#$id)";
226 if ( !isset( $this->dbTrxMethodTimes
[$name] ) ) {
227 $this->logger
->info( "Detected no transaction for '$name' - out of sync." );
230 // Fill in the last non-query period...
231 $lastQuery = end( $this->dbTrxMethodTimes
[$name] );
233 $now = microtime( true );
234 $lastEnd = $lastQuery[2];
235 if ( ( $now - $lastEnd ) > $this->eventThreshold
) {
236 $this->dbTrxMethodTimes
[$name][] = array( '...delay...', $lastEnd, $now );
239 // Check for any slow queries or non-query periods...
241 foreach ( $this->dbTrxMethodTimes
[$name] as $info ) {
242 $elapsed = ( $info[2] - $info[1] );
243 if ( $elapsed >= $this->dbLockThreshold
) {
249 $dbs = implode( ', ', array_keys( $this->dbTrxHoldingLocks
[$name]['conns'] ) );
250 $msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n";
251 foreach ( $this->dbTrxMethodTimes
[$name] as $i => $info ) {
252 list( $query, $sTime, $end ) = $info;
253 $msg .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
255 $this->logger
->info( $msg );
257 unset( $this->dbTrxHoldingLocks
[$name] );
258 unset( $this->dbTrxMethodTimes
[$name] );
262 * @param string $expect
263 * @param string $query
265 protected function reportExpectationViolated( $expect, $query ) {
266 $n = $this->expect
[$expect];
267 $by = $this->expectBy
[$expect];
269 "Expectation ($expect <= $n) by $by not met:\n$query\n" . wfBacktrace( true )