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
24 namespace Wikimedia\Rdbms;
26 use Psr\Log\LoggerInterface;
27 use Psr\Log\LoggerAwareInterface;
28 use Psr\Log\NullLogger;
32 * Helper class that detects high-contention DB queries via profiling calls
34 * This class is meant to work with an IDatabase object, which manages queries
38 class TransactionProfiler implements LoggerAwareInterface {
39 /** @var float Seconds */
40 protected $dbLockThreshold = 3.0;
41 /** @var float Seconds */
42 protected $eventThreshold = 0.25;
44 protected $silenced = false;
46 /** @var array transaction ID => (write start time, list of DBs involved) */
47 protected $dbTrxHoldingLocks = [];
48 /** @var array transaction ID => list of (query name, start time, end time) */
49 protected $dbTrxMethodTimes = [];
65 'readQueryTime' => INF,
66 'writeQueryTime' => INF
69 protected $expectBy = [];
72 * @var LoggerInterface
76 public function __construct() {
77 $this->setLogger( new NullLogger() );
80 public function setLogger( LoggerInterface $logger ) {
81 $this->logger = $logger;
85 * @param bool $value New value
86 * @return bool Old value
89 public function setSilenced( $value ) {
90 $old = $this->silenced;
91 $this->silenced = $value;
97 * Set performance expectations
99 * With conflicting expectations, the most narrow ones will be used
101 * @param string $event (writes,queries,conns,mConns)
102 * @param int $value Maximum count of the event
103 * @param string $fname Caller
106 public function setExpectation( $event, $value, $fname ) {
107 $this->expect[$event] = isset( $this->expect[$event] )
108 ? min( $this->expect[$event], $value )
110 if ( $this->expect[$event] == $value ) {
111 $this->expectBy[$event] = $fname;
116 * Set multiple performance expectations
118 * With conflicting expectations, the most narrow ones will be used
120 * @param array $expects Map of (event => limit)
121 * @param string $fname
124 public function setExpectations( array $expects, $fname ) {
125 foreach ( $expects as $event => $value ) {
126 $this->setExpectation( $event, $value, $fname );
131 * Reset performance expectations and hit counters
135 public function resetExpectations() {
136 foreach ( $this->hits as &$val ) {
140 foreach ( $this->expect as &$val ) {
144 $this->expectBy = [];
148 * Mark a DB as having been connected to with a new handle
150 * Note that there can be multiple connections to a single DB.
152 * @param string $server DB server
153 * @param string $db DB name
154 * @param bool $isMaster
156 public function recordConnection( $server, $db, $isMaster ) {
157 // Report when too many connections happen...
158 if ( $this->hits['conns']++ >= $this->expect['conns'] ) {
159 $this->reportExpectationViolated(
160 'conns', "[connect to $server ($db)]", $this->hits['conns'] );
162 if ( $isMaster && $this->hits['masterConns']++ >= $this->expect['masterConns'] ) {
163 $this->reportExpectationViolated(
164 'masterConns', "[connect to $server ($db)]", $this->hits['masterConns'] );
169 * Mark a DB as in a transaction with one or more writes pending
171 * Note that there can be multiple connections to a single DB.
173 * @param string $server DB server
174 * @param string $db DB name
175 * @param string $id ID string of transaction
177 public function transactionWritingIn( $server, $db, $id ) {
178 $name = "{$server} ({$db}) (TRX#$id)";
179 if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
180 $this->logger->info( "Nested transaction for '$name' - out of sync." );
182 $this->dbTrxHoldingLocks[$name] = [
183 'start' => microtime( true ),
184 'conns' => [], // all connections involved
186 $this->dbTrxMethodTimes[$name] = [];
188 foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
189 // Track all DBs in transactions for this transaction
190 $info['conns'][$name] = 1;
195 * Register the name and time of a method for slow DB trx detection
197 * This assumes that all queries are synchronous (non-overlapping)
199 * @param string $query Function name or generalized SQL
200 * @param float $sTime Starting UNIX wall time
201 * @param bool $isWrite Whether this is a write query
202 * @param int $n Number of affected rows
204 public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
205 $eTime = microtime( true );
206 $elapsed = ( $eTime - $sTime );
208 if ( $isWrite && $n > $this->expect['maxAffected'] ) {
210 "Query affected $n row(s):\n" . $query . "\n" .
211 ( new RuntimeException() )->getTraceAsString() );
214 // Report when too many writes/queries happen...
215 if ( $this->hits['queries']++ >= $this->expect['queries'] ) {
216 $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
218 if ( $isWrite && $this->hits['writes']++ >= $this->expect['writes'] ) {
219 $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
221 // Report slow queries...
222 if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
223 $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
225 if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
226 $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
229 if ( !$this->dbTrxHoldingLocks ) {
232 } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
233 // Not an important query nor slow enough
237 foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
238 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
240 // Additional query in the trx...
241 $lastEnd = $lastQuery[2];
242 if ( $sTime >= $lastEnd ) { // sanity check
243 if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
244 // Add an entry representing the time spent doing non-queries
245 $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
247 $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
250 // First query in the trx...
251 if ( $sTime >= $info['start'] ) { // sanity check
252 $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
259 * Mark a DB as no longer in a transaction
261 * This will check if locks are possibly held for longer than
262 * needed and log any affected transactions to a special DB log.
263 * Note that there can be multiple connections to a single DB.
265 * @param string $server DB server
266 * @param string $db DB name
267 * @param string $id ID string of transaction
268 * @param float $writeTime Time spent in write queries
269 * @param int $affected Number of rows affected by writes
271 public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
272 $name = "{$server} ({$db}) (TRX#$id)";
273 if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
274 $this->logger->info( "Detected no transaction for '$name' - out of sync." );
280 // Warn if too much time was spend writing...
281 if ( $writeTime > $this->expect['writeQueryTime'] ) {
282 $this->reportExpectationViolated(
284 "[transaction $id writes to {$server} ({$db})]",
289 // Warn if too many rows were changed...
290 if ( $affected > $this->expect['maxAffected'] ) {
291 $this->reportExpectationViolated(
293 "[transaction $id writes to {$server} ({$db})]",
297 // Fill in the last non-query period...
298 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
300 $now = microtime( true );
301 $lastEnd = $lastQuery[2];
302 if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
303 $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
306 // Check for any slow queries or non-query periods...
307 foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
308 $elapsed = ( $info[2] - $info[1] );
309 if ( $elapsed >= $this->dbLockThreshold ) {
316 foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
317 list( $query, $sTime, $end ) = $info;
318 $trace .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
320 $this->logger->info( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
321 'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
325 unset( $this->dbTrxHoldingLocks[$name] );
326 unset( $this->dbTrxMethodTimes[$name] );
330 * @param string $expect
331 * @param string $query
332 * @param string|float|int $actual
334 protected function reportExpectationViolated( $expect, $query, $actual ) {
335 if ( $this->silenced ) {
340 "Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n" .
341 ( new RuntimeException() )->getTraceAsString(),
343 'measure' => $expect,
344 'max' => $this->expect[$expect],
345 'by' => $this->expectBy[$expect],