MediaWiki  1.30.0
TransactionProfiler.php
Go to the documentation of this file.
1 <?php
24 namespace Wikimedia\Rdbms;
25 
26 use Psr\Log\LoggerInterface;
27 use Psr\Log\LoggerAwareInterface;
28 use Psr\Log\NullLogger;
29 use RuntimeException;
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  'readQueryTime' => INF,
66  'writeQueryTime' => INF
67  ];
69  protected $expectBy = [];
70 
74  private $logger;
75 
76  public function __construct() {
77  $this->setLogger( new NullLogger() );
78  }
79 
80  public function setLogger( LoggerInterface $logger ) {
81  $this->logger = $logger;
82  }
83 
89  public function setSilenced( $value ) {
90  $old = $this->silenced;
91  $this->silenced = $value;
92 
93  return $old;
94  }
95 
106  public function setExpectation( $event, $value, $fname ) {
107  $this->expect[$event] = isset( $this->expect[$event] )
108  ? min( $this->expect[$event], $value )
109  : $value;
110  if ( $this->expect[$event] == $value ) {
111  $this->expectBy[$event] = $fname;
112  }
113  }
114 
124  public function setExpectations( array $expects, $fname ) {
125  foreach ( $expects as $event => $value ) {
126  $this->setExpectation( $event, $value, $fname );
127  }
128  }
129 
135  public function resetExpectations() {
136  foreach ( $this->hits as &$val ) {
137  $val = 0;
138  }
139  unset( $val );
140  foreach ( $this->expect as &$val ) {
141  $val = INF;
142  }
143  unset( $val );
144  $this->expectBy = [];
145  }
146 
156  public function recordConnection( $server, $db, $isMaster ) {
157  // Report when too many connections happen...
158  if ( $this->hits['conns']++ >= $this->expect['conns'] ) {
160  'conns', "[connect to $server ($db)]", $this->hits['conns'] );
161  }
162  if ( $isMaster && $this->hits['masterConns']++ >= $this->expect['masterConns'] ) {
164  'masterConns', "[connect to $server ($db)]", $this->hits['masterConns'] );
165  }
166  }
167 
177  public function transactionWritingIn( $server, $db, $id ) {
178  $name = "{$server} ({$db}) (TRX#$id)";
179  if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
180  $this->logger->info( "Nested transaction for '$name' - out of sync." );
181  }
182  $this->dbTrxHoldingLocks[$name] = [
183  'start' => microtime( true ),
184  'conns' => [], // all connections involved
185  ];
186  $this->dbTrxMethodTimes[$name] = [];
187 
188  foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
189  // Track all DBs in transactions for this transaction
190  $info['conns'][$name] = 1;
191  }
192  }
193 
204  public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
205  $eTime = microtime( true );
206  $elapsed = ( $eTime - $sTime );
207 
208  if ( $isWrite && $n > $this->expect['maxAffected'] ) {
209  $this->logger->info(
210  "Query affected $n row(s):\n" . $query . "\n" .
211  ( new RuntimeException() )->getTraceAsString() );
212  }
213 
214  // Report when too many writes/queries happen...
215  if ( $this->hits['queries']++ >= $this->expect['queries'] ) {
216  $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
217  }
218  if ( $isWrite && $this->hits['writes']++ >= $this->expect['writes'] ) {
219  $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
220  }
221  // Report slow queries...
222  if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
223  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
224  }
225  if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
226  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
227  }
228 
229  if ( !$this->dbTrxHoldingLocks ) {
230  // Short-circuit
231  return;
232  } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
233  // Not an important query nor slow enough
234  return;
235  }
236 
237  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
238  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
239  if ( $lastQuery ) {
240  // Additional query in the trx...
241  $lastEnd = $lastQuery[2];
242  if ( $sTime >= $lastEnd ) { // sanity check
243  if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
244  // Add an entry representing the time spent doing non-queries
245  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
246  }
247  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
248  }
249  } else {
250  // First query in the trx...
251  if ( $sTime >= $info['start'] ) { // sanity check
252  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
253  }
254  }
255  }
256  }
257 
271  public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
272  $name = "{$server} ({$db}) (TRX#$id)";
273  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
274  $this->logger->info( "Detected no transaction for '$name' - out of sync." );
275  return;
276  }
277 
278  $slow = false;
279 
280  // Warn if too much time was spend writing...
281  if ( $writeTime > $this->expect['writeQueryTime'] ) {
283  'writeQueryTime',
284  "[transaction $id writes to {$server} ({$db})]",
285  $writeTime
286  );
287  $slow = true;
288  }
289  // Warn if too many rows were changed...
290  if ( $affected > $this->expect['maxAffected'] ) {
292  'maxAffected',
293  "[transaction $id writes to {$server} ({$db})]",
294  $affected
295  );
296  }
297  // Fill in the last non-query period...
298  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
299  if ( $lastQuery ) {
300  $now = microtime( true );
301  $lastEnd = $lastQuery[2];
302  if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
303  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
304  }
305  }
306  // Check for any slow queries or non-query periods...
307  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
308  $elapsed = ( $info[2] - $info[1] );
309  if ( $elapsed >= $this->dbLockThreshold ) {
310  $slow = true;
311  break;
312  }
313  }
314  if ( $slow ) {
315  $trace = '';
316  foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
317  list( $query, $sTime, $end ) = $info;
318  $trace .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
319  }
320  $this->logger->info( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
321  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
322  'trace' => $trace
323  ] );
324  }
325  unset( $this->dbTrxHoldingLocks[$name] );
326  unset( $this->dbTrxMethodTimes[$name] );
327  }
328 
334  protected function reportExpectationViolated( $expect, $query, $actual ) {
335  if ( $this->silenced ) {
336  return;
337  }
338 
339  $this->logger->info(
340  "Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n" .
341  ( new RuntimeException() )->getTraceAsString(),
342  [
343  'measure' => $expect,
344  'max' => $this->expect[$expect],
345  'by' => $this->expectBy[$expect],
346  'actual' => $actual,
347  'query' => $query
348  ]
349  );
350  }
351 }
Wikimedia\Rdbms\TransactionProfiler\$hits
array $hits
Definition: TransactionProfiler.php:52
Wikimedia\Rdbms\TransactionProfiler\$dbLockThreshold
float $dbLockThreshold
Seconds.
Definition: TransactionProfiler.php:40
Wikimedia\Rdbms\TransactionProfiler\$expectBy
array $expectBy
Definition: TransactionProfiler.php:69
Wikimedia\Rdbms\TransactionProfiler\setLogger
setLogger(LoggerInterface $logger)
Definition: TransactionProfiler.php:80
Wikimedia\Rdbms\TransactionProfiler\$eventThreshold
float $eventThreshold
Seconds.
Definition: TransactionProfiler.php:42
Wikimedia\Rdbms\TransactionProfiler\recordConnection
recordConnection( $server, $db, $isMaster)
Mark a DB as having been connected to with a new handle.
Definition: TransactionProfiler.php:156
use
as see the revision history and available at free of to any person obtaining a copy of this software and associated documentation to deal in the Software without including without limitation the rights to use
Definition: MIT-LICENSE.txt:10
Wikimedia\Rdbms
Definition: ChronologyProtector.php:24
$fname
if(!defined( 'MEDIAWIKI')) $fname
This file is not a valid entry point, perform no further processing unless MEDIAWIKI is defined.
Definition: Setup.php:36
Wikimedia\Rdbms\TransactionProfiler\$expect
array $expect
Definition: TransactionProfiler.php:59
$name
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:302
Wikimedia\Rdbms\TransactionProfiler\$dbTrxHoldingLocks
array $dbTrxHoldingLocks
transaction ID => (write start time, list of DBs involved)
Definition: TransactionProfiler.php:47
php
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
Wikimedia\Rdbms\TransactionProfiler\$silenced
bool $silenced
Definition: TransactionProfiler.php:44
$query
null for the 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:1581
Wikimedia\Rdbms\TransactionProfiler\$dbTrxMethodTimes
array $dbTrxMethodTimes
transaction ID => list of (query name, start time, end time)
Definition: TransactionProfiler.php:49
list
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
$value
$value
Definition: styleTest.css.php:45
Wikimedia\Rdbms\TransactionProfiler\$logger
LoggerInterface $logger
Definition: TransactionProfiler.php:74
Wikimedia\Rdbms\TransactionProfiler\__construct
__construct()
Definition: TransactionProfiler.php:76
Wikimedia\Rdbms\TransactionProfiler\transactionWritingIn
transactionWritingIn( $server, $db, $id)
Mark a DB as in a transaction with one or more writes pending.
Definition: TransactionProfiler.php:177
Wikimedia\Rdbms\TransactionProfiler\setExpectations
setExpectations(array $expects, $fname)
Set multiple performance expectations.
Definition: TransactionProfiler.php:124
Wikimedia\Rdbms\TransactionProfiler\transactionWritingOut
transactionWritingOut( $server, $db, $id, $writeTime=0.0, $affected=0)
Mark a DB as no longer in a transaction.
Definition: TransactionProfiler.php:271
Wikimedia\Rdbms\TransactionProfiler\recordQueryCompletion
recordQueryCompletion( $query, $sTime, $isWrite=false, $n=0)
Register the name and time of a method for slow DB trx detection.
Definition: TransactionProfiler.php:204
as
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
Wikimedia\Rdbms\TransactionProfiler\setSilenced
setSilenced( $value)
Definition: TransactionProfiler.php:89
Wikimedia\Rdbms\TransactionProfiler\resetExpectations
resetExpectations()
Reset performance expectations and hit counters.
Definition: TransactionProfiler.php:135
Wikimedia\Rdbms\TransactionProfiler\reportExpectationViolated
reportExpectationViolated( $expect, $query, $actual)
Definition: TransactionProfiler.php:334
Wikimedia\Rdbms\TransactionProfiler
Helper class that detects high-contention DB queries via profiling calls.
Definition: TransactionProfiler.php:38
Wikimedia\Rdbms\TransactionProfiler\setExpectation
setExpectation( $event, $value, $fname)
Set performance expectations.
Definition: TransactionProfiler.php:106
array
the array() calling protocol came about after MediaWiki 1.4rc1.