MediaWiki master
TransactionProfiler.php
Go to the documentation of this file.
1<?php
20namespace Wikimedia\Rdbms;
21
22use InvalidArgumentException;
23use Psr\Log\LoggerAwareInterface;
24use Psr\Log\LoggerInterface;
25use Psr\Log\NullLogger;
26use RuntimeException;
27use Wikimedia\ScopedCallback;
29
40class TransactionProfiler implements LoggerAwareInterface {
42 private $logger;
44 private $statsFactory;
46 private $expect;
48 private $hits;
50 private $violations;
52 private $silenced;
53
58 private $dbTrxHoldingLocks;
59
64 private $dbTrxMethodTimes;
65
67 private $method;
68
70 private $wallClockOverride;
71
73 private const DB_LOCK_THRESHOLD_SEC = 3.0;
75 private const EVENT_THRESHOLD_SEC = 0.25;
76
78 private const EVENT_NAMES = [
79 'writes',
80 'queries',
81 'conns',
82 'masterConns',
83 'maxAffected',
84 'readQueryRows',
85 'readQueryTime',
86 'writeQueryTime'
87 ];
88
90 private const COUNTER_EVENT_NAMES = [
91 'writes',
92 'queries',
93 'conns',
94 'masterConns'
95 ];
96
98 private const FLD_LIMIT = 0;
100 private const FLD_FNAME = 1;
101
103 public const EXPECTATION_ANY = 'any';
105 public const EXPECTATION_REPLICAS_ONLY = 'replicas-only';
106
107 public function __construct() {
108 $this->initPlaceholderExpectations();
109
110 $this->dbTrxHoldingLocks = [];
111 $this->dbTrxMethodTimes = [];
112
113 $this->silenced = array_fill_keys( self::EVENT_NAMES, 0 );
114
115 $this->setLogger( new NullLogger() );
116 $this->statsFactory = StatsFactory::newNull();
117 }
118
119 public function setLogger( LoggerInterface $logger ) {
120 $this->logger = $logger;
121 }
122
129 public function setStatsFactory( StatsFactory $statsFactory ) {
130 $this->statsFactory = $statsFactory;
131 }
132
137 public function setRequestMethod( ?string $method ) {
138 $this->method = $method;
139 }
140
154 public function silenceForScope( string $type = self::EXPECTATION_ANY ) {
155 if ( $type === self::EXPECTATION_REPLICAS_ONLY ) {
156 $events = [];
157 foreach ( [ 'writes', 'masterConns' ] as $event ) {
158 if ( $this->expect[$event][self::FLD_LIMIT] === 0 ) {
159 $events[] = $event;
160 }
161 }
162 } else {
163 $events = self::EVENT_NAMES;
164 }
165
166 foreach ( $events as $event ) {
167 ++$this->silenced[$event];
168 }
169
170 return new ScopedCallback( function () use ( $events ) {
171 foreach ( $events as $event ) {
172 --$this->silenced[$event];
173 }
174 } );
175 }
176
187 public function setExpectation( string $event, $limit, string $fname ) {
188 if ( !isset( $this->expect[$event] ) ) {
189 return; // obsolete/bogus expectation
190 }
191
192 if ( $limit <= $this->expect[$event][self::FLD_LIMIT] ) {
193 // New limit is more restrictive
194 $this->expect[$event] = [
195 self::FLD_LIMIT => $limit,
196 self::FLD_FNAME => $fname
197 ];
198 }
199 }
200
212 public function setExpectations( array $expects, string $fname ) {
213 foreach ( $expects as $event => $value ) {
214 $this->setExpectation( $event, $value, $fname );
215 }
216 }
217
227 public function resetExpectations() {
228 $this->initPlaceholderExpectations();
229 }
230
241 public function redefineExpectations( array $expects, string $fname ) {
242 $this->initPlaceholderExpectations();
243 $this->setExpectations( $expects, $fname );
244 }
245
261 public function getExpectation( string $event ) {
262 if ( !isset( $this->expect[$event] ) ) {
263 throw new InvalidArgumentException( "Unrecognised event name '$event' provided." );
264 }
265
266 return $this->expect[$event][self::FLD_LIMIT];
267 }
268
278 public function recordConnection( $server, $db, bool $isPrimaryWithReplicas ) {
279 // Report when too many connections happen...
280 if ( $this->pingAndCheckThreshold( 'conns' ) ) {
281 $this->reportExpectationViolated(
282 'conns',
283 "[connect to $server ($db)]",
284 $this->hits['conns']
285 );
286 }
287
288 // Report when too many primary connections happen...
289 if ( $isPrimaryWithReplicas && $this->pingAndCheckThreshold( 'masterConns' ) ) {
290 $this->reportExpectationViolated(
291 'masterConns',
292 "[connect to $server ($db)]",
293 $this->hits['masterConns']
294 );
295 }
296 }
297
308 public function transactionWritingIn( $server, $db, string $id, float $startTime ) {
309 $name = "{$db} {$server} TRX#$id";
310 if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
311 $this->logger->warning( "Nested transaction for '$name' - out of sync." );
312 }
313 $this->dbTrxHoldingLocks[$name] = [
314 'start' => $startTime,
315 'conns' => [], // all connections involved
316 ];
317 $this->dbTrxMethodTimes[$name] = [];
318
319 foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
320 // Track all DBs in transactions for this transaction
321 $info['conns'][$name] = 1;
322 }
323 }
324
337 public function recordQueryCompletion(
338 $query,
339 float $sTime,
340 bool $isWrite,
341 ?int $rowCount,
342 string $trxId,
343 ?string $serverName = null
344 ) {
345 $eTime = $this->getCurrentTime();
346 $elapsed = ( $eTime - $sTime );
347
348 if ( $isWrite && $this->isAboveThreshold( $rowCount, 'maxAffected' ) ) {
349 $this->reportExpectationViolated( 'maxAffected', $query, $rowCount, $trxId, $serverName );
350 } elseif ( !$isWrite && $this->isAboveThreshold( $rowCount, 'readQueryRows' ) ) {
351 $this->reportExpectationViolated( 'readQueryRows', $query, $rowCount, $trxId, $serverName );
352 }
353
354 // Report when too many writes/queries happen...
355 if ( $this->pingAndCheckThreshold( 'queries' ) ) {
356 $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'], $trxId, $serverName );
357 }
358 if ( $isWrite && $this->pingAndCheckThreshold( 'writes' ) ) {
359 $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'], $trxId, $serverName );
360 }
361 // Report slow queries...
362 if ( !$isWrite && $this->isAboveThreshold( $elapsed, 'readQueryTime' ) ) {
363 $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed, $trxId, $serverName );
364 }
365 if ( $isWrite && $this->isAboveThreshold( $elapsed, 'writeQueryTime' ) ) {
366 $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed, $trxId, $serverName );
367 }
368
369 if ( !$this->dbTrxHoldingLocks ) {
370 // Short-circuit
371 return;
372 } elseif ( !$isWrite && $elapsed < self::EVENT_THRESHOLD_SEC ) {
373 // Not an important query nor slow enough
374 return;
375 }
376
377 foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
378 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
379 if ( $lastQuery ) {
380 // Additional query in the trx...
381 $lastEnd = $lastQuery[2];
382 if ( $sTime >= $lastEnd ) {
383 if ( ( $sTime - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
384 // Add an entry representing the time spent doing non-queries
385 $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
386 }
387 $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
388 }
389 } else {
390 // First query in the trx...
391 if ( $sTime >= $info['start'] ) {
392 $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
393 }
394 }
395 }
396 }
397
411 public function transactionWritingOut(
412 $server,
413 $db,
414 string $id,
415 float $writeTime,
416 int $affected
417 ) {
418 // Must match $name in transactionWritingIn()
419 $name = "{$db} {$server} TRX#$id";
420 if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
421 $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
422 return;
423 }
424
425 $slow = false;
426
427 // Warn if too much time was spend writing...
428 if ( $this->isAboveThreshold( $writeTime, 'writeQueryTime' ) ) {
429 $this->reportExpectationViolated(
430 'writeQueryTime',
431 "[transaction writes to {$db} at {$server}]",
432 $writeTime,
433 $id
434 );
435 $slow = true;
436 }
437 // Warn if too many rows were changed...
438 if ( $this->isAboveThreshold( $affected, 'maxAffected' ) ) {
439 $this->reportExpectationViolated(
440 'maxAffected',
441 "[transaction writes to {$db} at {$server}]",
442 $affected,
443 $id
444 );
445 }
446 // Fill in the last non-query period...
447 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
448 if ( $lastQuery ) {
449 $now = $this->getCurrentTime();
450 $lastEnd = $lastQuery[2];
451 if ( ( $now - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
452 $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
453 }
454 }
455 // Check for any slow queries or non-query periods...
456 foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
457 $elapsed = ( $info[2] - $info[1] );
458 if ( $elapsed >= self::DB_LOCK_THRESHOLD_SEC ) {
459 $slow = true;
460 break;
461 }
462 }
463 if ( $slow ) {
464 $trace = '';
465 foreach ( $this->dbTrxMethodTimes[$name] as $i => [ $query, $sTime, $end ] ) {
466 $trace .= sprintf(
467 "%-2d %.3fs %s\n", $i, ( $end - $sTime ), $this->getGeneralizedSql( $query ) );
468 }
469 $this->logger->warning( "Suboptimal transaction [{dbs}]:\n{trace}", [
470 'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
471 'trace' => mb_substr( $trace, 0, 2000 )
472 ] );
473 }
474 unset( $this->dbTrxHoldingLocks[$name] );
475 unset( $this->dbTrxMethodTimes[$name] );
476 }
477
478 private function initPlaceholderExpectations() {
479 $this->expect = array_fill_keys(
480 self::EVENT_NAMES,
481 [ self::FLD_LIMIT => INF, self::FLD_FNAME => null ]
482 );
483
484 $this->hits = array_fill_keys( self::COUNTER_EVENT_NAMES, 0 );
485 $this->violations = array_fill_keys( self::EVENT_NAMES, 0 );
486 }
487
493 private function isAboveThreshold( $value, string $event ) {
494 if ( $this->silenced[$event] > 0 ) {
495 return false;
496 }
497
498 return ( $value > $this->expect[$event][self::FLD_LIMIT] );
499 }
500
505 private function pingAndCheckThreshold( string $event ) {
506 if ( $this->silenced[$event] > 0 ) {
507 return false;
508 }
509
510 $newValue = ++$this->hits[$event];
511 $limit = $this->expect[$event][self::FLD_LIMIT];
512
513 return ( $newValue > $limit );
514 }
515
523 private function reportExpectationViolated(
524 $event,
525 $query,
526 $actual,
527 ?string $trxId = null,
528 ?string $serverName = null
529 ) {
530 $violations = ++$this->violations[$event];
531 // First violation; check if this is a web request
532 if ( $violations === 1 && $this->method !== null ) {
533 $this->statsFactory->getCounter( 'rdbms_trxprofiler_warnings_total' )
534 ->setLabel( 'event', $event )
535 ->setLabel( 'method', $this->method )
536 ->copyToStatsdAt( "rdbms_trxprofiler_warnings.$event.{$this->method}" )
537 ->increment();
538 }
539
540 $max = $this->expect[$event][self::FLD_LIMIT];
541 $by = $this->expect[$event][self::FLD_FNAME];
542
543 $message = "Expectation ($event <= $max) by $by not met (actual: {actualSeconds})";
544 if ( $trxId ) {
545 $message .= ' in trx #{trxId}';
546 }
547 $message .= ":\n{query}\n";
548
549 $this->logger->warning(
550 $message,
551 [
552 'db_log_category' => 'performance',
553 'measure' => $event,
554 'maxSeconds' => $max,
555 'by' => $by,
556 'actualSeconds' => $actual,
557 'query' => $this->getGeneralizedSql( $query ),
558 'exception' => new RuntimeException(),
559 'trxId' => $trxId,
560 // Avoid truncated JSON in Logstash (T349140)
561 'fullQuery' => mb_substr( $this->getRawSql( $query ), 0, 2000 ),
562 'dbHost' => $serverName
563 ]
564 );
565 }
566
571 private function getGeneralizedSql( $query ) {
572 return $query instanceof GeneralizedSql ? $query->stringify() : $query;
573 }
574
579 private function getRawSql( $query ) {
580 return $query instanceof GeneralizedSql ? $query->getRawSql() : $query;
581 }
582
587 private function getCurrentTime() {
588 return $this->wallClockOverride ?: microtime( true );
589 }
590
595 public function setMockTime( &$time ) {
596 $this->wallClockOverride =& $time;
597 }
598}
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.
resetExpectations()
Reset all performance expectations and hit counters.
getExpectation(string $event)
Get the expectation associated with a specific event name.
const EXPECTATION_ANY
Any type of expectation.
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.
transactionWritingIn( $server, $db, string $id, float $startTime)
Mark a DB as in a transaction with one or more writes pending.
recordConnection( $server, $db, bool $isPrimaryWithReplicas)
Mark a DB as having been connected to with a new handle.
const EXPECTATION_REPLICAS_ONLY
Any expectations about replica usage never occurring.
setExpectation(string $event, $limit, string $fname)
Set performance expectations.
silenceForScope(string $type=self::EXPECTATION_ANY)
Temporarily ignore expectations until the returned object goes out of scope.
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.
setStatsFactory(StatsFactory $statsFactory)
Set statsFactory.
This is the primary interface for validating metrics definitions, caching defined metrics,...