22 use Liuggio\StatsdClient\Factory\StatsdDataFactoryInterface;
24 use Psr\Log\LoggerAwareInterface;
25 use Psr\Log\LoggerInterface;
26 use Psr\Log\NullLogger;
29 use Wikimedia\ScopedCallback;
59 private $dbTrxHoldingLocks;
65 private $dbTrxMethodTimes;
71 private $wallClockOverride;
74 private const DB_LOCK_THRESHOLD_SEC = 3.0;
76 private const EVENT_THRESHOLD_SEC = 0.25;
79 private const EVENT_NAMES = [
91 private const COUNTER_EVENT_NAMES = [
99 private const FLD_LIMIT = 0;
101 private const FLD_FNAME = 1;
109 $this->initPlaceholderExpectations();
111 $this->dbTrxHoldingLocks = [];
112 $this->dbTrxMethodTimes = [];
114 $this->silenced = array_fill_keys( self::EVENT_NAMES, 0 );
121 $this->logger = $logger;
125 $this->stats = $statsFactory;
133 $this->method = $method;
145 $delta = $value ? 1 : -1;
146 foreach ( self::EVENT_NAMES as $event ) {
147 $this->silenced[$event] += $delta;
167 if (
$type === self::EXPECTATION_REPLICAS_ONLY ) {
169 foreach ( [
'writes',
'masterConns' ] as $event ) {
170 if ( $this->expect[$event][self::FLD_LIMIT] === 0 ) {
175 $events = self::EVENT_NAMES;
178 foreach ( $events as $event ) {
179 ++$this->silenced[$event];
182 return new ScopedCallback(
function () use ( $events ) {
183 foreach ( $events as $event ) {
184 --$this->silenced[$event];
200 if ( !isset( $this->expect[$event] ) ) {
204 if ( $limit <= $this->expect[$event][self::FLD_LIMIT] ) {
206 $this->expect[$event] = [
207 self::FLD_LIMIT => $limit,
208 self::FLD_FNAME => $fname
225 foreach ( $expects as $event => $value ) {
240 $this->initPlaceholderExpectations();
254 $this->initPlaceholderExpectations();
269 if ( $this->pingAndCheckThreshold(
'conns' ) ) {
270 $this->reportExpectationViolated(
272 "[connect to $server ($db)]",
278 if ( $isPrimary && $this->pingAndCheckThreshold(
'masterConns' ) ) {
279 $this->reportExpectationViolated(
281 "[connect to $server ($db)]",
282 $this->hits[
'masterConns']
297 $name =
"{$db} {$server} TRX#$id";
298 if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
299 $this->logger->warning(
"Nested transaction for '$name' - out of sync." );
301 $this->dbTrxHoldingLocks[$name] = [
302 'start' => $this->getCurrentTime(),
305 $this->dbTrxMethodTimes[$name] = [];
307 foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
309 $info[
'conns'][$name] = 1;
331 ?
string $serverName =
null
333 $eTime = $this->getCurrentTime();
334 $elapsed = ( $eTime - $sTime );
336 if ( $isWrite && $this->isAboveThreshold( $rowCount,
'maxAffected' ) ) {
337 $this->reportExpectationViolated(
'maxAffected', $query, $rowCount, $trxId, $serverName );
338 } elseif ( !$isWrite && $this->isAboveThreshold( $rowCount,
'readQueryRows' ) ) {
339 $this->reportExpectationViolated(
'readQueryRows', $query, $rowCount, $trxId, $serverName );
343 if ( $this->pingAndCheckThreshold(
'queries' ) ) {
344 $this->reportExpectationViolated(
'queries', $query, $this->hits[
'queries'], $trxId, $serverName );
346 if ( $isWrite && $this->pingAndCheckThreshold(
'writes' ) ) {
347 $this->reportExpectationViolated(
'writes', $query, $this->hits[
'writes'], $trxId, $serverName );
350 if ( !$isWrite && $this->isAboveThreshold( $elapsed,
'readQueryTime' ) ) {
351 $this->reportExpectationViolated(
'readQueryTime', $query, $elapsed, $trxId, $serverName );
353 if ( $isWrite && $this->isAboveThreshold( $elapsed,
'writeQueryTime' ) ) {
354 $this->reportExpectationViolated(
'writeQueryTime', $query, $elapsed, $trxId, $serverName );
357 if ( !$this->dbTrxHoldingLocks ) {
360 } elseif ( !$isWrite && $elapsed < self::EVENT_THRESHOLD_SEC ) {
365 foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
366 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
369 $lastEnd = $lastQuery[2];
370 if ( $sTime >= $lastEnd ) {
371 if ( ( $sTime - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
373 $this->dbTrxMethodTimes[$name][] = [
'...delay...', $lastEnd, $sTime ];
375 $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
379 if ( $sTime >= $info[
'start'] ) {
380 $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
407 $name =
"{$db} {$server} TRX#$id";
408 if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
409 $this->logger->warning(
"Detected no transaction for '$name' - out of sync." );
416 if ( $this->isAboveThreshold( $writeTime,
'writeQueryTime' ) ) {
417 $this->reportExpectationViolated(
419 "[transaction writes to {$db} at {$server}]",
426 if ( $this->isAboveThreshold( $affected,
'maxAffected' ) ) {
427 $this->reportExpectationViolated(
429 "[transaction writes to {$db} at {$server}]",
435 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
437 $now = $this->getCurrentTime();
438 $lastEnd = $lastQuery[2];
439 if ( ( $now - $lastEnd ) > self::EVENT_THRESHOLD_SEC ) {
440 $this->dbTrxMethodTimes[$name][] = [
'...delay...', $lastEnd, $now ];
444 foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
445 $elapsed = ( $info[2] - $info[1] );
446 if ( $elapsed >= self::DB_LOCK_THRESHOLD_SEC ) {
453 foreach ( $this->dbTrxMethodTimes[$name] as $i => [ $query, $sTime, $end ] ) {
455 "%-2d %.3fs %s\n", $i, ( $end - $sTime ), $this->getGeneralizedSql( $query ) );
457 $this->logger->warning(
"Sub-optimal transaction [{dbs}]:\n{trace}", [
458 'dbs' => implode(
', ', array_keys( $this->dbTrxHoldingLocks[$name][
'conns'] ) ),
462 unset( $this->dbTrxHoldingLocks[$name] );
463 unset( $this->dbTrxMethodTimes[$name] );
466 private function initPlaceholderExpectations() {
467 $this->expect = array_fill_keys(
469 [ self::FLD_LIMIT => INF, self::FLD_FNAME =>
null ]
472 $this->hits = array_fill_keys( self::COUNTER_EVENT_NAMES, 0 );
473 $this->violations = array_fill_keys( self::EVENT_NAMES, 0 );
481 private function isAboveThreshold( $value,
string $event ) {
482 if ( $this->silenced[$event] > 0 ) {
486 return ( $value > $this->expect[$event][self::FLD_LIMIT] );
493 private function pingAndCheckThreshold(
string $event ) {
494 if ( $this->silenced[$event] > 0 ) {
498 $newValue = ++$this->hits[$event];
499 $limit = $this->expect[$event][self::FLD_LIMIT];
501 return ( $newValue > $limit );
511 private function reportExpectationViolated(
515 ?
string $trxId =
null,
516 ?
string $serverName =
null
518 $violations = ++$this->violations[$event];
520 if ( $violations === 1 && $this->method !==
null ) {
521 $this->stats->increment(
"rdbms_trxprofiler_warnings.$event.{$this->method}" );
524 $max = $this->expect[$event][self::FLD_LIMIT];
525 $by = $this->expect[$event][self::FLD_FNAME];
527 $message =
"Expectation ($event <= $max) by $by not met (actual: {actualSeconds})";
529 $message .=
' in trx #{trxId}';
531 $message .=
":\n{query}\n";
533 $this->logger->warning(
536 'db_log_category' =>
'performance',
538 'maxSeconds' => $max,
540 'actualSeconds' => $actual,
541 'query' => $this->getGeneralizedSql( $query ),
542 'exception' =>
new RuntimeException(),
544 'fullQuery' => $this->getRawSql( $query ),
545 'dbHost' => $serverName
554 private function getGeneralizedSql( $query ) {
555 return $query instanceof GeneralizedSql ? $query->stringify() : $query;
562 private function getRawSql( $query ) {
563 return $query instanceof GeneralizedSql ? $query->getRawSql() : $query;
570 private function getCurrentTime() {
571 return $this->wallClockOverride ?: microtime(
true );
579 $this->wallClockOverride =& $time;
wfDeprecated( $function, $version=false, $component=false, $callerOffset=2)
Logs a warning that a deprecated feature was used.
Describes a Statsd aware interface.