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