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 'readQueryRows' => INF
,
66 'readQueryTime' => INF
,
67 'writeQueryTime' => INF
70 protected $expectBy = [];
73 * @var LoggerInterface
77 public function __construct() {
78 $this->setLogger( new NullLogger() );
81 public function setLogger( LoggerInterface
$logger ) {
82 $this->logger
= $logger;
87 * @return bool Old value
90 public function setSilenced( $value ) {
91 $old = $this->silenced
;
92 $this->silenced
= $value;
98 * Set performance expectations
100 * With conflicting expectations, the most narrow ones will be used
102 * @param string $event (writes,queries,conns,mConns)
103 * @param int $value Maximum count of the event
104 * @param string $fname Caller
107 public function setExpectation( $event, $value, $fname ) {
108 $this->expect
[$event] = isset( $this->expect
[$event] )
109 ?
min( $this->expect
[$event], $value )
111 if ( $this->expect
[$event] == $value ) {
112 $this->expectBy
[$event] = $fname;
117 * Set one or multiple performance expectations
119 * With conflicting expectations, the most narrow ones will be used
121 * Use this to initialize expectations or make them stricter mid-request
123 * @param array $expects Map of (event => limit)
124 * @param string $fname
127 public function setExpectations( array $expects, $fname ) {
128 foreach ( $expects as $event => $value ) {
129 $this->setExpectation( $event, $value, $fname );
134 * Reset all performance expectations and hit counters
136 * Use this for unit testing or before applying a totally different set of expectations
137 * for a different part of the request, such as during "post-send" (execution after HTTP
138 * response completion)
142 public function resetExpectations() {
143 foreach ( $this->hits
as &$val ) {
147 foreach ( $this->expect
as &$val ) {
151 $this->expectBy
= [];
155 * Clear all expectations and hit counters and set new performance expectations
157 * Use this to apply a totally different set of expectations for a different part
158 * of the request, such as during "post-send" (execution after HTTP response completion)
160 * @param array $expects Map of (event => limit)
161 * @param string $fname
164 public function redefineExpectations( array $expects, $fname ) {
165 $this->resetExpectations();
166 $this->setExpectations( $expects, $fname );
170 * Mark a DB as having been connected to with a new handle
172 * Note that there can be multiple connections to a single DB.
174 * @param string $server DB server
175 * @param string $db DB name
176 * @param bool $isMaster
178 public function recordConnection( $server, $db, $isMaster ) {
179 // Report when too many connections happen...
180 if ( $this->hits
['conns']++
>= $this->expect
['conns'] ) {
181 $this->reportExpectationViolated(
182 'conns', "[connect to $server ($db)]", $this->hits
['conns'] );
184 if ( $isMaster && $this->hits
['masterConns']++
>= $this->expect
['masterConns'] ) {
185 $this->reportExpectationViolated(
186 'masterConns', "[connect to $server ($db)]", $this->hits
['masterConns'] );
191 * Mark a DB as in a transaction with one or more writes pending
193 * Note that there can be multiple connections to a single DB.
195 * @param string $server DB server
196 * @param string $db DB name
197 * @param string $id ID string of transaction
199 public function transactionWritingIn( $server, $db, $id ) {
200 $name = "{$server} ({$db}) (TRX#$id)";
201 if ( isset( $this->dbTrxHoldingLocks
[$name] ) ) {
202 $this->logger
->warning( "Nested transaction for '$name' - out of sync." );
204 $this->dbTrxHoldingLocks
[$name] = [
205 'start' => microtime( true ),
206 'conns' => [], // all connections involved
208 $this->dbTrxMethodTimes
[$name] = [];
210 foreach ( $this->dbTrxHoldingLocks
as $name => &$info ) {
211 // Track all DBs in transactions for this transaction
212 $info['conns'][$name] = 1;
217 * Register the name and time of a method for slow DB trx detection
219 * This assumes that all queries are synchronous (non-overlapping)
221 * @param string|GeneralizedSql $query Function name or generalized SQL
222 * @param float $sTime Starting UNIX wall time
223 * @param bool $isWrite Whether this is a write query
224 * @param int $n Number of affected/read rows
226 public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
227 $eTime = microtime( true );
228 $elapsed = ( $eTime - $sTime );
230 if ( $isWrite && $n > $this->expect
['maxAffected'] ) {
231 $this->logger
->warning(
232 "Query affected $n row(s):\n" . self
::queryString( $query ) . "\n" .
233 ( new RuntimeException() )->getTraceAsString() );
234 } elseif ( !$isWrite && $n > $this->expect
['readQueryRows'] ) {
235 $this->logger
->warning(
236 "Query returned $n row(s):\n" . self
::queryString( $query ) . "\n" .
237 ( new RuntimeException() )->getTraceAsString() );
240 // Report when too many writes/queries happen...
241 if ( $this->hits
['queries']++
>= $this->expect
['queries'] ) {
242 $this->reportExpectationViolated( 'queries', $query, $this->hits
['queries'] );
244 if ( $isWrite && $this->hits
['writes']++
>= $this->expect
['writes'] ) {
245 $this->reportExpectationViolated( 'writes', $query, $this->hits
['writes'] );
247 // Report slow queries...
248 if ( !$isWrite && $elapsed > $this->expect
['readQueryTime'] ) {
249 $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
251 if ( $isWrite && $elapsed > $this->expect
['writeQueryTime'] ) {
252 $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
255 if ( !$this->dbTrxHoldingLocks
) {
258 } elseif ( !$isWrite && $elapsed < $this->eventThreshold
) {
259 // Not an important query nor slow enough
263 foreach ( $this->dbTrxHoldingLocks
as $name => $info ) {
264 $lastQuery = end( $this->dbTrxMethodTimes
[$name] );
266 // Additional query in the trx...
267 $lastEnd = $lastQuery[2];
268 if ( $sTime >= $lastEnd ) { // sanity check
269 if ( ( $sTime - $lastEnd ) > $this->eventThreshold
) {
270 // Add an entry representing the time spent doing non-queries
271 $this->dbTrxMethodTimes
[$name][] = [ '...delay...', $lastEnd, $sTime ];
273 $this->dbTrxMethodTimes
[$name][] = [ $query, $sTime, $eTime ];
276 // First query in the trx...
277 if ( $sTime >= $info['start'] ) { // sanity check
278 $this->dbTrxMethodTimes
[$name][] = [ $query, $sTime, $eTime ];
285 * Mark a DB as no longer in a transaction
287 * This will check if locks are possibly held for longer than
288 * needed and log any affected transactions to a special DB log.
289 * Note that there can be multiple connections to a single DB.
291 * @param string $server DB server
292 * @param string $db DB name
293 * @param string $id ID string of transaction
294 * @param float $writeTime Time spent in write queries
295 * @param int $affected Number of rows affected by writes
297 public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
298 $name = "{$server} ({$db}) (TRX#$id)";
299 if ( !isset( $this->dbTrxMethodTimes
[$name] ) ) {
300 $this->logger
->warning( "Detected no transaction for '$name' - out of sync." );
306 // Warn if too much time was spend writing...
307 if ( $writeTime > $this->expect
['writeQueryTime'] ) {
308 $this->reportExpectationViolated(
310 "[transaction $id writes to {$server} ({$db})]",
315 // Warn if too many rows were changed...
316 if ( $affected > $this->expect
['maxAffected'] ) {
317 $this->reportExpectationViolated(
319 "[transaction $id writes to {$server} ({$db})]",
323 // Fill in the last non-query period...
324 $lastQuery = end( $this->dbTrxMethodTimes
[$name] );
326 $now = microtime( true );
327 $lastEnd = $lastQuery[2];
328 if ( ( $now - $lastEnd ) > $this->eventThreshold
) {
329 $this->dbTrxMethodTimes
[$name][] = [ '...delay...', $lastEnd, $now ];
332 // Check for any slow queries or non-query periods...
333 foreach ( $this->dbTrxMethodTimes
[$name] as $info ) {
334 $elapsed = ( $info[2] - $info[1] );
335 if ( $elapsed >= $this->dbLockThreshold
) {
342 foreach ( $this->dbTrxMethodTimes
[$name] as $i => $info ) {
343 list( $query, $sTime, $end ) = $info;
345 "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self
::queryString( $query ) );
347 $this->logger
->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
348 'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks
[$name]['conns'] ) ),
352 unset( $this->dbTrxHoldingLocks
[$name] );
353 unset( $this->dbTrxMethodTimes
[$name] );
357 * @param string $expect
358 * @param string|GeneralizedSql $query
359 * @param string|float|int $actual
361 protected function reportExpectationViolated( $expect, $query, $actual ) {
362 if ( $this->silenced
) {
366 $this->logger
->warning(
367 "Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n" .
368 ( new RuntimeException() )->getTraceAsString(),
370 'measure' => $expect,
371 'max' => $this->expect
[$expect],
372 'by' => $this->expectBy
[$expect],
374 'query' => self
::queryString( $query )
380 * @param GeneralizedSql|string $query
383 private static function queryString( $query ) {
384 return $query instanceof GeneralizedSql ?
$query->stringify() : $query;