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 = [];
49  protected $dbTrxMethodTimes = [];
50 
52  protected $hits = [
53  'writes' => 0,
54  'queries' => 0,
55  'conns' => 0,
56  'masterConns' => 0
57  ];
59  protected $expect = [
60  'writes' => INF,
61  'queries' => INF,
62  'conns' => INF,
63  'masterConns' => INF,
64  'maxAffected' => INF,
65  'readQueryRows' => INF,
66  'readQueryTime' => INF,
67  'writeQueryTime' => INF
68  ];
70  protected $expectBy = [];
71 
75  private $logger;
76 
77  public function __construct() {
78  $this->setLogger( new NullLogger() );
79  }
80 
81  public function setLogger( LoggerInterface $logger ) {
82  $this->logger = $logger;
83  }
84 
90  public function setSilenced( $value ) {
91  $old = $this->silenced;
92  $this->silenced = $value;
93 
94  return $old;
95  }
96 
107  public function setExpectation( $event, $value, $fname ) {
108  $this->expect[$event] = isset( $this->expect[$event] )
109  ? min( $this->expect[$event], $value )
110  : $value;
111  if ( $this->expect[$event] == $value ) {
112  $this->expectBy[$event] = $fname;
113  }
114  }
115 
127  public function setExpectations( array $expects, $fname ) {
128  foreach ( $expects as $event => $value ) {
129  $this->setExpectation( $event, $value, $fname );
130  }
131  }
132 
142  public function resetExpectations() {
143  foreach ( $this->hits as &$val ) {
144  $val = 0;
145  }
146  unset( $val );
147  foreach ( $this->expect as &$val ) {
148  $val = INF;
149  }
150  unset( $val );
151  $this->expectBy = [];
152  }
153 
164  public function redefineExpectations( array $expects, $fname ) {
165  $this->resetExpectations();
166  $this->setExpectations( $expects, $fname );
167  }
168 
178  public function recordConnection( $server, $db, $isMaster ) {
179  // Report when too many connections happen...
180  if ( $this->hits['conns']++ >= $this->expect['conns'] ) {
182  'conns', "[connect to $server ($db)]", $this->hits['conns'] );
183  }
184  if ( $isMaster && $this->hits['masterConns']++ >= $this->expect['masterConns'] ) {
186  'masterConns', "[connect to $server ($db)]", $this->hits['masterConns'] );
187  }
188  }
189 
199  public function transactionWritingIn( $server, $db, $id ) {
200  $name = "{$server} ({$db}) (TRX#$id)";
201  if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
202  $this->logger->warning( "Nested transaction for '$name' - out of sync." );
203  }
204  $this->dbTrxHoldingLocks[$name] = [
205  'start' => microtime( true ),
206  'conns' => [], // all connections involved
207  ];
208  $this->dbTrxMethodTimes[$name] = [];
209 
210  foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
211  // Track all DBs in transactions for this transaction
212  $info['conns'][$name] = 1;
213  }
214  }
215 
226  public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
227  $eTime = microtime( true );
228  $elapsed = ( $eTime - $sTime );
229 
230  if ( $isWrite && $n > $this->expect['maxAffected'] ) {
231  $this->logger->warning(
232  "Query affected $n row(s):\n" . self::queryString( $query ) . "\n" .
233  ( new RuntimeException() )->getTraceAsString() );
234  } elseif ( !$isWrite && $n > $this->expect['readQueryRows'] ) {
235  $this->logger->warning(
236  "Query returned $n row(s):\n" . self::queryString( $query ) . "\n" .
237  ( new RuntimeException() )->getTraceAsString() );
238  }
239 
240  // Report when too many writes/queries happen...
241  if ( $this->hits['queries']++ >= $this->expect['queries'] ) {
242  $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
243  }
244  if ( $isWrite && $this->hits['writes']++ >= $this->expect['writes'] ) {
245  $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
246  }
247  // Report slow queries...
248  if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
249  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
250  }
251  if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
252  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
253  }
254 
255  if ( !$this->dbTrxHoldingLocks ) {
256  // Short-circuit
257  return;
258  } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
259  // Not an important query nor slow enough
260  return;
261  }
262 
263  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
264  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
265  if ( $lastQuery ) {
266  // Additional query in the trx...
267  $lastEnd = $lastQuery[2];
268  if ( $sTime >= $lastEnd ) { // sanity check
269  if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
270  // Add an entry representing the time spent doing non-queries
271  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
272  }
273  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
274  }
275  } else {
276  // First query in the trx...
277  if ( $sTime >= $info['start'] ) { // sanity check
278  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
279  }
280  }
281  }
282  }
283 
297  public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
298  $name = "{$server} ({$db}) (TRX#$id)";
299  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
300  $this->logger->warning( "Detected no transaction for '$name' - out of sync." );
301  return;
302  }
303 
304  $slow = false;
305 
306  // Warn if too much time was spend writing...
307  if ( $writeTime > $this->expect['writeQueryTime'] ) {
309  'writeQueryTime',
310  "[transaction $id writes to {$server} ({$db})]",
311  $writeTime
312  );
313  $slow = true;
314  }
315  // Warn if too many rows were changed...
316  if ( $affected > $this->expect['maxAffected'] ) {
318  'maxAffected',
319  "[transaction $id writes to {$server} ({$db})]",
320  $affected
321  );
322  }
323  // Fill in the last non-query period...
324  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
325  if ( $lastQuery ) {
326  $now = microtime( true );
327  $lastEnd = $lastQuery[2];
328  if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
329  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
330  }
331  }
332  // Check for any slow queries or non-query periods...
333  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
334  $elapsed = ( $info[2] - $info[1] );
335  if ( $elapsed >= $this->dbLockThreshold ) {
336  $slow = true;
337  break;
338  }
339  }
340  if ( $slow ) {
341  $trace = '';
342  foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
343  list( $query, $sTime, $end ) = $info;
344  $trace .= sprintf(
345  "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self::queryString( $query ) );
346  }
347  $this->logger->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
348  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
349  'trace' => $trace
350  ] );
351  }
352  unset( $this->dbTrxHoldingLocks[$name] );
353  unset( $this->dbTrxMethodTimes[$name] );
354  }
355 
361  protected function reportExpectationViolated( $expect, $query, $actual ) {
362  if ( $this->silenced ) {
363  return;
364  }
365 
366  $this->logger->warning(
367  "Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n" .
368  ( new RuntimeException() )->getTraceAsString(),
369  [
370  'measure' => $expect,
371  'max' => $this->expect[$expect],
372  'by' => $this->expectBy[$expect],
373  'actual' => $actual,
374  'query' => self::queryString( $query )
375  ]
376  );
377  }
378 
383  private static function queryString( $query ) {
384  return $query instanceof GeneralizedSql ? $query->stringify() : $query;
385  }
386 }
The wiki should then use memcached to cache various data To use multiple just add more items to the array To increase the weight of a make its entry a array("192.168.0.1:11211", 2))
Helper class that detects high-contention DB queries via profiling calls.
reportExpectationViolated( $expect, $query, $actual)
deferred txt A few of the database updates required by various functions here can be deferred until after the result page is displayed to the user For updating the view updating the linked to tables after a etc PHP does not yet have any way to tell the server to actually return and disconnect while still running these but it might have such a feature in the future We handle these by creating a deferred update object and putting those objects on a global list
Definition: deferred.txt:11
null for the local wiki Added should default to null in handler for backwards compatibility add a value to it if you want to add a cookie that have to vary cache options can modify $query
Definition: hooks.txt:1585
setExpectation( $event, $value, $fname)
Set performance expectations.
Apache License January AND DISTRIBUTION Definitions License shall mean the terms and conditions for use
$value
Lazy-loaded wrapper for simplification and scrubbing of SQL queries for profiling.
array $dbTrxMethodTimes
transaction ID => list of (query name, start time, end time)
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)
This document is intended to provide useful advice for parties seeking to redistribute MediaWiki to end users It s targeted particularly at maintainers for Linux since it s been observed that distribution packages of MediaWiki often break We ve consistently had to recommend that users seeking support use official tarballs instead of their distribution s and this often solves whatever problem the user is having It would be nice if this could such as
Definition: distributors.txt:9
if(defined( 'MW_SETUP_CALLBACK')) $fname
Customization point after all loading (constants, functions, classes, DefaultSettings, LocalSettings).
Definition: Setup.php:123
redefineExpectations(array $expects, $fname)
Clear all expectations and hit counters and set new performance expectations.
injection txt This is an overview of how MediaWiki makes use of dependency injection The design described here grew from the discussion of RFC T384 The term dependency this means that anything an object needs to operate should be injected from the the object itself should only know narrow no concrete implementation of the logic it relies on The requirement to inject everything typically results in an architecture that based on two main types of and essentially stateless service objects that use other service objects to operate on the value objects As of the beginning MediaWiki is only starting to use the DI approach Much of the code still relies on global state or direct resulting in a highly cyclical dependency which acts as the top level factory for services in MediaWiki which can be used to gain access to default instances of various services MediaWikiServices however also allows new services to be defined and default services to be redefined Services are defined or redefined by providing a callback the instantiator that will return a new instance of the service When it will create an instance of MediaWikiServices and populate it with the services defined in the files listed by thereby bootstrapping the DI framework Per $wgServiceWiringFiles lists includes ServiceWiring php
Definition: injection.txt:35
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:271
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.