MediaWiki REL1_34
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 '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}
Lazy-loaded wrapper for simplification and scrubbing of SQL queries for profiling.
Helper class that detects high-contention DB queries via profiling calls.
redefineExpectations(array $expects, $fname)
Clear all expectations and hit counters and set new performance expectations.
setExpectation( $event, $value, $fname)
Set performance expectations.
resetExpectations()
Reset all performance expectations and hit counters.
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.
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.