Code Coverage |
||||||||||
Lines |
Functions and Methods |
Classes and Traits |
||||||||
| Total | |
82.47% |
160 / 194 |
|
50.00% |
11 / 22 |
CRAP | |
0.00% |
0 / 1 |
| TransactionProfiler | |
82.47% |
160 / 194 |
|
50.00% |
11 / 22 |
118.20 | |
0.00% |
0 / 1 |
| __construct | |
100.00% |
6 / 6 |
|
100.00% |
1 / 1 |
1 | |||
| setLogger | |
100.00% |
1 / 1 |
|
100.00% |
1 / 1 |
1 | |||
| setStatsFactory | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| setRequestMethod | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| silenceForScope | |
100.00% |
12 / 12 |
|
100.00% |
1 / 1 |
6 | |||
| isSilenced | |
80.00% |
4 / 5 |
|
0.00% |
0 / 1 |
3.07 | |||
| setExpectation | |
85.71% |
6 / 7 |
|
0.00% |
0 / 1 |
3.03 | |||
| setExpectations | |
100.00% |
2 / 2 |
|
100.00% |
1 / 1 |
2 | |||
| resetExpectations | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| redefineExpectations | |
0.00% |
0 / 2 |
|
0.00% |
0 / 1 |
2 | |||
| getExpectation | |
100.00% |
3 / 3 |
|
100.00% |
1 / 1 |
2 | |||
| recordConnection | |
100.00% |
12 / 12 |
|
100.00% |
1 / 1 |
4 | |||
| transactionWritingIn | |
90.00% |
9 / 10 |
|
0.00% |
0 / 1 |
3.01 | |||
| recordQueryCompletion | |
77.78% |
28 / 36 |
|
0.00% |
0 / 1 |
27.31 | |||
| transactionWritingOut | |
71.43% |
30 / 42 |
|
0.00% |
0 / 1 |
12.33 | |||
| initPlaceholderExpectations | |
100.00% |
7 / 7 |
|
100.00% |
1 / 1 |
1 | |||
| isAboveThreshold | |
100.00% |
3 / 3 |
|
100.00% |
1 / 1 |
2 | |||
| pingAndCheckThreshold | |
100.00% |
5 / 5 |
|
100.00% |
1 / 1 |
2 | |||
| pingAndCheckThresholdFname | |
77.78% |
7 / 9 |
|
0.00% |
0 / 1 |
5.27 | |||
| reportExpectationViolated | |
85.19% |
23 / 27 |
|
0.00% |
0 / 1 |
4.05 | |||
| getGeneralizedSql | |
100.00% |
1 / 1 |
|
100.00% |
1 / 1 |
2 | |||
| getRawSql | |
100.00% |
1 / 1 |
|
100.00% |
1 / 1 |
2 | |||
| getCurrentTime | n/a |
0 / 0 |
n/a |
0 / 0 |
2 | |||||
| setMockTime | n/a |
0 / 0 |
n/a |
0 / 0 |
1 | |||||
| 1 | <?php |
| 2 | /** |
| 3 | * @license GPL-2.0-or-later |
| 4 | * @file |
| 5 | */ |
| 6 | namespace Wikimedia\Rdbms; |
| 7 | |
| 8 | use InvalidArgumentException; |
| 9 | use Psr\Log\LoggerAwareInterface; |
| 10 | use Psr\Log\LoggerInterface; |
| 11 | use Psr\Log\NullLogger; |
| 12 | use RuntimeException; |
| 13 | use Wikimedia\ScopedCallback; |
| 14 | use Wikimedia\Stats\StatsFactory; |
| 15 | |
| 16 | /** |
| 17 | * Detect high-contention DB queries via profiling calls. |
| 18 | * |
| 19 | * This class is meant to work with an IDatabase object, which manages queries. |
| 20 | * |
| 21 | * @internal For use by Database only |
| 22 | * @since 1.24 |
| 23 | * @ingroup Profiler |
| 24 | * @ingroup Database |
| 25 | */ |
| 26 | class TransactionProfiler implements LoggerAwareInterface { |
| 27 | /** @var LoggerInterface */ |
| 28 | private $logger; |
| 29 | /** @var StatsFactory */ |
| 30 | private $statsFactory; |
| 31 | /** @var array<string,array> Map of (event name => map of FLD_* class constants) */ |
| 32 | private $expect; |
| 33 | /** @var array<string,int> Map of (event name => current hits) */ |
| 34 | private $hits; |
| 35 | /** @var array<string,array<string,int>> Map of (event name => fName => current hits) */ |
| 36 | private $hitsFName; |
| 37 | /** @var array<string,int> Map of (event name => violation counter) */ |
| 38 | private $violations; |
| 39 | /** @var array<string,int> Map of (event name => silence counter) */ |
| 40 | private $silenced; |
| 41 | |
| 42 | /** |
| 43 | * @var array<string,array> Map of (trx ID => (write start time, list of DBs involved)) |
| 44 | * @phan-var array<string,array{start:float,conns:array<string,int>}> |
| 45 | */ |
| 46 | private $dbTrxHoldingLocks; |
| 47 | |
| 48 | /** |
| 49 | * @var array[][] Map of (trx ID => list of (query name, start time, end time)) |
| 50 | * @phan-var array<string,array<int,array{0:string|GeneralizedSQL,1:float,2:float}>> |
| 51 | */ |
| 52 | private $dbTrxMethodTimes; |
| 53 | |
| 54 | /** @var string|null HTTP request method; null for CLI mode */ |
| 55 | private $method; |
| 56 | |
| 57 | /** @var float|null */ |
| 58 | private $wallClockOverride; |
| 59 | |
| 60 | /** Treat locks as long-running if they last longer than this many seconds */ |
| 61 | private const DB_LOCK_THRESHOLD_SEC = 3.0; |
| 62 | /** Include events in any violation logs if they last longer than this many seconds */ |
| 63 | private const EVENT_THRESHOLD_SEC = 0.25; |
| 64 | |
| 65 | /** List of event names */ |
| 66 | private const EVENT_NAMES = [ |
| 67 | 'writes', |
| 68 | 'queries', |
| 69 | 'queriesPerCaller', |
| 70 | 'conns', |
| 71 | 'masterConns', |
| 72 | 'maxAffected', |
| 73 | 'readQueryRows', |
| 74 | 'readQueryTime', |
| 75 | 'writeQueryTime' |
| 76 | ]; |
| 77 | |
| 78 | /** List of event names with hit counters */ |
| 79 | private const COUNTER_EVENT_NAMES = [ |
| 80 | 'writes', |
| 81 | 'queries', |
| 82 | 'conns', |
| 83 | 'masterConns' |
| 84 | ]; |
| 85 | |
| 86 | /** Key to max expected value */ |
| 87 | private const FLD_LIMIT = 0; |
| 88 | /** Key to the function that set the max expected value */ |
| 89 | private const FLD_FNAME = 1; |
| 90 | |
| 91 | /** Any type of expectation */ |
| 92 | public const EXPECTATION_ANY = 'any'; |
| 93 | /** Any expectations about replica usage never occurring */ |
| 94 | public const EXPECTATION_REPLICAS_ONLY = 'replicas-only'; |
| 95 | |
| 96 | public function __construct() { |
| 97 | $this->initPlaceholderExpectations(); |
| 98 | |
| 99 | $this->dbTrxHoldingLocks = []; |
| 100 | $this->dbTrxMethodTimes = []; |
| 101 | |
| 102 | $this->silenced = array_fill_keys( self::EVENT_NAMES, 0 ); |
| 103 | |
| 104 | $this->setLogger( new NullLogger() ); |
| 105 | $this->statsFactory = StatsFactory::newNull(); |
| 106 | } |
| 107 | |
| 108 | public function setLogger( LoggerInterface $logger ): void { |
| 109 | $this->logger = $logger; |
| 110 | } |
| 111 | |
| 112 | /** |
| 113 | * Set statsFactory |
| 114 | * |
| 115 | * @param StatsFactory $statsFactory |
| 116 | * @return void |
| 117 | */ |
| 118 | public function setStatsFactory( StatsFactory $statsFactory ) { |
| 119 | $this->statsFactory = $statsFactory; |
| 120 | } |
| 121 | |
| 122 | /** |
| 123 | * @param ?string $method HTTP method; null for CLI mode |
| 124 | * @return void |
| 125 | */ |
| 126 | public function setRequestMethod( ?string $method ) { |
| 127 | $this->method = $method; |
| 128 | } |
| 129 | |
| 130 | /** |
| 131 | * Temporarily ignore expectations until the returned object goes out of scope |
| 132 | * |
| 133 | * During this time, violation of expectations will not be logged and counters |
| 134 | * for expectations (e.g. "conns") will not be incremented. |
| 135 | * |
| 136 | * This will suppress warnings about event counters which have a limit of zero. |
| 137 | * The main use case is too avoid warnings about primary connections/writes and |
| 138 | * warnings about getting any primary/replica connections at all. |
| 139 | * |
| 140 | * @param string $type Class EXPECTATION_* constant [default: TransactionProfiler::EXPECTATION_ANY] |
| 141 | */ |
| 142 | #[\NoDiscard] |
| 143 | public function silenceForScope( string $type = self::EXPECTATION_ANY ): ScopedCallback { |
| 144 | if ( $type === self::EXPECTATION_REPLICAS_ONLY ) { |
| 145 | $events = []; |
| 146 | foreach ( [ 'writes', 'masterConns' ] as $event ) { |
| 147 | if ( $this->expect[$event][self::FLD_LIMIT] === 0 ) { |
| 148 | $events[] = $event; |
| 149 | } |
| 150 | } |
| 151 | } else { |
| 152 | $events = self::EVENT_NAMES; |
| 153 | } |
| 154 | |
| 155 | foreach ( $events as $event ) { |
| 156 | ++$this->silenced[$event]; |
| 157 | } |
| 158 | |
| 159 | return new ScopedCallback( function () use ( $events ) { |
| 160 | foreach ( $events as $event ) { |
| 161 | --$this->silenced[$event]; |
| 162 | } |
| 163 | } ); |
| 164 | } |
| 165 | |
| 166 | /** |
| 167 | * Check whether an event currently has its expectations silenced. |
| 168 | * |
| 169 | * This method lets PHPUnit tests observe whether {@link self::silenceForScope} |
| 170 | * was called by the subject under test, and that it is still in-scope. |
| 171 | * |
| 172 | * This returns true if {@link self::silenceForScope} was called, |
| 173 | * the returned {@link ScopedCallback} has not gone out of scope, and |
| 174 | * the expectation was zero (for {@link self::EXPECTATION_REPLICAS_ONLY}. |
| 175 | * |
| 176 | * @internal For use in PHPUnit tests |
| 177 | * @param string $event Event name, as defined in {@see self::EVENT_NAMES} |
| 178 | * @return bool Whether the given event is currently ignoring expectations. |
| 179 | * @throws InvalidArgumentException If the event name is not one in {@see self::EVENT_NAMES} |
| 180 | */ |
| 181 | public function isSilenced( string $event ): bool { |
| 182 | if ( !defined( 'MW_PHPUNIT_TEST' ) ) { |
| 183 | throw new RuntimeException( 'May only be called in tests' ); |
| 184 | } |
| 185 | if ( !isset( $this->silenced[$event] ) ) { |
| 186 | throw new InvalidArgumentException( "Unrecognised event name '$event' provided." ); |
| 187 | } |
| 188 | |
| 189 | return $this->silenced[$event] > 0; |
| 190 | } |
| 191 | |
| 192 | /** |
| 193 | * Set performance expectations |
| 194 | * |
| 195 | * With conflicting expectations, the most narrow ones will be used |
| 196 | * |
| 197 | * @param string $event Event name, {@see self::EVENT_NAMES} |
| 198 | * @param float|int $limit Maximum event count, event value, or total event value |
| 199 | * @param string $fname Caller |
| 200 | * @since 1.25 |
| 201 | */ |
| 202 | public function setExpectation( string $event, $limit, string $fname ) { |
| 203 | if ( !isset( $this->expect[$event] ) ) { |
| 204 | return; // obsolete/bogus expectation |
| 205 | } |
| 206 | |
| 207 | if ( $limit <= $this->expect[$event][self::FLD_LIMIT] ) { |
| 208 | // New limit is more restrictive |
| 209 | $this->expect[$event] = [ |
| 210 | self::FLD_LIMIT => $limit, |
| 211 | self::FLD_FNAME => $fname |
| 212 | ]; |
| 213 | } |
| 214 | } |
| 215 | |
| 216 | /** |
| 217 | * Set one or multiple performance expectations |
| 218 | * |
| 219 | * With conflicting expectations, the most narrow ones will be used |
| 220 | * |
| 221 | * Use this to initialize expectations or make them stricter mid-request |
| 222 | * |
| 223 | * @param array $expects Map of (event name => limit), {@see self::EVENT_NAMES} |
| 224 | * @param string $fname |
| 225 | * @since 1.26 |
| 226 | */ |
| 227 | public function setExpectations( array $expects, string $fname ) { |
| 228 | foreach ( $expects as $event => $value ) { |
| 229 | $this->setExpectation( $event, $value, $fname ); |
| 230 | } |
| 231 | } |
| 232 | |
| 233 | /** |
| 234 | * Reset all performance expectations and hit counters |
| 235 | * |
| 236 | * Use this for unit testing or before applying a totally different set of expectations |
| 237 | * for a different part of the request, such as during "post-send" (execution after HTTP |
| 238 | * response completion) |
| 239 | * |
| 240 | * @since 1.25 |
| 241 | */ |
| 242 | public function resetExpectations() { |
| 243 | $this->initPlaceholderExpectations(); |
| 244 | } |
| 245 | |
| 246 | /** |
| 247 | * Clear all expectations and hit counters and set new performance expectations |
| 248 | * |
| 249 | * Use this to apply a totally different set of expectations for a different part |
| 250 | * of the request, such as during "post-send" (execution after HTTP response completion) |
| 251 | * |
| 252 | * @param array $expects Map of (event name => limit), {@see self::EVENT_NAMES} |
| 253 | * @param string $fname |
| 254 | * @since 1.33 |
| 255 | */ |
| 256 | public function redefineExpectations( array $expects, string $fname ) { |
| 257 | $this->initPlaceholderExpectations(); |
| 258 | $this->setExpectations( $expects, $fname ); |
| 259 | } |
| 260 | |
| 261 | /** |
| 262 | * Get the expectation associated with a specific event name. |
| 263 | * |
| 264 | * This will return the value of the expectation even if the event is silenced. |
| 265 | * |
| 266 | * Use this to check if a specific event is allowed before performing it, such as checking |
| 267 | * if the request will allow writes before performing them and instead deferring the writes |
| 268 | * to outside the request. |
| 269 | * |
| 270 | * @since 1.44 |
| 271 | * @param string $event Event name. Valid event names are defined in {@see self::EVENT_NAMES} |
| 272 | * @return float|int Maximum event count, event value, or total event value |
| 273 | * depending on the type of event. |
| 274 | * @throws InvalidArgumentException If the provided event name is not one in {@see self::EVENT_NAMES} |
| 275 | */ |
| 276 | public function getExpectation( string $event ) { |
| 277 | if ( !isset( $this->expect[$event] ) ) { |
| 278 | throw new InvalidArgumentException( "Unrecognised event name '$event' provided." ); |
| 279 | } |
| 280 | |
| 281 | return $this->expect[$event][self::FLD_LIMIT]; |
| 282 | } |
| 283 | |
| 284 | /** |
| 285 | * Mark a DB as having been connected to with a new handle |
| 286 | * |
| 287 | * Note that there can be multiple connections to a single DB. |
| 288 | * |
| 289 | * @param string $server DB server |
| 290 | * @param string|null $db DB name |
| 291 | * @param bool $isPrimaryWithReplicas If the server is the primary and there are replicas |
| 292 | */ |
| 293 | public function recordConnection( $server, $db, bool $isPrimaryWithReplicas ) { |
| 294 | // Report when too many connections happen... |
| 295 | if ( $this->pingAndCheckThreshold( 'conns' ) ) { |
| 296 | $this->reportExpectationViolated( |
| 297 | 'conns', |
| 298 | "[connect to $server ($db)]", |
| 299 | $this->hits['conns'] |
| 300 | ); |
| 301 | } |
| 302 | |
| 303 | // Report when too many primary connections happen... |
| 304 | if ( $isPrimaryWithReplicas && $this->pingAndCheckThreshold( 'masterConns' ) ) { |
| 305 | $this->reportExpectationViolated( |
| 306 | 'masterConns', |
| 307 | "[connect to $server ($db)]", |
| 308 | $this->hits['masterConns'] |
| 309 | ); |
| 310 | } |
| 311 | } |
| 312 | |
| 313 | /** |
| 314 | * Mark a DB as in a transaction with one or more writes pending |
| 315 | * |
| 316 | * Note that there can be multiple connections to a single DB. |
| 317 | * |
| 318 | * @param string $server DB server |
| 319 | * @param string|null $db DB name |
| 320 | * @param string $id ID string of transaction |
| 321 | * @param float $startTime UNIX timestamp |
| 322 | */ |
| 323 | public function transactionWritingIn( $server, $db, string $id, float $startTime ) { |
| 324 | $name = "{$db} {$server} TRX#$id"; |
| 325 | if ( isset( $this->dbTrxHoldingLocks[$name] ) ) { |
| 326 | $this->logger->warning( "Nested transaction for '$name' - out of sync." ); |
| 327 | } |
| 328 | $this->dbTrxHoldingLocks[$name] = [ |
| 329 | 'start' => $startTime, |
| 330 | 'conns' => [], // all connections involved |
| 331 | ]; |
| 332 | $this->dbTrxMethodTimes[$name] = []; |
| 333 | |
| 334 | foreach ( $this->dbTrxHoldingLocks as $name => &$info ) { |
| 335 | // Track all DBs in transactions for this transaction |
| 336 | $info['conns'][$name] = 1; |
| 337 | } |
| 338 | } |
| 339 | |
| 340 | /** |
| 341 | * Register the name and time of a method for slow DB trx detection |
| 342 | * |
| 343 | * This assumes that all queries are synchronous (non-overlapping) |
| 344 | * |
| 345 | * @param string|GeneralizedSql $query Function name or generalized SQL |
| 346 | * @param float $sTime Starting UNIX wall time |
| 347 | * @param bool $isWrite Whether this is a write query |
| 348 | * @param int|null $rowCount Number of affected/read rows |
| 349 | * @param string $trxId Transaction id |
| 350 | * @param string|null $serverName db host name like db1234 |
| 351 | * @param string|null $fname Name of the calling function |
| 352 | */ |
| 353 | public function recordQueryCompletion( |
| 354 | $query, |
| 355 | float $sTime, |
| 356 | bool $isWrite, |
| 357 | ?int $rowCount, |
| 358 | string $trxId, |
| 359 | ?string $serverName = null, |
| 360 | ?string $fname = null, |
| 361 | ) { |
| 362 | $eTime = $this->getCurrentTime(); |
| 363 | $elapsed = ( $eTime - $sTime ); |
| 364 | |
| 365 | if ( $isWrite && $this->isAboveThreshold( $rowCount, 'maxAffected' ) ) { |
| 366 | $this->reportExpectationViolated( 'maxAffected', $query, $rowCount, $trxId, $serverName ); |
| 367 | } elseif ( !$isWrite && $this->isAboveThreshold( $rowCount, 'readQueryRows' ) ) { |
| 368 | $this->reportExpectationViolated( 'readQueryRows', $query, $rowCount, $trxId, $serverName ); |
| 369 | } |
| 370 | |
| 371 | // Report when too many writes/queries happen... |
| 372 | if ( $this->pingAndCheckThreshold( 'queries' ) ) { |
| 373 | $this->reportExpectationViolated( 'queries', $query, $this->hits['queries'], $trxId, $serverName ); |
| 374 | } |
| 375 | if ( $isWrite && $this->pingAndCheckThreshold( 'writes' ) ) { |
| 376 | $this->reportExpectationViolated( 'writes', $query, $this->hits['writes'], $trxId, $serverName ); |
| 377 | } |
| 378 | if ( $fname !== null && $this->pingAndCheckThresholdFname( 'queriesPerCaller', $fname ) ) { |
| 379 | $this->reportExpectationViolated( |
| 380 | 'queriesPerCaller', |
| 381 | $query, |
| 382 | $this->hitsFName['queriesPerCaller'][$fname] . ' by ' . $fname, |
| 383 | $trxId, |
| 384 | $serverName, |
| 385 | ); |
| 386 | } |
| 387 | // Report slow queries... |
| 388 | if ( !$isWrite && $this->isAboveThreshold( $elapsed, 'readQueryTime' ) ) { |
| 389 | $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed, $trxId, $serverName ); |
| 390 | } |
| 391 | if ( $isWrite && $this->isAboveThreshold( $elapsed, 'writeQueryTime' ) ) { |
| 392 | $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed, $trxId, $serverName ); |
| 393 | } |
| 394 | |
| 395 | if ( !$this->dbTrxHoldingLocks ) { |
| 396 | // Short-circuit |
| 397 | return; |
| 398 | } elseif ( !$isWrite && $elapsed < self::EVENT_THRESHOLD_SEC ) { |
| 399 | // Not an important query nor slow enough |
| 400 | return; |
| 401 | } |
| 402 | |
| 403 | foreach ( $this->dbTrxHoldingLocks as $name => $info ) { |
| 404 | $lastQuery = end( $this->dbTrxMethodTimes[$name] ); |
| 405 | if ( $lastQuery ) { |
| 406 | // Additional query in the trx... |
| 407 | $lastEnd = $lastQuery[2]; |
| 408 | if ( $sTime >= $lastEnd ) { |
| 409 | if ( ( $sTime - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) { |
| 410 | // Add an entry representing the time spent doing non-queries |
| 411 | $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ]; |
| 412 | } |
| 413 | $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ]; |
| 414 | } |
| 415 | } else { |
| 416 | // First query in the trx... |
| 417 | if ( $sTime >= $info['start'] ) { |
| 418 | $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ]; |
| 419 | } |
| 420 | } |
| 421 | } |
| 422 | } |
| 423 | |
| 424 | /** |
| 425 | * Mark a DB as no longer in a transaction |
| 426 | * |
| 427 | * This will check if locks are possibly held for longer than |
| 428 | * needed and log any affected transactions to a special DB log. |
| 429 | * Note that there can be multiple connections to a single DB. |
| 430 | * |
| 431 | * @param string $server DB server |
| 432 | * @param string|null $db DB name |
| 433 | * @param string $id ID string of transaction |
| 434 | * @param float $writeTime Time spent in write queries |
| 435 | * @param int $affected Number of rows affected by writes |
| 436 | */ |
| 437 | public function transactionWritingOut( |
| 438 | $server, |
| 439 | $db, |
| 440 | string $id, |
| 441 | float $writeTime, |
| 442 | int $affected |
| 443 | ) { |
| 444 | // Must match $name in transactionWritingIn() |
| 445 | $name = "{$db} {$server} TRX#$id"; |
| 446 | if ( !isset( $this->dbTrxMethodTimes[$name] ) ) { |
| 447 | $this->logger->warning( "Detected no transaction for '$name' - out of sync." ); |
| 448 | return; |
| 449 | } |
| 450 | |
| 451 | $slow = false; |
| 452 | |
| 453 | // Warn if too much time was spend writing... |
| 454 | if ( $this->isAboveThreshold( $writeTime, 'writeQueryTime' ) ) { |
| 455 | $this->reportExpectationViolated( |
| 456 | 'writeQueryTime', |
| 457 | "[transaction writes to {$db} at {$server}]", |
| 458 | $writeTime, |
| 459 | $id |
| 460 | ); |
| 461 | $slow = true; |
| 462 | } |
| 463 | // Warn if too many rows were changed... |
| 464 | if ( $this->isAboveThreshold( $affected, 'maxAffected' ) ) { |
| 465 | $this->reportExpectationViolated( |
| 466 | 'maxAffected', |
| 467 | "[transaction writes to {$db} at {$server}]", |
| 468 | $affected, |
| 469 | $id |
| 470 | ); |
| 471 | } |
| 472 | // Fill in the last non-query period... |
| 473 | $lastQuery = end( $this->dbTrxMethodTimes[$name] ); |
| 474 | if ( $lastQuery ) { |
| 475 | $now = $this->getCurrentTime(); |
| 476 | $lastEnd = $lastQuery[2]; |
| 477 | if ( ( $now - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) { |
| 478 | $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ]; |
| 479 | } |
| 480 | } |
| 481 | // Check for any slow queries or non-query periods... |
| 482 | foreach ( $this->dbTrxMethodTimes[$name] as $info ) { |
| 483 | $elapsed = ( $info[2] - $info[1] ); |
| 484 | if ( $elapsed >= self::DB_LOCK_THRESHOLD_SEC ) { |
| 485 | $slow = true; |
| 486 | break; |
| 487 | } |
| 488 | } |
| 489 | if ( $slow ) { |
| 490 | $trace = ''; |
| 491 | foreach ( $this->dbTrxMethodTimes[$name] as $i => [ $query, $sTime, $end ] ) { |
| 492 | $trace .= sprintf( |
| 493 | "%-2d %.3fs %s\n", $i, ( $end - $sTime ), $this->getGeneralizedSql( $query ) ); |
| 494 | } |
| 495 | $this->logger->warning( "Suboptimal transaction [{dbs}]:\n{trace}", [ |
| 496 | 'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ), |
| 497 | 'trace' => mb_substr( $trace, 0, 2000 ) |
| 498 | ] ); |
| 499 | } |
| 500 | unset( $this->dbTrxHoldingLocks[$name] ); |
| 501 | unset( $this->dbTrxMethodTimes[$name] ); |
| 502 | } |
| 503 | |
| 504 | private function initPlaceholderExpectations() { |
| 505 | $this->expect = array_fill_keys( |
| 506 | self::EVENT_NAMES, |
| 507 | [ self::FLD_LIMIT => INF, self::FLD_FNAME => null ] |
| 508 | ); |
| 509 | |
| 510 | $this->hits = array_fill_keys( self::COUNTER_EVENT_NAMES, 0 ); |
| 511 | $this->hitsFName = []; |
| 512 | $this->violations = array_fill_keys( self::EVENT_NAMES, 0 ); |
| 513 | } |
| 514 | |
| 515 | /** |
| 516 | * @param float|int $value |
| 517 | * @param string $event |
| 518 | * @return bool |
| 519 | */ |
| 520 | private function isAboveThreshold( $value, string $event ) { |
| 521 | if ( $this->silenced[$event] > 0 ) { |
| 522 | return false; |
| 523 | } |
| 524 | |
| 525 | return ( $value > $this->expect[$event][self::FLD_LIMIT] ); |
| 526 | } |
| 527 | |
| 528 | /** |
| 529 | * @param string $event |
| 530 | * @return bool |
| 531 | */ |
| 532 | private function pingAndCheckThreshold( string $event ) { |
| 533 | if ( $this->silenced[$event] > 0 ) { |
| 534 | return false; |
| 535 | } |
| 536 | |
| 537 | $newValue = ++$this->hits[$event]; |
| 538 | $limit = $this->expect[$event][self::FLD_LIMIT]; |
| 539 | |
| 540 | return ( $newValue > $limit ); |
| 541 | } |
| 542 | |
| 543 | private function pingAndCheckThresholdFname( string $event, string $fname ): bool { |
| 544 | if ( $this->silenced[$event] > 0 || str_starts_with( $fname, 'Wikimedia\\Rdbms\\' ) ) { |
| 545 | return false; |
| 546 | } |
| 547 | $limit = $this->expect[$event][self::FLD_LIMIT]; |
| 548 | if ( $limit === INF ) { |
| 549 | // expectation disabled, skip collecting function names |
| 550 | return false; |
| 551 | } |
| 552 | if ( !isset( $this->hitsFName[$event][$fname] ) ) { |
| 553 | $this->hitsFName[$event][$fname] = 0; |
| 554 | } |
| 555 | |
| 556 | $newValue = ++$this->hitsFName[$event][$fname]; |
| 557 | |
| 558 | return $newValue > $limit; |
| 559 | } |
| 560 | |
| 561 | /** |
| 562 | * @param string $event |
| 563 | * @param string|GeneralizedSql $query |
| 564 | * @param float|int|string $actual |
| 565 | * @param string|null $trxId Transaction id |
| 566 | * @param string|null $serverName db host name like db1234 |
| 567 | */ |
| 568 | private function reportExpectationViolated( |
| 569 | $event, |
| 570 | $query, |
| 571 | $actual, |
| 572 | ?string $trxId = null, |
| 573 | ?string $serverName = null |
| 574 | ) { |
| 575 | $violations = ++$this->violations[$event]; |
| 576 | // First violation; check if this is a web request |
| 577 | if ( $violations === 1 && $this->method !== null ) { |
| 578 | $this->statsFactory->getCounter( 'rdbms_trxprofiler_warnings_total' ) |
| 579 | ->setLabel( 'event', $event ) |
| 580 | ->setLabel( 'method', $this->method ) |
| 581 | ->increment(); |
| 582 | } |
| 583 | |
| 584 | $max = $this->expect[$event][self::FLD_LIMIT]; |
| 585 | $by = $this->expect[$event][self::FLD_FNAME]; |
| 586 | |
| 587 | $message = "Expectation ($event <= $max) by $by not met (actual: {actualSeconds})"; |
| 588 | if ( $trxId ) { |
| 589 | $message .= ' in trx #{trxId}'; |
| 590 | } |
| 591 | $message .= ":\n{query}\n"; |
| 592 | |
| 593 | $this->logger->warning( |
| 594 | $message, |
| 595 | [ |
| 596 | 'db_log_category' => 'performance', |
| 597 | 'measure' => $event, |
| 598 | 'maxSeconds' => $max, |
| 599 | 'by' => $by, |
| 600 | 'actualSeconds' => $actual, |
| 601 | 'query' => $this->getGeneralizedSql( $query ), |
| 602 | 'exception' => new RuntimeException(), |
| 603 | 'trxId' => $trxId, |
| 604 | // Avoid truncated JSON in Logstash (T349140) |
| 605 | 'fullQuery' => mb_substr( $this->getRawSql( $query ), 0, 2000 ), |
| 606 | 'dbHost' => $serverName |
| 607 | ] |
| 608 | ); |
| 609 | } |
| 610 | |
| 611 | /** |
| 612 | * @param GeneralizedSql|string $query |
| 613 | * @return string |
| 614 | */ |
| 615 | private function getGeneralizedSql( $query ) { |
| 616 | return $query instanceof GeneralizedSql ? $query->stringify() : $query; |
| 617 | } |
| 618 | |
| 619 | /** |
| 620 | * @param GeneralizedSql|string $query |
| 621 | * @return string |
| 622 | */ |
| 623 | private function getRawSql( $query ) { |
| 624 | return $query instanceof GeneralizedSql ? $query->getRawSql() : $query; |
| 625 | } |
| 626 | |
| 627 | /** |
| 628 | * @return float UNIX timestamp |
| 629 | * @codeCoverageIgnore |
| 630 | */ |
| 631 | private function getCurrentTime() { |
| 632 | return $this->wallClockOverride ?: microtime( true ); |
| 633 | } |
| 634 | |
| 635 | /** |
| 636 | * @param float|null &$time Mock UNIX timestamp for testing |
| 637 | * @codeCoverageIgnore |
| 638 | */ |
| 639 | public function setMockTime( &$time ) { |
| 640 | $this->wallClockOverride =& $time; |
| 641 | } |
| 642 | } |