MediaWiki  1.28.0
TransactionProfiler.php
Go to the documentation of this file.
1 <?php
28 
36 class TransactionProfiler implements LoggerAwareInterface {
38  protected $dbLockThreshold = 3.0;
40  protected $eventThreshold = .25;
42  protected $silenced = false;
43 
45  protected $dbTrxHoldingLocks = [];
47  protected $dbTrxMethodTimes = [];
48 
50  protected $hits = [
51  'writes' => 0,
52  'queries' => 0,
53  'conns' => 0,
54  'masterConns' => 0
55  ];
57  protected $expect = [
58  'writes' => INF,
59  'queries' => INF,
60  'conns' => INF,
61  'masterConns' => INF,
62  'maxAffected' => INF,
63  'readQueryTime' => INF,
64  'writeQueryTime' => INF
65  ];
67  protected $expectBy = [];
68 
72  private $logger;
73 
74  public function __construct() {
75  $this->setLogger( new NullLogger() );
76  }
77 
78  public function setLogger( LoggerInterface $logger ) {
79  $this->logger = $logger;
80  }
81 
87  public function setSilenced( $value ) {
88  $old = $this->silenced;
89  $this->silenced = $value;
90 
91  return $old;
92  }
93 
104  public function setExpectation( $event, $value, $fname ) {
105  $this->expect[$event] = isset( $this->expect[$event] )
106  ? min( $this->expect[$event], $value )
107  : $value;
108  if ( $this->expect[$event] == $value ) {
109  $this->expectBy[$event] = $fname;
110  }
111  }
112 
122  public function setExpectations( array $expects, $fname ) {
123  foreach ( $expects as $event => $value ) {
124  $this->setExpectation( $event, $value, $fname );
125  }
126  }
127 
133  public function resetExpectations() {
134  foreach ( $this->hits as &$val ) {
135  $val = 0;
136  }
137  unset( $val );
138  foreach ( $this->expect as &$val ) {
139  $val = INF;
140  }
141  unset( $val );
142  $this->expectBy = [];
143  }
144 
154  public function recordConnection( $server, $db, $isMaster ) {
155  // Report when too many connections happen...
156  if ( $this->hits['conns']++ == $this->expect['conns'] ) {
157  $this->reportExpectationViolated( 'conns', "[connect to $server ($db)]" );
158  }
159  if ( $isMaster && $this->hits['masterConns']++ == $this->expect['masterConns'] ) {
160  $this->reportExpectationViolated( 'masterConns', "[connect to $server ($db)]" );
161  }
162  }
163 
173  public function transactionWritingIn( $server, $db, $id ) {
174  $name = "{$server} ({$db}) (TRX#$id)";
175  if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
176  $this->logger->info( "Nested transaction for '$name' - out of sync." );
177  }
178  $this->dbTrxHoldingLocks[$name] = [
179  'start' => microtime( true ),
180  'conns' => [], // all connections involved
181  ];
182  $this->dbTrxMethodTimes[$name] = [];
183 
184  foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
185  // Track all DBs in transactions for this transaction
186  $info['conns'][$name] = 1;
187  }
188  }
189 
200  public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
201  $eTime = microtime( true );
202  $elapsed = ( $eTime - $sTime );
203 
204  if ( $isWrite && $n > $this->expect['maxAffected'] ) {
205  $this->logger->info(
206  "Query affected $n row(s):\n" . $query . "\n" .
207  ( new RuntimeException() )->getTraceAsString() );
208  }
209 
210  // Report when too many writes/queries happen...
211  if ( $this->hits['queries']++ == $this->expect['queries'] ) {
212  $this->reportExpectationViolated( 'queries', $query );
213  }
214  if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) {
215  $this->reportExpectationViolated( 'writes', $query );
216  }
217  // Report slow queries...
218  if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
219  $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
220  }
221  if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
222  $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
223  }
224 
225  if ( !$this->dbTrxHoldingLocks ) {
226  // Short-circuit
227  return;
228  } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
229  // Not an important query nor slow enough
230  return;
231  }
232 
233  foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
234  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
235  if ( $lastQuery ) {
236  // Additional query in the trx...
237  $lastEnd = $lastQuery[2];
238  if ( $sTime >= $lastEnd ) { // sanity check
239  if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
240  // Add an entry representing the time spent doing non-queries
241  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
242  }
243  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
244  }
245  } else {
246  // First query in the trx...
247  if ( $sTime >= $info['start'] ) { // sanity check
248  $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
249  }
250  }
251  }
252  }
253 
266  public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0 ) {
267  $name = "{$server} ({$db}) (TRX#$id)";
268  if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
269  $this->logger->info( "Detected no transaction for '$name' - out of sync." );
270  return;
271  }
272 
273  $slow = false;
274 
275  // Warn if too much time was spend writing...
276  if ( $writeTime > $this->expect['writeQueryTime'] ) {
278  'writeQueryTime',
279  "[transaction $id writes to {$server} ({$db})]",
280  $writeTime
281  );
282  $slow = true;
283  }
284  // Fill in the last non-query period...
285  $lastQuery = end( $this->dbTrxMethodTimes[$name] );
286  if ( $lastQuery ) {
287  $now = microtime( true );
288  $lastEnd = $lastQuery[2];
289  if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
290  $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
291  }
292  }
293  // Check for any slow queries or non-query periods...
294  foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
295  $elapsed = ( $info[2] - $info[1] );
296  if ( $elapsed >= $this->dbLockThreshold ) {
297  $slow = true;
298  break;
299  }
300  }
301  if ( $slow ) {
302  $trace = '';
303  foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
304  list( $query, $sTime, $end ) = $info;
305  $trace .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
306  }
307  $this->logger->info( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
308  'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
309  'trace' => $trace
310  ] );
311  }
312  unset( $this->dbTrxHoldingLocks[$name] );
313  unset( $this->dbTrxMethodTimes[$name] );
314  }
315 
321  protected function reportExpectationViolated( $expect, $query, $actual = null ) {
322  if ( $this->silenced ) {
323  return;
324  }
325 
326  $n = $this->expect[$expect];
327  $by = $this->expectBy[$expect];
328  $actual = ( $actual !== null ) ? " (actual: $actual)" : "";
329 
330  $this->logger->info(
331  "Expectation ($expect <= $n) by $by not met$actual:\n$query\n" .
332  ( new RuntimeException() )->getTraceAsString()
333  );
334  }
335 }
array $dbTrxMethodTimes
transaction ID => list of (query name, start time, end time)
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
the array() calling protocol came about after MediaWiki 1.4rc1.
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:1555
float $dbLockThreshold
Seconds.
reportExpectationViolated($expect, $query, $actual=null)
Apache License January AND DISTRIBUTION Definitions License shall mean the terms and conditions for use
array $dbTrxHoldingLocks
transaction ID => (write start time, list of DBs involved)
float $eventThreshold
Seconds.
$value
array array array $expectBy
setExpectations(array $expects, $fname)
Set multiple performance expectations.
Helper class that detects high-contention DB queries via profiling calls.
resetExpectations()
Reset performance expectations and hit counters.
setExpectation($event, $value, $fname)
Set performance expectations.
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
setLogger(LoggerInterface $logger)
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
if(!defined( 'MEDIAWIKI')) $fname
This file is not a valid entry point, perform no further processing unless MEDIAWIKI is defined...
Definition: Setup.php:36
transactionWritingOut($server, $db, $id, $writeTime=0.0)
Mark a DB as no longer in a transaction.
recordConnection($server, $db, $isMaster)
Mark a DB as having been connected to with a new handle.
transactionWritingIn($server, $db, $id)
Mark a DB as in a transaction with one or more writes pending.
recordQueryCompletion($query, $sTime, $isWrite=false, $n=0)
Register the name and time of a method for slow DB trx detection.
Allows to change the fields on the form that will be generated $name
Definition: hooks.txt:300