MediaWiki  1.29.1
TransactionProfiler.php
Go to the documentation of this file.
1 <?php
25 namespace Wikimedia\Rdbms;
26 
27 use Psr\Log\LoggerInterface;
28 use Psr\Log\LoggerAwareInterface;
29 use Psr\Log\NullLogger;
30 use RuntimeException;
31 
39 class TransactionProfiler implements LoggerAwareInterface {
41  protected $dbLockThreshold = 3.0;
43  protected $eventThreshold = .25;
45  protected $silenced = false;
46 
48  protected $dbTrxHoldingLocks = [];
50  protected $dbTrxMethodTimes = [];
51 
53  protected $hits = [
54  'writes' => 0,
55  'queries' => 0,
56  'conns' => 0,
57  'masterConns' => 0
58  ];
60  protected $expect = [
61  'writes' => INF,
62  'queries' => INF,
63  'conns' => INF,
64  'masterConns' => INF,
65  'maxAffected' => 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 
125  public function setExpectations( array $expects, $fname ) {
126  foreach ( $expects as $event => $value ) {
127  $this->setExpectation( $event, $value, $fname );
128  }
129  }
130 
136  public function resetExpectations() {
137  foreach ( $this->hits as &$val ) {
138  $val = 0;
139  }
140  unset( $val );
141  foreach ( $this->expect as &$val ) {
142  $val = INF;
143  }
144  unset( $val );
145  $this->expectBy = [];
146  }
147 
157  public function recordConnection( $server, $db, $isMaster ) {
158  // Report when too many connections happen...
159  if ( $this->hits['conns']++ == $this->expect['conns'] ) {
160  $this->reportExpectationViolated( 'conns', "[connect to $server ($db)]" );
161  }
162  if ( $isMaster && $this->hits['masterConns']++ == $this->expect['masterConns'] ) {
163  $this->reportExpectationViolated( 'masterConns', "[connect to $server ($db)]" );
164  }
165  }
166 
176  public function transactionWritingIn( $server, $db, $id ) {
177  $name = "{$server} ({$db}) (TRX#$id)";
178  if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
179  $this->logger->info( "Nested transaction for '$name' - out of sync." );
180  }
181  $this->dbTrxHoldingLocks[$name] = [
182  'start' => microtime( true ),
183  'conns' => [], // all connections involved
184  ];
185  $this->dbTrxMethodTimes[$name] = [];
186 
187  foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
188  // Track all DBs in transactions for this transaction
189  $info['conns'][$name] = 1;
190  }
191  }
192 
203  public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
204  $eTime = microtime( true );
205  $elapsed = ( $eTime - $sTime );
206 
207  if ( $isWrite && $n > $this->expect['maxAffected'] ) {
208  $this->logger->info(
209  "Query affected $n row(s):\n" . $query . "\n" .
210  ( new RuntimeException() )->getTraceAsString() );
211  }
212 
213  // Report when too many writes/queries happen...
214  if ( $this->hits['queries']++ == $this->expect['queries'] ) {
215  $this->reportExpectationViolated( 'queries', $query );
216  }
217  if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) {
218  $this->reportExpectationViolated( 'writes', $query );
219  }
220  // Report slow queries...
221  if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
222  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
223  }
224  if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
225  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
226  }
227 
228  if ( !$this->dbTrxHoldingLocks ) {
229  // Short-circuit
230  return;
231  } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
232  // Not an important query nor slow enough
233  return;
234  }
235 
236  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
237  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
238  if ( $lastQuery ) {
239  // Additional query in the trx...
240  $lastEnd = $lastQuery[2];
241  if ( $sTime >= $lastEnd ) { // sanity check
242  if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
243  // Add an entry representing the time spent doing non-queries
244  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
245  }
246  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
247  }
248  } else {
249  // First query in the trx...
250  if ( $sTime >= $info['start'] ) { // sanity check
251  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
252  }
253  }
254  }
255  }
256 
269  public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0 ) {
270  $name = "{$server} ({$db}) (TRX#$id)";
271  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
272  $this->logger->info( "Detected no transaction for '$name' - out of sync." );
273  return;
274  }
275 
276  $slow = false;
277 
278  // Warn if too much time was spend writing...
279  if ( $writeTime > $this->expect['writeQueryTime'] ) {
281  'writeQueryTime',
282  "[transaction $id writes to {$server} ({$db})]",
283  $writeTime
284  );
285  $slow = true;
286  }
287  // Fill in the last non-query period...
288  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
289  if ( $lastQuery ) {
290  $now = microtime( true );
291  $lastEnd = $lastQuery[2];
292  if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
293  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
294  }
295  }
296  // Check for any slow queries or non-query periods...
297  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
298  $elapsed = ( $info[2] - $info[1] );
299  if ( $elapsed >= $this->dbLockThreshold ) {
300  $slow = true;
301  break;
302  }
303  }
304  if ( $slow ) {
305  $trace = '';
306  foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
307  list( $query, $sTime, $end ) = $info;
308  $trace .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
309  }
310  $this->logger->info( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
311  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
312  'trace' => $trace
313  ] );
314  }
315  unset( $this->dbTrxHoldingLocks[$name] );
316  unset( $this->dbTrxMethodTimes[$name] );
317  }
318 
324  protected function reportExpectationViolated( $expect, $query, $actual = null ) {
325  if ( $this->silenced ) {
326  return;
327  }
328 
329  $n = $this->expect[$expect];
330  $by = $this->expectBy[$expect];
331  $actual = ( $actual !== null ) ? " (actual: $actual)" : "";
332 
333  $this->logger->info(
334  "Expectation ($expect <= $n) by $by not met$actual:\n$query\n" .
335  ( new RuntimeException() )->getTraceAsString()
336  );
337  }
338 }
Wikimedia\Rdbms\TransactionProfiler\$hits
array $hits
Definition: TransactionProfiler.php:53
Wikimedia\Rdbms\TransactionProfiler\$dbLockThreshold
float $dbLockThreshold
Seconds.
Definition: TransactionProfiler.php:41
Wikimedia\Rdbms\TransactionProfiler\reportExpectationViolated
reportExpectationViolated( $expect, $query, $actual=null)
Definition: TransactionProfiler.php:324
Wikimedia\Rdbms\TransactionProfiler\$expectBy
array $expectBy
Definition: TransactionProfiler.php:70
Wikimedia\Rdbms\TransactionProfiler\setLogger
setLogger(LoggerInterface $logger)
Definition: TransactionProfiler.php:81
Wikimedia\Rdbms\TransactionProfiler\$eventThreshold
float $eventThreshold
Seconds.
Definition: TransactionProfiler.php:43
Wikimedia\Rdbms\TransactionProfiler\recordConnection
recordConnection( $server, $db, $isMaster)
Mark a DB as having been connected to with a new handle.
Definition: TransactionProfiler.php:157
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:60
$name
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:304
Wikimedia\Rdbms\TransactionProfiler\$dbTrxHoldingLocks
array $dbTrxHoldingLocks
transaction ID => (write start time, list of DBs involved)
Definition: TransactionProfiler.php:48
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:45
$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:1572
Wikimedia\Rdbms\TransactionProfiler\transactionWritingOut
transactionWritingOut( $server, $db, $id, $writeTime=0.0)
Mark a DB as no longer in a transaction.
Definition: TransactionProfiler.php:269
Wikimedia\Rdbms\TransactionProfiler\$dbTrxMethodTimes
array $dbTrxMethodTimes
transaction ID => list of (query name, start time, end time)
Definition: TransactionProfiler.php:50
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:75
Wikimedia\Rdbms\TransactionProfiler\__construct
__construct()
Definition: TransactionProfiler.php:77
Wikimedia\Rdbms\TransactionProfiler\transactionWritingIn
transactionWritingIn( $server, $db, $id)
Mark a DB as in a transaction with one or more writes pending.
Definition: TransactionProfiler.php:176
Wikimedia\Rdbms\TransactionProfiler\setExpectations
setExpectations(array $expects, $fname)
Set multiple performance expectations.
Definition: TransactionProfiler.php:125
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:203
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:90
Wikimedia\Rdbms\TransactionProfiler\resetExpectations
resetExpectations()
Reset performance expectations and hit counters.
Definition: TransactionProfiler.php:136
Wikimedia\Rdbms\TransactionProfiler
Helper class that detects high-contention DB queries via profiling calls.
Definition: TransactionProfiler.php:39
Wikimedia\Rdbms\TransactionProfiler\setExpectation
setExpectation( $event, $value, $fname)
Set performance expectations.
Definition: TransactionProfiler.php:107
array
the array() calling protocol came about after MediaWiki 1.4rc1.