MediaWiki  master
TransactionProfiler.php
Go to the documentation of this file.
1 <?php
20 namespace Wikimedia\Rdbms;
21 
22 use Psr\Log\LoggerAwareInterface;
23 use Psr\Log\LoggerInterface;
24 use Psr\Log\NullLogger;
25 use RuntimeException;
26 use Wikimedia\ScopedCallback;
27 
38 class TransactionProfiler implements LoggerAwareInterface {
40  private $logger;
42  private $expect;
44  private $hits;
46  private $silenced;
47 
52  private $dbTrxHoldingLocks;
53 
58  private $dbTrxMethodTimes;
59 
61  private $wallClockOverride;
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 
94  public const EXPECTATION_ANY = 'any';
96  public const EXPECTATION_REPLICAS_ONLY = 'replicas-only';
97 
98  public function __construct() {
99  $this->initPlaceholderExpectations();
100 
101  $this->dbTrxHoldingLocks = [];
102  $this->dbTrxMethodTimes = [];
103 
104  $this->silenced = array_fill_keys( self::EVENT_NAMES, 0 );
105 
106  $this->setLogger( new NullLogger() );
107  }
108 
109  public function setLogger( LoggerInterface $logger ) {
110  $this->logger = $logger;
111  }
112 
119  public function setSilenced( bool $value ) {
120  wfDeprecated( __METHOD__, '1.40' );
121 
122  $delta = $value ? 1 : -1;
123  foreach ( self::EVENT_NAMES as $event ) {
124  $this->silenced[$event] += $delta;
125  }
126 
127  return false;
128  }
129 
143  public function silenceForScope( string $type = self::EXPECTATION_ANY ) {
144  if ( $type === self::EXPECTATION_REPLICAS_ONLY ) {
145  $events = [];
146  foreach ( [ 'writes', 'masterConns' ] as $event ) {
147  if ( $this->expect[$event][self::FLD_LIMIT] === 0 ) {
148  $events[] = $event;
149  }
150  }
151  } else {
152  $events = self::EVENT_NAMES;
153  }
154 
155  foreach ( $events as $event ) {
156  ++$this->silenced[$event];
157  }
158 
159  return new ScopedCallback( function () use ( $events ) {
160  foreach ( $events as $event ) {
161  --$this->silenced[$event];
162  }
163  } );
164  }
165 
176  public function setExpectation( string $event, $limit, string $fname ) {
177  if ( !isset( $this->expect[$event] ) ) {
178  return; // obsolete/bogus expectation
179  }
180 
181  if ( $limit <= $this->expect[$event][self::FLD_LIMIT] ) {
182  // New limit is more restrictive
183  $this->expect[$event] = [
184  self::FLD_LIMIT => $limit,
185  self::FLD_FNAME => $fname
186  ];
187  }
188  }
189 
201  public function setExpectations( array $expects, string $fname ) {
202  foreach ( $expects as $event => $value ) {
203  $this->setExpectation( $event, $value, $fname );
204  }
205  }
206 
216  public function resetExpectations() {
217  $this->initPlaceholderExpectations();
218  }
219 
230  public function redefineExpectations( array $expects, string $fname ) {
231  $this->initPlaceholderExpectations();
232  $this->setExpectations( $expects, $fname );
233  }
234 
244  public function recordConnection( $server, $db, bool $isPrimary ) {
245  // Report when too many connections happen...
246  if ( $this->pingAndCheckThreshold( 'conns' ) ) {
247  $this->reportExpectationViolated(
248  'conns',
249  "[connect to $server ($db)]",
250  $this->hits['conns']
251  );
252  }
253 
254  // Report when too many primary connections happen...
255  if ( $isPrimary && $this->pingAndCheckThreshold( 'masterConns' ) ) {
256  $this->reportExpectationViolated(
257  'masterConns',
258  "[connect to $server ($db)]",
259  $this->hits['masterConns']
260  );
261  }
262  }
263 
273  public function transactionWritingIn( $server, $db, string $id ) {
274  $name = "{$db} {$server} TRX#$id";
275  if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
276  $this->logger->warning( "Nested transaction for '$name' - out of sync." );
277  }
278  $this->dbTrxHoldingLocks[$name] = [
279  'start' => $this->getCurrentTime(),
280  'conns' => [], // all connections involved
281  ];
282  $this->dbTrxMethodTimes[$name] = [];
283 
284  foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
285  // Track all DBs in transactions for this transaction
286  $info['conns'][$name] = 1;
287  }
288  }
289 
302  public function recordQueryCompletion(
303  $query,
304  float $sTime,
305  bool $isWrite,
306  ?int $rowCount,
307  string $trxId,
308  ?string $serverName = null
309  ) {
310  $eTime = $this->getCurrentTime();
311  $elapsed = ( $eTime - $sTime );
312 
313  if ( $isWrite && $this->isAboveThreshold( $rowCount, 'maxAffected' ) ) {
314  $this->reportExpectationViolated( 'maxAffected', $query, $rowCount, $trxId, $serverName );
315  } elseif ( !$isWrite && $this->isAboveThreshold( $rowCount, 'readQueryRows' ) ) {
316  $this->reportExpectationViolated( 'readQueryRows', $query, $rowCount, $trxId, $serverName );
317  }
318 
319  // Report when too many writes/queries happen...
320  if ( $this->pingAndCheckThreshold( 'queries' ) ) {
321  $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'], $trxId, $serverName );
322  }
323  if ( $isWrite && $this->pingAndCheckThreshold( 'writes' ) ) {
324  $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'], $trxId, $serverName );
325  }
326  // Report slow queries...
327  if ( !$isWrite && $this->isAboveThreshold( $elapsed, 'readQueryTime' ) ) {
328  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed, $trxId, $serverName );
329  }
330  if ( $isWrite && $this->isAboveThreshold( $elapsed, 'writeQueryTime' ) ) {
331  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed, $trxId, $serverName );
332  }
333 
334  if ( !$this->dbTrxHoldingLocks ) {
335  // Short-circuit
336  return;
337  } elseif ( !$isWrite && $elapsed < self::EVENT_THRESHOLD_SEC ) {
338  // Not an important query nor slow enough
339  return;
340  }
341 
342  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
343  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
344  if ( $lastQuery ) {
345  // Additional query in the trx...
346  $lastEnd = $lastQuery[2];
347  if ( $sTime >= $lastEnd ) {
348  if ( ( $sTime - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
349  // Add an entry representing the time spent doing non-queries
350  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
351  }
352  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
353  }
354  } else {
355  // First query in the trx...
356  if ( $sTime >= $info['start'] ) {
357  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
358  }
359  }
360  }
361  }
362 
376  public function transactionWritingOut(
377  $server,
378  $db,
379  string $id,
380  float $writeTime,
381  int $affected
382  ) {
383  // Must match $name in transactionWritingIn()
384  $name = "{$db} {$server} TRX#$id";
385  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
386  $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
387  return;
388  }
389 
390  $slow = false;
391 
392  // Warn if too much time was spend writing...
393  if ( $this->isAboveThreshold( $writeTime, 'writeQueryTime' ) ) {
394  $this->reportExpectationViolated(
395  'writeQueryTime',
396  "[transaction writes to {$db} at {$server}]",
397  $writeTime,
398  $id
399  );
400  $slow = true;
401  }
402  // Warn if too many rows were changed...
403  if ( $this->isAboveThreshold( $affected, 'maxAffected' ) ) {
404  $this->reportExpectationViolated(
405  'maxAffected',
406  "[transaction writes to {$db} at {$server}]",
407  $affected,
408  $id
409  );
410  }
411  // Fill in the last non-query period...
412  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
413  if ( $lastQuery ) {
414  $now = $this->getCurrentTime();
415  $lastEnd = $lastQuery[2];
416  if ( ( $now - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
417  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
418  }
419  }
420  // Check for any slow queries or non-query periods...
421  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
422  $elapsed = ( $info[2] - $info[1] );
423  if ( $elapsed >= self::DB_LOCK_THRESHOLD_SEC ) {
424  $slow = true;
425  break;
426  }
427  }
428  if ( $slow ) {
429  $trace = '';
430  foreach ( $this->dbTrxMethodTimes[$name] as $i => [ $query, $sTime, $end ] ) {
431  $trace .= sprintf(
432  "%-2d %.3fs %s\n", $i, ( $end - $sTime ), $this->getGeneralizedSql( $query ) );
433  }
434  $this->logger->warning( "Sub-optimal transaction [{dbs}]:\n{trace}", [
435  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
436  'trace' => $trace
437  ] );
438  }
439  unset( $this->dbTrxHoldingLocks[$name] );
440  unset( $this->dbTrxMethodTimes[$name] );
441  }
442 
443  private function initPlaceholderExpectations() {
444  $this->expect = array_fill_keys(
445  self::EVENT_NAMES,
446  [ self::FLD_LIMIT => INF, self::FLD_FNAME => null ]
447  );
448 
449  $this->hits = array_fill_keys( self::COUNTER_EVENT_NAMES, 0 );
450  }
451 
457  private function isAboveThreshold( $value, string $event ) {
458  if ( $this->silenced[$event] > 0 ) {
459  return false;
460  }
461 
462  return ( $value > $this->expect[$event][self::FLD_LIMIT] );
463  }
464 
469  private function pingAndCheckThreshold( string $event ) {
470  if ( $this->silenced[$event] > 0 ) {
471  return false;
472  }
473 
474  $newValue = ++$this->hits[$event];
475  $limit = $this->expect[$event][self::FLD_LIMIT];
476 
477  return ( $newValue > $limit );
478  }
479 
487  private function reportExpectationViolated(
488  $event,
489  $query,
490  $actual,
491  ?string $trxId = null,
492  ?string $serverName = null
493  ) {
494  $max = $this->expect[$event][self::FLD_LIMIT];
495  $by = $this->expect[$event][self::FLD_FNAME];
496  $message = "Expectation ($event <= $max) by $by not met (actual: {actualSeconds})";
497  if ( $trxId ) {
498  $message .= ' in trx #{trxId}';
499  }
500  $message .= ":\n{query}\n";
501  $this->logger->warning(
502  $message,
503  [
504  'measure' => $event,
505  'maxSeconds' => $max,
506  'by' => $by,
507  'actualSeconds' => $actual,
508  'query' => $this->getGeneralizedSql( $query ),
509  'exception' => new RuntimeException(),
510  'trxId' => $trxId,
511  'fullQuery' => $this->getRawSql( $query ),
512  'dbHost' => $serverName
513  ]
514  );
515  }
516 
521  private function getGeneralizedSql( $query ) {
522  return $query instanceof GeneralizedSql ? $query->stringify() : $query;
523  }
524 
529  private function getRawSql( $query ) {
530  return $query instanceof GeneralizedSql ? $query->getRawSql() : $query;
531  }
532 
537  private function getCurrentTime() {
538  return $this->wallClockOverride ?: microtime( true );
539  }
540 
545  public function setMockTime( &$time ) {
546  $this->wallClockOverride =& $time;
547  }
548 }
wfDeprecated( $function, $version=false, $component=false, $callerOffset=2)
Logs a warning that a deprecated feature was used.
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.
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.
recordConnection( $server, $db, bool $isPrimary)
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.