MediaWiki  master
TransactionProfiler.php
Go to the documentation of this file.
1 <?php
20 namespace Wikimedia\Rdbms;
21 
22 use Liuggio\StatsdClient\Factory\StatsdDataFactoryInterface;
24 use Psr\Log\LoggerAwareInterface;
25 use Psr\Log\LoggerInterface;
26 use Psr\Log\NullLogger;
27 use RuntimeException;
29 use Wikimedia\ScopedCallback;
30 
41 class TransactionProfiler implements LoggerAwareInterface, StatsdAwareInterface {
43  private $logger;
45  private $stats;
47  private $expect;
49  private $hits;
51  private $violations;
53  private $silenced;
54 
59  private $dbTrxHoldingLocks;
60 
65  private $dbTrxMethodTimes;
66 
68  private $method;
69 
71  private $wallClockOverride;
72 
74  private const DB_LOCK_THRESHOLD_SEC = 3.0;
76  private const EVENT_THRESHOLD_SEC = 0.25;
77 
79  private const EVENT_NAMES = [
80  'writes',
81  'queries',
82  'conns',
83  'masterConns',
84  'maxAffected',
85  'readQueryRows',
86  'readQueryTime',
87  'writeQueryTime'
88  ];
89 
91  private const COUNTER_EVENT_NAMES = [
92  'writes',
93  'queries',
94  'conns',
95  'masterConns'
96  ];
97 
99  private const FLD_LIMIT = 0;
101  private const FLD_FNAME = 1;
102 
104  public const EXPECTATION_ANY = 'any';
106  public const EXPECTATION_REPLICAS_ONLY = 'replicas-only';
107 
108  public function __construct() {
109  $this->initPlaceholderExpectations();
110 
111  $this->dbTrxHoldingLocks = [];
112  $this->dbTrxMethodTimes = [];
113 
114  $this->silenced = array_fill_keys( self::EVENT_NAMES, 0 );
115 
116  $this->setLogger( new NullLogger() );
117  $this->setStatsdDataFactory( new NullStatsdDataFactory() );
118  }
119 
120  public function setLogger( LoggerInterface $logger ) {
121  $this->logger = $logger;
122  }
123 
124  public function setStatsdDataFactory( StatsdDataFactoryInterface $statsFactory ) {
125  $this->stats = $statsFactory;
126  }
127 
132  public function setRequestMethod( ?string $method ) {
133  $this->method = $method;
134  }
135 
142  public function setSilenced( bool $value ) {
143  wfDeprecated( __METHOD__, '1.40' );
144 
145  $delta = $value ? 1 : -1;
146  foreach ( self::EVENT_NAMES as $event ) {
147  $this->silenced[$event] += $delta;
148  }
149 
150  return false;
151  }
152 
166  public function silenceForScope( string $type = self::EXPECTATION_ANY ) {
167  if ( $type === self::EXPECTATION_REPLICAS_ONLY ) {
168  $events = [];
169  foreach ( [ 'writes', 'masterConns' ] as $event ) {
170  if ( $this->expect[$event][self::FLD_LIMIT] === 0 ) {
171  $events[] = $event;
172  }
173  }
174  } else {
175  $events = self::EVENT_NAMES;
176  }
177 
178  foreach ( $events as $event ) {
179  ++$this->silenced[$event];
180  }
181 
182  return new ScopedCallback( function () use ( $events ) {
183  foreach ( $events as $event ) {
184  --$this->silenced[$event];
185  }
186  } );
187  }
188 
199  public function setExpectation( string $event, $limit, string $fname ) {
200  if ( !isset( $this->expect[$event] ) ) {
201  return; // obsolete/bogus expectation
202  }
203 
204  if ( $limit <= $this->expect[$event][self::FLD_LIMIT] ) {
205  // New limit is more restrictive
206  $this->expect[$event] = [
207  self::FLD_LIMIT => $limit,
208  self::FLD_FNAME => $fname
209  ];
210  }
211  }
212 
224  public function setExpectations( array $expects, string $fname ) {
225  foreach ( $expects as $event => $value ) {
226  $this->setExpectation( $event, $value, $fname );
227  }
228  }
229 
239  public function resetExpectations() {
240  $this->initPlaceholderExpectations();
241  }
242 
253  public function redefineExpectations( array $expects, string $fname ) {
254  $this->initPlaceholderExpectations();
255  $this->setExpectations( $expects, $fname );
256  }
257 
267  public function recordConnection( $server, $db, bool $isPrimary ) {
268  // Report when too many connections happen...
269  if ( $this->pingAndCheckThreshold( 'conns' ) ) {
270  $this->reportExpectationViolated(
271  'conns',
272  "[connect to $server ($db)]",
273  $this->hits['conns']
274  );
275  }
276 
277  // Report when too many primary connections happen...
278  if ( $isPrimary && $this->pingAndCheckThreshold( 'masterConns' ) ) {
279  $this->reportExpectationViolated(
280  'masterConns',
281  "[connect to $server ($db)]",
282  $this->hits['masterConns']
283  );
284  }
285  }
286 
296  public function transactionWritingIn( $server, $db, string $id ) {
297  $name = "{$db} {$server} TRX#$id";
298  if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
299  $this->logger->warning( "Nested transaction for '$name' - out of sync." );
300  }
301  $this->dbTrxHoldingLocks[$name] = [
302  'start' => $this->getCurrentTime(),
303  'conns' => [], // all connections involved
304  ];
305  $this->dbTrxMethodTimes[$name] = [];
306 
307  foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
308  // Track all DBs in transactions for this transaction
309  $info['conns'][$name] = 1;
310  }
311  }
312 
325  public function recordQueryCompletion(
326  $query,
327  float $sTime,
328  bool $isWrite,
329  ?int $rowCount,
330  string $trxId,
331  ?string $serverName = null
332  ) {
333  $eTime = $this->getCurrentTime();
334  $elapsed = ( $eTime - $sTime );
335 
336  if ( $isWrite && $this->isAboveThreshold( $rowCount, 'maxAffected' ) ) {
337  $this->reportExpectationViolated( 'maxAffected', $query, $rowCount, $trxId, $serverName );
338  } elseif ( !$isWrite && $this->isAboveThreshold( $rowCount, 'readQueryRows' ) ) {
339  $this->reportExpectationViolated( 'readQueryRows', $query, $rowCount, $trxId, $serverName );
340  }
341 
342  // Report when too many writes/queries happen...
343  if ( $this->pingAndCheckThreshold( 'queries' ) ) {
344  $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'], $trxId, $serverName );
345  }
346  if ( $isWrite && $this->pingAndCheckThreshold( 'writes' ) ) {
347  $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'], $trxId, $serverName );
348  }
349  // Report slow queries...
350  if ( !$isWrite && $this->isAboveThreshold( $elapsed, 'readQueryTime' ) ) {
351  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed, $trxId, $serverName );
352  }
353  if ( $isWrite && $this->isAboveThreshold( $elapsed, 'writeQueryTime' ) ) {
354  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed, $trxId, $serverName );
355  }
356 
357  if ( !$this->dbTrxHoldingLocks ) {
358  // Short-circuit
359  return;
360  } elseif ( !$isWrite && $elapsed < self::EVENT_THRESHOLD_SEC ) {
361  // Not an important query nor slow enough
362  return;
363  }
364 
365  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
366  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
367  if ( $lastQuery ) {
368  // Additional query in the trx...
369  $lastEnd = $lastQuery[2];
370  if ( $sTime >= $lastEnd ) {
371  if ( ( $sTime - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
372  // Add an entry representing the time spent doing non-queries
373  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
374  }
375  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
376  }
377  } else {
378  // First query in the trx...
379  if ( $sTime >= $info['start'] ) {
380  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
381  }
382  }
383  }
384  }
385 
399  public function transactionWritingOut(
400  $server,
401  $db,
402  string $id,
403  float $writeTime,
404  int $affected
405  ) {
406  // Must match $name in transactionWritingIn()
407  $name = "{$db} {$server} TRX#$id";
408  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
409  $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
410  return;
411  }
412 
413  $slow = false;
414 
415  // Warn if too much time was spend writing...
416  if ( $this->isAboveThreshold( $writeTime, 'writeQueryTime' ) ) {
417  $this->reportExpectationViolated(
418  'writeQueryTime',
419  "[transaction writes to {$db} at {$server}]",
420  $writeTime,
421  $id
422  );
423  $slow = true;
424  }
425  // Warn if too many rows were changed...
426  if ( $this->isAboveThreshold( $affected, 'maxAffected' ) ) {
427  $this->reportExpectationViolated(
428  'maxAffected',
429  "[transaction writes to {$db} at {$server}]",
430  $affected,
431  $id
432  );
433  }
434  // Fill in the last non-query period...
435  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
436  if ( $lastQuery ) {
437  $now = $this->getCurrentTime();
438  $lastEnd = $lastQuery[2];
439  if ( ( $now - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
440  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
441  }
442  }
443  // Check for any slow queries or non-query periods...
444  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
445  $elapsed = ( $info[2] - $info[1] );
446  if ( $elapsed >= self::DB_LOCK_THRESHOLD_SEC ) {
447  $slow = true;
448  break;
449  }
450  }
451  if ( $slow ) {
452  $trace = '';
453  foreach ( $this->dbTrxMethodTimes[$name] as $i => [ $query, $sTime, $end ] ) {
454  $trace .= sprintf(
455  "%-2d %.3fs %s\n", $i, ( $end - $sTime ), $this->getGeneralizedSql( $query ) );
456  }
457  $this->logger->warning( "Sub-optimal transaction [{dbs}]:\n{trace}", [
458  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
459  'trace' => $trace
460  ] );
461  }
462  unset( $this->dbTrxHoldingLocks[$name] );
463  unset( $this->dbTrxMethodTimes[$name] );
464  }
465 
466  private function initPlaceholderExpectations() {
467  $this->expect = array_fill_keys(
468  self::EVENT_NAMES,
469  [ self::FLD_LIMIT => INF, self::FLD_FNAME => null ]
470  );
471 
472  $this->hits = array_fill_keys( self::COUNTER_EVENT_NAMES, 0 );
473  $this->violations = array_fill_keys( self::EVENT_NAMES, 0 );
474  }
475 
481  private function isAboveThreshold( $value, string $event ) {
482  if ( $this->silenced[$event] > 0 ) {
483  return false;
484  }
485 
486  return ( $value > $this->expect[$event][self::FLD_LIMIT] );
487  }
488 
493  private function pingAndCheckThreshold( string $event ) {
494  if ( $this->silenced[$event] > 0 ) {
495  return false;
496  }
497 
498  $newValue = ++$this->hits[$event];
499  $limit = $this->expect[$event][self::FLD_LIMIT];
500 
501  return ( $newValue > $limit );
502  }
503 
511  private function reportExpectationViolated(
512  $event,
513  $query,
514  $actual,
515  ?string $trxId = null,
516  ?string $serverName = null
517  ) {
518  $violations = ++$this->violations[$event];
519  // First violation; check if this is a web request
520  if ( $violations === 1 && $this->method !== null ) {
521  $this->stats->increment( "rdbms_trxprofiler_warnings.$event.{$this->method}" );
522  }
523 
524  $max = $this->expect[$event][self::FLD_LIMIT];
525  $by = $this->expect[$event][self::FLD_FNAME];
526 
527  $message = "Expectation ($event <= $max) by $by not met (actual: {actualSeconds})";
528  if ( $trxId ) {
529  $message .= ' in trx #{trxId}';
530  }
531  $message .= ":\n{query}\n";
532 
533  $this->logger->warning(
534  $message,
535  [
536  'db_log_category' => 'performance',
537  'measure' => $event,
538  'maxSeconds' => $max,
539  'by' => $by,
540  'actualSeconds' => $actual,
541  'query' => $this->getGeneralizedSql( $query ),
542  'exception' => new RuntimeException(),
543  'trxId' => $trxId,
544  'fullQuery' => $this->getRawSql( $query ),
545  'dbHost' => $serverName
546  ]
547  );
548  }
549 
554  private function getGeneralizedSql( $query ) {
555  return $query instanceof GeneralizedSql ? $query->stringify() : $query;
556  }
557 
562  private function getRawSql( $query ) {
563  return $query instanceof GeneralizedSql ? $query->getRawSql() : $query;
564  }
565 
570  private function getCurrentTime() {
571  return $this->wallClockOverride ?: microtime( true );
572  }
573 
578  public function setMockTime( &$time ) {
579  $this->wallClockOverride =& $time;
580  }
581 }
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.
setStatsdDataFactory(StatsdDataFactoryInterface $statsFactory)
Sets a StatsdDataFactory instance on the object.
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.
Describes a Statsd aware interface.