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