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 
265  public function recordQueryCompletion( $query, float $sTime, bool $isWrite, ?int $rowCount ) {
266  $eTime = microtime( true );
267  $elapsed = ( $eTime - $sTime );
268 
269  if ( $isWrite && $this->isAboveThreshold( $rowCount, 'maxAffected' ) ) {
270  $this->reportExpectationViolated( 'maxAffected', $query, $rowCount );
271  } elseif ( !$isWrite && $this->isAboveThreshold( $rowCount, 'readQueryRows' ) ) {
272  $this->reportExpectationViolated( 'readQueryRows', $query, $rowCount );
273  }
274 
275  // Report when too many writes/queries happen...
276  if ( $this->pingAndCheckThreshold( 'queries' ) ) {
277  $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
278  }
279  if ( $isWrite && $this->pingAndCheckThreshold( 'writes' ) ) {
280  $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
281  }
282  // Report slow queries...
283  if ( !$isWrite && $this->isAboveThreshold( $elapsed, 'readQueryTime' ) ) {
284  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
285  }
286  if ( $isWrite && $this->isAboveThreshold( $elapsed, 'writeQueryTime' ) ) {
287  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
288  }
289 
290  if ( !$this->dbTrxHoldingLocks ) {
291  // Short-circuit
292  return;
293  } elseif ( !$isWrite && $elapsed < self::EVENT_THRESHOLD_SEC ) {
294  // Not an important query nor slow enough
295  return;
296  }
297 
298  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
299  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
300  if ( $lastQuery ) {
301  // Additional query in the trx...
302  $lastEnd = $lastQuery[2];
303  if ( $sTime >= $lastEnd ) { // sanity check
304  if ( ( $sTime - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
305  // Add an entry representing the time spent doing non-queries
306  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
307  }
308  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
309  }
310  } else {
311  // First query in the trx...
312  if ( $sTime >= $info['start'] ) { // sanity check
313  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
314  }
315  }
316  }
317  }
318 
332  public function transactionWritingOut(
333  $server,
334  $db,
335  string $id,
336  float $writeTime,
337  int $affected
338  ) {
339  $name = "{$server} ({$db}) (TRX#$id)";
340  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
341  $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
342  return;
343  }
344 
345  $slow = false;
346 
347  // Warn if too much time was spend writing...
348  if ( $this->isAboveThreshold( $writeTime, 'writeQueryTime' ) ) {
350  'writeQueryTime',
351  "[transaction $id writes to {$server} ({$db})]",
352  $writeTime
353  );
354  $slow = true;
355  }
356  // Warn if too many rows were changed...
357  if ( $this->isAboveThreshold( $affected, 'maxAffected' ) ) {
359  'maxAffected',
360  "[transaction $id writes to {$server} ({$db})]",
361  $affected
362  );
363  }
364  // Fill in the last non-query period...
365  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
366  if ( $lastQuery ) {
367  $now = microtime( true );
368  $lastEnd = $lastQuery[2];
369  if ( ( $now - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
370  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
371  }
372  }
373  // Check for any slow queries or non-query periods...
374  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
375  $elapsed = ( $info[2] - $info[1] );
376  if ( $elapsed >= self::DB_LOCK_THRESHOLD_SEC ) {
377  $slow = true;
378  break;
379  }
380  }
381  if ( $slow ) {
382  $trace = '';
383  foreach ( $this->dbTrxMethodTimes[$name] as $i => [ $query, $sTime, $end ] ) {
384  $trace .= sprintf(
385  "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self::queryString( $query ) );
386  }
387  $this->logger->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
388  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
389  'trace' => $trace
390  ] );
391  }
392  unset( $this->dbTrxHoldingLocks[$name] );
393  unset( $this->dbTrxMethodTimes[$name] );
394  }
395 
396  private function initPlaceholderExpectations() {
397  $this->expect = array_fill_keys(
398  self::EVENT_NAMES,
399  [ self::FLD_LIMIT => INF, self::FLD_FNAME => null ]
400  );
401 
402  $this->hits = array_fill_keys( self::COUNTER_EVENT_NAMES, 0 );
403  }
404 
410  private function isAboveThreshold( $value, string $expectation ) {
411  return ( $value > $this->expect[$expectation][self::FLD_LIMIT] );
412  }
413 
418  private function pingAndCheckThreshold( string $expectation ) {
419  $newValue = ++$this->hits[$expectation];
420 
421  return ( $newValue > $this->expect[$expectation][self::FLD_LIMIT] );
422  }
423 
429  private function reportExpectationViolated( $expectation, $query, $actual ) {
430  if ( $this->silenced ) {
431  return;
432  }
433 
434  $max = $this->expect[$expectation][self::FLD_LIMIT];
435  $by = $this->expect[$expectation][self::FLD_FNAME];
436  $this->logger->warning(
437  "Expectation ($expectation <=) $max by $by not met (actual: {actual}):\n{query}\n",
438  [
439  'measure' => $expectation,
440  'max' => $max,
441  'by' => $by,
442  'actual' => $actual,
443  'query' => self::queryString( $query ),
444  'exception' => new RuntimeException()
445  ]
446  );
447  }
448 
453  private static function queryString( $query ) {
454  return $query instanceof GeneralizedSql ? $query->stringify() : $query;
455  }
456 }
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:332
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:410
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:396
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\queryString
static queryString( $query)
Definition: TransactionProfiler.php:453
Wikimedia\Rdbms\TransactionProfiler\recordQueryCompletion
recordQueryCompletion( $query, float $sTime, bool $isWrite, ?int $rowCount)
Register the name and time of a method for slow DB trx detection.
Definition: TransactionProfiler.php:265
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\reportExpectationViolated
reportExpectationViolated( $expectation, $query, $actual)
Definition: TransactionProfiler.php:429
Wikimedia\Rdbms\TransactionProfiler\COUNTER_EVENT_NAMES
const COUNTER_EVENT_NAMES
List of event names with hit counters.
Definition: TransactionProfiler.php:81
Wikimedia\Rdbms\TransactionProfiler\pingAndCheckThreshold
pingAndCheckThreshold(string $expectation)
Definition: TransactionProfiler.php:418
Wikimedia\Rdbms\TransactionProfiler\$expect
array< string, array > $expect
Map of (name => threshold value)
Definition: TransactionProfiler.php:44
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:85
Wikimedia\Rdbms\TransactionProfiler\setExpectation
setExpectation(string $event, $limit, string $fname)
Set performance expectations.
Definition: TransactionProfiler.php:141
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