MediaWiki REL1_30
TransactionProfiler.php
Go to the documentation of this file.
1<?php
24namespace Wikimedia\Rdbms;
25
26use Psr\Log\LoggerInterface;
27use Psr\Log\LoggerAwareInterface;
28use Psr\Log\NullLogger;
29use RuntimeException;
30
38class 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}
if(!defined( 'MEDIAWIKI')) $fname
This file is not a valid entry point, perform no further processing unless MEDIAWIKI is defined.
Definition Setup.php:36
Helper class that detects high-contention DB queries via profiling calls.
setExpectation( $event, $value, $fname)
Set performance expectations.
resetExpectations()
Reset performance expectations and hit counters.
setExpectations(array $expects, $fname)
Set multiple performance expectations.
transactionWritingIn( $server, $db, $id)
Mark a DB as in a transaction with one or more writes pending.
recordConnection( $server, $db, $isMaster)
Mark a DB as having been connected to with a new handle.
array $dbTrxMethodTimes
transaction ID => list of (query name, start time, end time)
reportExpectationViolated( $expect, $query, $actual)
array $dbTrxHoldingLocks
transaction ID => (write start time, list of DBs involved)
recordQueryCompletion( $query, $sTime, $isWrite=false, $n=0)
Register the name and time of a method for slow DB trx detection.
transactionWritingOut( $server, $db, $id, $writeTime=0.0, $affected=0)
Mark a DB as no longer in a transaction.
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
Allows to change the fields on the form that will be generated $name
Definition hooks.txt:302
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:1610