MediaWiki  master
TransactionProfiler.php
Go to the documentation of this file.
1 <?php
24 namespace Wikimedia\Rdbms;
25 
30 
38 class TransactionProfiler implements LoggerAwareInterface {
40  protected $dbLockThreshold = 3.0;
42  protected $eventThreshold = 0.25;
44  protected $silenced = false;
45 
47  protected $dbTrxHoldingLocks = [];
52  protected $dbTrxMethodTimes = [];
53 
55  protected $hits = [
56  'writes' => 0,
57  'queries' => 0,
58  'conns' => 0,
59  'masterConns' => 0
60  ];
62  protected $expect = [
63  'writes' => INF,
64  'queries' => INF,
65  'conns' => INF,
66  'masterConns' => INF,
67  'maxAffected' => INF,
68  'readQueryRows' => INF,
69  'readQueryTime' => INF,
70  'writeQueryTime' => INF
71  ];
73  protected $expectBy = [];
74 
78  private $logger;
79 
80  public function __construct() {
81  $this->setLogger( new NullLogger() );
82  }
83 
84  public function setLogger( LoggerInterface $logger ) {
85  $this->logger = $logger;
86  }
87 
93  public function setSilenced( $value ) {
94  $old = $this->silenced;
95  $this->silenced = $value;
96 
97  return $old;
98  }
99 
110  public function setExpectation( $event, $value, $fname ) {
111  $this->expect[$event] = isset( $this->expect[$event] )
112  ? min( $this->expect[$event], $value )
113  : $value;
114  if ( $this->expect[$event] == $value ) {
115  $this->expectBy[$event] = $fname;
116  }
117  }
118 
130  public function setExpectations( array $expects, $fname ) {
131  foreach ( $expects as $event => $value ) {
132  $this->setExpectation( $event, $value, $fname );
133  }
134  }
135 
145  public function resetExpectations() {
146  foreach ( $this->hits as &$val ) {
147  $val = 0;
148  }
149  unset( $val );
150  foreach ( $this->expect as &$val ) {
151  $val = INF;
152  }
153  unset( $val );
154  $this->expectBy = [];
155  }
156 
167  public function redefineExpectations( array $expects, $fname ) {
168  $this->resetExpectations();
169  $this->setExpectations( $expects, $fname );
170  }
171 
181  public function recordConnection( $server, $db, $isMaster ) {
182  // Report when too many connections happen...
183  if ( $this->hits['conns']++ >= $this->expect['conns'] ) {
185  'conns', "[connect to $server ($db)]", $this->hits['conns'] );
186  }
187  if ( $isMaster && $this->hits['masterConns']++ >= $this->expect['masterConns'] ) {
189  'masterConns', "[connect to $server ($db)]", $this->hits['masterConns'] );
190  }
191  }
192 
202  public function transactionWritingIn( $server, $db, $id ) {
203  $name = "{$server} ({$db}) (TRX#$id)";
204  if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
205  $this->logger->warning( "Nested transaction for '$name' - out of sync." );
206  }
207  $this->dbTrxHoldingLocks[$name] = [
208  'start' => microtime( true ),
209  'conns' => [], // all connections involved
210  ];
211  $this->dbTrxMethodTimes[$name] = [];
212 
213  foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
214  // Track all DBs in transactions for this transaction
215  $info['conns'][$name] = 1;
216  }
217  }
218 
229  public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
230  $eTime = microtime( true );
231  $elapsed = ( $eTime - $sTime );
232 
233  if ( $isWrite && $n > $this->expect['maxAffected'] ) {
234  $this->logger->warning(
235  "Query affected $n row(s):\n" . self::queryString( $query ) . "\n" .
236  ( new RuntimeException() )->getTraceAsString() );
237  } elseif ( !$isWrite && $n > $this->expect['readQueryRows'] ) {
238  $this->logger->warning(
239  "Query returned $n row(s):\n" . self::queryString( $query ) . "\n" .
240  ( new RuntimeException() )->getTraceAsString() );
241  }
242 
243  // Report when too many writes/queries happen...
244  if ( $this->hits['queries']++ >= $this->expect['queries'] ) {
245  $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
246  }
247  if ( $isWrite && $this->hits['writes']++ >= $this->expect['writes'] ) {
248  $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
249  }
250  // Report slow queries...
251  if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
252  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
253  }
254  if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
255  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
256  }
257 
258  if ( !$this->dbTrxHoldingLocks ) {
259  // Short-circuit
260  return;
261  } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
262  // Not an important query nor slow enough
263  return;
264  }
265 
266  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
267  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
268  if ( $lastQuery ) {
269  // Additional query in the trx...
270  $lastEnd = $lastQuery[2];
271  if ( $sTime >= $lastEnd ) { // sanity check
272  if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
273  // Add an entry representing the time spent doing non-queries
274  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
275  }
276  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
277  }
278  } else {
279  // First query in the trx...
280  if ( $sTime >= $info['start'] ) { // sanity check
281  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
282  }
283  }
284  }
285  }
286 
300  public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
301  $name = "{$server} ({$db}) (TRX#$id)";
302  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
303  $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
304  return;
305  }
306 
307  $slow = false;
308 
309  // Warn if too much time was spend writing...
310  if ( $writeTime > $this->expect['writeQueryTime'] ) {
312  'writeQueryTime',
313  "[transaction $id writes to {$server} ({$db})]",
314  $writeTime
315  );
316  $slow = true;
317  }
318  // Warn if too many rows were changed...
319  if ( $affected > $this->expect['maxAffected'] ) {
321  'maxAffected',
322  "[transaction $id writes to {$server} ({$db})]",
323  $affected
324  );
325  }
326  // Fill in the last non-query period...
327  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
328  if ( $lastQuery ) {
329  $now = microtime( true );
330  $lastEnd = $lastQuery[2];
331  if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
332  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
333  }
334  }
335  // Check for any slow queries or non-query periods...
336  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
337  $elapsed = ( $info[2] - $info[1] );
338  if ( $elapsed >= $this->dbLockThreshold ) {
339  $slow = true;
340  break;
341  }
342  }
343  if ( $slow ) {
344  $trace = '';
345  foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
346  list( $query, $sTime, $end ) = $info;
347  $trace .= sprintf(
348  "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self::queryString( $query ) );
349  }
350  $this->logger->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
351  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
352  'trace' => $trace
353  ] );
354  }
355  unset( $this->dbTrxHoldingLocks[$name] );
356  unset( $this->dbTrxMethodTimes[$name] );
357  }
358 
364  protected function reportExpectationViolated( $expect, $query, $actual ) {
365  if ( $this->silenced ) {
366  return;
367  }
368 
369  $this->logger->warning(
370  "Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n" .
371  ( new RuntimeException() )->getTraceAsString(),
372  [
373  'measure' => $expect,
374  'max' => $this->expect[$expect],
375  'by' => $this->expectBy[$expect],
376  'actual' => $actual,
377  'query' => self::queryString( $query )
378  ]
379  );
380  }
381 
386  private static function queryString( $query ) {
387  return $query instanceof GeneralizedSql ? $query->stringify() : $query;
388  }
389 }
Helper class that detects high-contention DB queries via profiling calls.
reportExpectationViolated( $expect, $query, $actual)
setExpectation( $event, $value, $fname)
Set performance expectations.
Lazy-loaded wrapper for simplification and scrubbing of SQL queries for profiling.
recordConnection( $server, $db, $isMaster)
Mark a DB as having been connected to with a new handle.
resetExpectations()
Reset all performance expectations and hit counters.
transactionWritingOut( $server, $db, $id, $writeTime=0.0, $affected=0)
Mark a DB as no longer in a transaction.
recordQueryCompletion( $query, $sTime, $isWrite=false, $n=0)
Register the name and time of a method for slow DB trx detection.
array $dbTrxHoldingLocks
transaction ID => (write start time, list of DBs involved)
array [][] $dbTrxMethodTimes
transaction ID => list of (query name, start time, end time) -var array<string,array<int,array{0:string,1:int,2:int}>>
redefineExpectations(array $expects, $fname)
Clear all expectations and hit counters and set new performance expectations.
setExpectations(array $expects, $fname)
Set one or multiple performance expectations.
transactionWritingIn( $server, $db, $id)
Mark a DB as in a transaction with one or more writes pending.