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 
39 class TransactionProfiler implements LoggerAwareInterface {
41  private $logger;
43  private $expect;
45  private $hits;
46 
52 
58 
60  private $silenced;
61 
63  private const DB_LOCK_THRESHOLD_SEC = 3.0;
65  private const EVENT_THRESHOLD_SEC = 0.25;
66 
68  private const EVENT_NAMES = [
69  'writes',
70  'queries',
71  'conns',
72  'masterConns',
73  'maxAffected',
74  'readQueryRows',
75  'readQueryTime',
76  'writeQueryTime'
77  ];
78 
80  private const COUNTER_EVENT_NAMES = [
81  'writes',
82  'queries',
83  'conns',
84  'masterConns'
85  ];
86 
88  private const FLD_LIMIT = 0;
90  private const FLD_FNAME = 1;
91 
92  public function __construct() {
94 
95  $this->dbTrxHoldingLocks = [];
96  $this->dbTrxMethodTimes = [];
97 
98  $this->silenced = false;
99 
100  $this->setLogger( new NullLogger() );
101  }
102 
103  public function setLogger( LoggerInterface $logger ) {
104  $this->logger = $logger;
105  }
106 
112  public function setSilenced( bool $value ) {
113  $old = $this->silenced;
114  $this->silenced = $value;
115 
116  return $old;
117  }
118 
129  public function setExpectation( string $event, $limit, string $fname ) {
130  if ( !isset( $this->expect[$event] ) ) {
131  return; // obsolete/bogus expectation
132  }
133 
134  if ( $limit <= $this->expect[$event][self::FLD_LIMIT] ) {
135  // New limit is more restrictive
136  $this->expect[$event] = [
137  self::FLD_LIMIT => $limit,
138  self::FLD_FNAME => $fname
139  ];
140  }
141  }
142 
154  public function setExpectations( array $expects, string $fname ) {
155  foreach ( $expects as $event => $value ) {
156  $this->setExpectation( $event, $value, $fname );
157  }
158  }
159 
169  public function resetExpectations() {
171  }
172 
183  public function redefineExpectations( array $expects, string $fname ) {
185  $this->setExpectations( $expects, $fname );
186  }
187 
197  public function recordConnection( $server, $db, bool $isMaster ) {
198  // Report when too many connections happen...
199  if ( $this->pingAndCheckThreshold( 'conns' ) ) {
201  'conns',
202  "[connect to $server ($db)]",
203  $this->hits['conns']
204  );
205  }
206 
207  // Report when too many master connections happen...
208  if ( $isMaster && $this->pingAndCheckThreshold( 'masterConns' ) ) {
210  'masterConns',
211  "[connect to $server ($db)]",
212  $this->hits['masterConns']
213  );
214  }
215  }
216 
226  public function transactionWritingIn( $server, $db, string $id ) {
227  $name = "{$server} ({$db}) (TRX#$id)";
228  if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
229  $this->logger->warning( "Nested transaction for '$name' - out of sync." );
230  }
231  $this->dbTrxHoldingLocks[$name] = [
232  'start' => microtime( true ),
233  'conns' => [], // all connections involved
234  ];
235  $this->dbTrxMethodTimes[$name] = [];
236 
237  foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
238  // Track all DBs in transactions for this transaction
239  $info['conns'][$name] = 1;
240  }
241  }
242 
253  public function recordQueryCompletion( $query, float $sTime, bool $isWrite, ?int $rowCount ) {
254  $eTime = microtime( true );
255  $elapsed = ( $eTime - $sTime );
256 
257  if ( $isWrite && $this->isAboveThreshold( $rowCount, 'maxAffected' ) ) {
258  $this->reportExpectationViolated( 'maxAffected', $query, $rowCount );
259  } elseif ( !$isWrite && $this->isAboveThreshold( $rowCount, 'readQueryRows' ) ) {
260  $this->reportExpectationViolated( 'readQueryRows', $query, $rowCount );
261  }
262 
263  // Report when too many writes/queries happen...
264  if ( $this->pingAndCheckThreshold( 'queries' ) ) {
265  $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
266  }
267  if ( $isWrite && $this->pingAndCheckThreshold( 'writes' ) ) {
268  $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
269  }
270  // Report slow queries...
271  if ( !$isWrite && $this->isAboveThreshold( $elapsed, 'readQueryTime' ) ) {
272  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
273  }
274  if ( $isWrite && $this->isAboveThreshold( $elapsed, 'writeQueryTime' ) ) {
275  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
276  }
277 
278  if ( !$this->dbTrxHoldingLocks ) {
279  // Short-circuit
280  return;
281  } elseif ( !$isWrite && $elapsed < self::EVENT_THRESHOLD_SEC ) {
282  // Not an important query nor slow enough
283  return;
284  }
285 
286  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
287  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
288  if ( $lastQuery ) {
289  // Additional query in the trx...
290  $lastEnd = $lastQuery[2];
291  if ( $sTime >= $lastEnd ) { // sanity check
292  if ( ( $sTime - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
293  // Add an entry representing the time spent doing non-queries
294  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
295  }
296  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
297  }
298  } else {
299  // First query in the trx...
300  if ( $sTime >= $info['start'] ) { // sanity check
301  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
302  }
303  }
304  }
305  }
306 
320  public function transactionWritingOut(
321  $server,
322  $db,
323  string $id,
324  float $writeTime,
325  int $affected
326  ) {
327  $name = "{$server} ({$db}) (TRX#$id)";
328  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
329  $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
330  return;
331  }
332 
333  $slow = false;
334 
335  // Warn if too much time was spend writing...
336  if ( $this->isAboveThreshold( $writeTime, 'writeQueryTime' ) ) {
338  'writeQueryTime',
339  "[transaction $id writes to {$server} ({$db})]",
340  $writeTime
341  );
342  $slow = true;
343  }
344  // Warn if too many rows were changed...
345  if ( $this->isAboveThreshold( $affected, 'maxAffected' ) ) {
347  'maxAffected',
348  "[transaction $id writes to {$server} ({$db})]",
349  $affected
350  );
351  }
352  // Fill in the last non-query period...
353  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
354  if ( $lastQuery ) {
355  $now = microtime( true );
356  $lastEnd = $lastQuery[2];
357  if ( ( $now - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
358  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
359  }
360  }
361  // Check for any slow queries or non-query periods...
362  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
363  $elapsed = ( $info[2] - $info[1] );
364  if ( $elapsed >= self::DB_LOCK_THRESHOLD_SEC ) {
365  $slow = true;
366  break;
367  }
368  }
369  if ( $slow ) {
370  $trace = '';
371  foreach ( $this->dbTrxMethodTimes[$name] as $i => [ $query, $sTime, $end ] ) {
372  $trace .= sprintf(
373  "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self::queryString( $query ) );
374  }
375  $this->logger->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
376  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
377  'trace' => $trace
378  ] );
379  }
380  unset( $this->dbTrxHoldingLocks[$name] );
381  unset( $this->dbTrxMethodTimes[$name] );
382  }
383 
384  private function initPlaceholderExpectations() {
385  $this->expect = array_fill_keys(
386  self::EVENT_NAMES,
387  [ self::FLD_LIMIT => INF, self::FLD_FNAME => null ]
388  );
389 
390  $this->hits = array_fill_keys( self::COUNTER_EVENT_NAMES, 0 );
391  }
392 
398  private function isAboveThreshold( $value, string $expectation ) {
399  return ( $value > $this->expect[$expectation][self::FLD_LIMIT] );
400  }
401 
406  private function pingAndCheckThreshold( string $expectation ) {
407  $newValue = ++$this->hits[$expectation];
408 
409  return ( $newValue > $this->expect[$expectation][self::FLD_LIMIT] );
410  }
411 
417  private function reportExpectationViolated( $expectation, $query, $actual ) {
418  if ( $this->silenced ) {
419  return;
420  }
421 
422  $this->logger->warning(
423  "Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n",
424  [
425  'measure' => $expectation,
426  'max' => $this->expect[$expectation][self::FLD_LIMIT],
427  'by' => $this->expect[$expectation][self::FLD_FNAME],
428  'actual' => $actual,
429  'query' => self::queryString( $query ),
430  'exception' => new RuntimeException()
431  ]
432  );
433  }
434 
439  private static function queryString( $query ) {
440  return $query instanceof GeneralizedSql ? $query->stringify() : $query;
441  }
442 }
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:320
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:65
Wikimedia\Rdbms\TransactionProfiler\isAboveThreshold
isAboveThreshold( $value, string $expectation)
Definition: TransactionProfiler.php:398
Wikimedia\Rdbms\TransactionProfiler\$dbTrxHoldingLocks
array< string, array > $dbTrxHoldingLocks
Map of (trx ID => (write start time, list of DBs involved))
Definition: TransactionProfiler.php:51
Wikimedia\Rdbms\TransactionProfiler\initPlaceholderExpectations
initPlaceholderExpectations()
Definition: TransactionProfiler.php:384
Wikimedia\Rdbms\TransactionProfiler\setExpectations
setExpectations(array $expects, string $fname)
Set one or multiple performance expectations.
Definition: TransactionProfiler.php:154
Wikimedia\Rdbms\TransactionProfiler\setLogger
setLogger(LoggerInterface $logger)
Definition: TransactionProfiler.php:103
Wikimedia\Rdbms\TransactionProfiler\setSilenced
setSilenced(bool $value)
Definition: TransactionProfiler.php:112
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:439
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:253
Wikimedia\Rdbms\TransactionProfiler\FLD_FNAME
const FLD_FNAME
Key to the function that set the max expected value.
Definition: TransactionProfiler.php:90
Wikimedia\Rdbms\TransactionProfiler\$silenced
bool $silenced
Whether logging is disabled.
Definition: TransactionProfiler.php:60
Wikimedia\Rdbms\TransactionProfiler\FLD_LIMIT
const FLD_LIMIT
Key to max expected value.
Definition: TransactionProfiler.php:88
Wikimedia\Rdbms\TransactionProfiler\reportExpectationViolated
reportExpectationViolated( $expectation, $query, $actual)
Definition: TransactionProfiler.php:417
Wikimedia\Rdbms\TransactionProfiler\COUNTER_EVENT_NAMES
const COUNTER_EVENT_NAMES
List of event names with hit counters.
Definition: TransactionProfiler.php:80
Wikimedia\Rdbms\TransactionProfiler\recordConnection
recordConnection( $server, $db, bool $isMaster)
Mark a DB as having been connected to with a new handle.
Definition: TransactionProfiler.php:197
Wikimedia\Rdbms\TransactionProfiler\pingAndCheckThreshold
pingAndCheckThreshold(string $expectation)
Definition: TransactionProfiler.php:406
Wikimedia\Rdbms\TransactionProfiler\$expect
array< string, array > $expect
Map of (name => threshold value)
Definition: TransactionProfiler.php:43
Wikimedia\Rdbms\TransactionProfiler\$logger
LoggerInterface $logger
Definition: TransactionProfiler.php:41
Wikimedia\Rdbms\TransactionProfiler\__construct
__construct()
Definition: TransactionProfiler.php:92
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:63
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:129
Wikimedia\Rdbms\TransactionProfiler\$hits
array< string, int > $hits
Map of (name => current hits)
Definition: TransactionProfiler.php:45
Wikimedia\Rdbms\TransactionProfiler\$dbTrxMethodTimes
array[][] $dbTrxMethodTimes
Map of (trx ID => list of (query name, start time, end time))
Definition: TransactionProfiler.php:57
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:226
Wikimedia\Rdbms\TransactionProfiler\resetExpectations
resetExpectations()
Reset all performance expectations and hit counters.
Definition: TransactionProfiler.php:169
Wikimedia\Rdbms\TransactionProfiler
Detect high-contention DB queries via profiling calls.
Definition: TransactionProfiler.php:39
Wikimedia\Rdbms\TransactionProfiler\redefineExpectations
redefineExpectations(array $expects, string $fname)
Clear all expectations and hit counters and set new performance expectations.
Definition: TransactionProfiler.php:183
Wikimedia\Rdbms\TransactionProfiler\EVENT_NAMES
const EVENT_NAMES
List of event names.
Definition: TransactionProfiler.php:68