MediaWiki REL1_39
TransactionProfiler.php
Go to the documentation of this file.
1<?php
20namespace Wikimedia\Rdbms;
21
22use Psr\Log\LoggerAwareInterface;
23use Psr\Log\LoggerInterface;
24use Psr\Log\NullLogger;
25use RuntimeException;
26use Wikimedia\ScopedCallback;
27
38class TransactionProfiler implements LoggerAwareInterface {
40 private $logger;
42 private $expect;
44 private $hits;
45
50 private $dbTrxHoldingLocks;
51
56 private $dbTrxMethodTimes;
57
59 private $silenced;
60
62 private const DB_LOCK_THRESHOLD_SEC = 3.0;
64 private const EVENT_THRESHOLD_SEC = 0.25;
65
67 private const EVENT_NAMES = [
68 'writes',
69 'queries',
70 'conns',
71 'masterConns',
72 'maxAffected',
73 'readQueryRows',
74 'readQueryTime',
75 'writeQueryTime'
76 ];
77
79 private const COUNTER_EVENT_NAMES = [
80 'writes',
81 'queries',
82 'conns',
83 'masterConns'
84 ];
85
87 private const FLD_LIMIT = 0;
89 private const FLD_FNAME = 1;
90
91 public function __construct() {
92 $this->initPlaceholderExpectations();
93
94 $this->dbTrxHoldingLocks = [];
95 $this->dbTrxMethodTimes = [];
96
97 $this->silenced = false;
98
99 $this->setLogger( new NullLogger() );
100 }
101
102 public function setLogger( LoggerInterface $logger ) {
103 $this->logger = $logger;
104 }
105
111 public function setSilenced( bool $value ) {
112 $old = $this->silenced;
113 $this->silenced = $value;
114
115 return $old;
116 }
117
122 public function silenceForScope() {
123 $oldSilenced = $this->setSilenced( true );
124 return new ScopedCallback( function () use ( $oldSilenced ) {
125 $this->setSilenced( $oldSilenced );
126 } );
127 }
128
139 public function setExpectation( string $event, $limit, string $fname ) {
140 if ( !isset( $this->expect[$event] ) ) {
141 return; // obsolete/bogus expectation
142 }
143
144 if ( $limit <= $this->expect[$event][self::FLD_LIMIT] ) {
145 // New limit is more restrictive
146 $this->expect[$event] = [
147 self::FLD_LIMIT => $limit,
148 self::FLD_FNAME => $fname
149 ];
150 }
151 }
152
164 public function setExpectations( array $expects, string $fname ) {
165 foreach ( $expects as $event => $value ) {
166 $this->setExpectation( $event, $value, $fname );
167 }
168 }
169
179 public function resetExpectations() {
180 $this->initPlaceholderExpectations();
181 }
182
193 public function redefineExpectations( array $expects, string $fname ) {
194 $this->initPlaceholderExpectations();
195 $this->setExpectations( $expects, $fname );
196 }
197
207 public function recordConnection( $server, $db, bool $isPrimary ) {
208 // Report when too many connections happen...
209 if ( $this->pingAndCheckThreshold( 'conns' ) ) {
210 $this->reportExpectationViolated(
211 'conns',
212 "[connect to $server ($db)]",
213 $this->hits['conns']
214 );
215 }
216
217 // Report when too many primary connections happen...
218 if ( $isPrimary && $this->pingAndCheckThreshold( 'masterConns' ) ) {
219 $this->reportExpectationViolated(
220 'masterConns',
221 "[connect to $server ($db)]",
222 $this->hits['masterConns']
223 );
224 }
225 }
226
236 public function transactionWritingIn( $server, $db, string $id ) {
237 $name = "{$db} {$server} TRX#$id";
238 if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
239 $this->logger->warning( "Nested transaction for '$name' - out of sync." );
240 }
241 $this->dbTrxHoldingLocks[$name] = [
242 'start' => microtime( true ),
243 'conns' => [], // all connections involved
244 ];
245 $this->dbTrxMethodTimes[$name] = [];
246
247 foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
248 // Track all DBs in transactions for this transaction
249 $info['conns'][$name] = 1;
250 }
251 }
252
265 public function recordQueryCompletion(
266 $query,
267 float $sTime,
268 bool $isWrite,
269 ?int $rowCount,
270 string $trxId,
271 ?string $serverName = null
272 ) {
273 $eTime = microtime( true );
274 $elapsed = ( $eTime - $sTime );
275
276 if ( $isWrite && $this->isAboveThreshold( $rowCount, 'maxAffected' ) ) {
277 $this->reportExpectationViolated( 'maxAffected', $query, $rowCount, $trxId, $serverName );
278 } elseif ( !$isWrite && $this->isAboveThreshold( $rowCount, 'readQueryRows' ) ) {
279 $this->reportExpectationViolated( 'readQueryRows', $query, $rowCount, $trxId, $serverName );
280 }
281
282 // Report when too many writes/queries happen...
283 if ( $this->pingAndCheckThreshold( 'queries' ) ) {
284 $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'], $trxId, $serverName );
285 }
286 if ( $isWrite && $this->pingAndCheckThreshold( 'writes' ) ) {
287 $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'], $trxId, $serverName );
288 }
289 // Report slow queries...
290 if ( !$isWrite && $this->isAboveThreshold( $elapsed, 'readQueryTime' ) ) {
291 $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed, $trxId, $serverName );
292 }
293 if ( $isWrite && $this->isAboveThreshold( $elapsed, 'writeQueryTime' ) ) {
294 $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed, $trxId, $serverName );
295 }
296
297 if ( !$this->dbTrxHoldingLocks ) {
298 // Short-circuit
299 return;
300 } elseif ( !$isWrite && $elapsed < self::EVENT_THRESHOLD_SEC ) {
301 // Not an important query nor slow enough
302 return;
303 }
304
305 foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
306 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
307 if ( $lastQuery ) {
308 // Additional query in the trx...
309 $lastEnd = $lastQuery[2];
310 if ( $sTime >= $lastEnd ) {
311 if ( ( $sTime - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
312 // Add an entry representing the time spent doing non-queries
313 $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
314 }
315 $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
316 }
317 } else {
318 // First query in the trx...
319 if ( $sTime >= $info['start'] ) {
320 $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
321 }
322 }
323 }
324 }
325
339 public function transactionWritingOut(
340 $server,
341 $db,
342 string $id,
343 float $writeTime,
344 int $affected
345 ) {
346 // Must match $name in transactionWritingIn()
347 $name = "{$db} {$server} TRX#$id";
348 if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
349 $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
350 return;
351 }
352
353 $slow = false;
354
355 // Warn if too much time was spend writing...
356 if ( $this->isAboveThreshold( $writeTime, 'writeQueryTime' ) ) {
357 $this->reportExpectationViolated(
358 'writeQueryTime',
359 "[transaction writes to {$db} at {$server}]",
360 $writeTime,
361 $id
362 );
363 $slow = true;
364 }
365 // Warn if too many rows were changed...
366 if ( $this->isAboveThreshold( $affected, 'maxAffected' ) ) {
367 $this->reportExpectationViolated(
368 'maxAffected',
369 "[transaction writes to {$db} at {$server}]",
370 $affected,
371 $id
372 );
373 }
374 // Fill in the last non-query period...
375 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
376 if ( $lastQuery ) {
377 $now = microtime( true );
378 $lastEnd = $lastQuery[2];
379 if ( ( $now - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
380 $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
381 }
382 }
383 // Check for any slow queries or non-query periods...
384 foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
385 $elapsed = ( $info[2] - $info[1] );
386 if ( $elapsed >= self::DB_LOCK_THRESHOLD_SEC ) {
387 $slow = true;
388 break;
389 }
390 }
391 if ( $slow ) {
392 $trace = '';
393 foreach ( $this->dbTrxMethodTimes[$name] as $i => [ $query, $sTime, $end ] ) {
394 $trace .= sprintf(
395 "%-2d %.3fs %s\n", $i, ( $end - $sTime ), $this->getGeneralizedSql( $query ) );
396 }
397 $this->logger->warning( "Sub-optimal transaction [{dbs}]:\n{trace}", [
398 'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
399 'trace' => $trace
400 ] );
401 }
402 unset( $this->dbTrxHoldingLocks[$name] );
403 unset( $this->dbTrxMethodTimes[$name] );
404 }
405
406 private function initPlaceholderExpectations() {
407 $this->expect = array_fill_keys(
408 self::EVENT_NAMES,
409 [ self::FLD_LIMIT => INF, self::FLD_FNAME => null ]
410 );
411
412 $this->hits = array_fill_keys( self::COUNTER_EVENT_NAMES, 0 );
413 }
414
420 private function isAboveThreshold( $value, string $expectation ) {
421 return ( $value > $this->expect[$expectation][self::FLD_LIMIT] );
422 }
423
428 private function pingAndCheckThreshold( string $expectation ) {
429 $newValue = ++$this->hits[$expectation];
430
431 return ( $newValue > $this->expect[$expectation][self::FLD_LIMIT] );
432 }
433
441 private function reportExpectationViolated(
442 $expectation,
443 $query,
444 $actual,
445 ?string $trxId = null,
446 ?string $serverName = null
447 ) {
448 if ( $this->silenced ) {
449 return;
450 }
451
452 $max = $this->expect[$expectation][self::FLD_LIMIT];
453 $by = $this->expect[$expectation][self::FLD_FNAME];
454 $message = "Expectation ($expectation <= $max) by $by not met (actual: {actualSeconds})";
455 if ( $trxId ) {
456 $message .= ' in trx #{trxId}';
457 }
458 $message .= ":\n{query}\n";
459 $this->logger->warning(
460 $message,
461 [
462 'measure' => $expectation,
463 'maxSeconds' => $max,
464 'by' => $by,
465 'actualSeconds' => $actual,
466 'query' => $this->getGeneralizedSql( $query ),
467 'exception' => new RuntimeException(),
468 'trxId' => $trxId,
469 'fullQuery' => $this->getRawSql( $query ),
470 'dbHost' => $serverName
471 ]
472 );
473 }
474
479 private function getGeneralizedSql( $query ) {
480 return $query instanceof GeneralizedSql ? $query->stringify() : $query;
481 }
482
487 private function getRawSql( $query ) {
488 return $query instanceof GeneralizedSql ? $query->getRawSql() : $query;
489 }
490}
Detect high-contention DB queries via profiling calls.
transactionWritingOut( $server, $db, string $id, float $writeTime, int $affected)
Mark a DB as no longer in a transaction.
transactionWritingIn( $server, $db, string $id)
Mark a DB as in a transaction with one or more writes pending.
resetExpectations()
Reset all performance expectations and hit counters.
redefineExpectations(array $expects, string $fname)
Clear all expectations and hit counters and set new performance expectations.
setExpectations(array $expects, string $fname)
Set one or multiple performance expectations.
silenceForScope()
Disable the logging of warnings until the returned object goes out of scope or is consumed.
recordConnection( $server, $db, bool $isPrimary)
Mark a DB as having been connected to with a new handle.
setExpectation(string $event, $limit, string $fname)
Set performance expectations.
recordQueryCompletion( $query, float $sTime, bool $isWrite, ?int $rowCount, string $trxId, ?string $serverName=null)
Register the name and time of a method for slow DB trx detection.