1<?php
2/**
3 *
4 * This program is free software; you can redistribute it and/or modify
5 * it under the terms of the GNU General Public License as published by
6 * the Free Software Foundation; either version 2 of the License, or
7 * (at your option) any later version.
8 *
9 * This program is distributed in the hope that it will be useful,
10 * but WITHOUT ANY WARRANTY; without even the implied warranty of
11 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
12 * GNU General Public License for more details.
13 *
14 * You should have received a copy of the GNU General Public License along
15 * with this program; if not, write to the Free Software Foundation, Inc.,
16 * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
17 * http://www.gnu.org/copyleft/gpl.html
18 *
19 * @file
20 */
21
22namespace Wikimedia\Rdbms;
23
24use Psr\Log\LoggerAwareInterface;
25use Psr\Log\LoggerInterface;
26use Psr\Log\NullLogger;
27use RuntimeException;
28
29/**
30 * Detect high-contention DB queries via profiling calls.
31 *
32 * This class is meant to work with an IDatabase object, which manages queries.
33 *
34 * @since 1.24
35 * @ingroup Profiler
36 * @ingroup Database
37 */
38class TransactionProfiler implements LoggerAwareInterface {
39	/** @var float Seconds */
40	protected $dbLockThreshold = 3.0;
41	/** @var float Seconds */
42	protected $eventThreshold = 0.25;
43	/** @var bool */
44	protected $silenced = false;
45
46	/** @var array transaction ID => (write start time, list of DBs involved) */
47	protected $dbTrxHoldingLocks = [];
48	/**
49	 * @var array[][] transaction ID => list of (query name, start time, end time)
50	 * @phan-var array<string,array<int,array{0:string,1:int,2:int}>>
51	 */
52	protected $dbTrxMethodTimes = [];
53
54	/** @var array */
55	protected $hits = [
56		'writes'      => 0,
57		'queries'     => 0,
58		'conns'       => 0,
59		'masterConns' => 0
60	];
61	/** @var array */
62	protected $expect = [
63		'writes'         => INF,
64		'queries'        => INF,
65		'conns'          => INF,
66		'masterConns'    => INF,
67		'maxAffected'    => INF,
68		'readQueryRows'  => INF,
69		'readQueryTime'  => INF,
70		'writeQueryTime' => INF
71	];
72	/** @var array */
73	protected $expectBy = [];
74
75	/**
76	 * @var LoggerInterface
77	 */
78	private $logger;
79
80	public function __construct() {
81		$this->setLogger( new NullLogger() );
82	}
83
84	public function setLogger( LoggerInterface $logger ) {
85		$this->logger = $logger;
86	}
87
88	/**
89	 * @param bool $value
90	 * @return bool Old value
91	 * @since 1.28
92	 */
93	public function setSilenced( $value ) {
94		$old = $this->silenced;
95		$this->silenced = $value;
96
97		return $old;
98	}
99
100	/**
101	 * Set performance expectations
102	 *
103	 * With conflicting expectations, the most narrow ones will be used
104	 *
105	 * @param string $event (writes,queries,conns,mConns)
106	 * @param int $value Maximum count of the event
107	 * @param string $fname Caller
108	 * @since 1.25
109	 */
110	public function setExpectation( $event, $value, $fname ) {
111		$this->expect[$event] = isset( $this->expect[$event] )
112			? min( $this->expect[$event], $value )
113			: $value;
114		if ( $this->expect[$event] == $value ) {
115			$this->expectBy[$event] = $fname;
116		}
117	}
118
119	/**
120	 * Set one or multiple performance expectations
121	 *
122	 * With conflicting expectations, the most narrow ones will be used
123	 *
124	 * Use this to initialize expectations or make them stricter mid-request
125	 *
126	 * @param array $expects Map of (event => limit)
127	 * @param string $fname
128	 * @since 1.26
129	 */
130	public function setExpectations( array $expects, $fname ) {
131		foreach ( $expects as $event => $value ) {
132			$this->setExpectation( $event, $value, $fname );
133		}
134	}
135
136	/**
137	 * Reset all performance expectations and hit counters
138	 *
139	 * Use this for unit testing or before applying a totally different set of expectations
140	 * for a different part of the request, such as during "post-send" (execution after HTTP
141	 * response completion)
142	 *
143	 * @since 1.25
144	 */
145	public function resetExpectations() {
146		foreach ( $this->hits as &$val ) {
147			$val = 0;
148		}
149		unset( $val );
150		foreach ( $this->expect as &$val ) {
151			$val = INF;
152		}
153		unset( $val );
154		$this->expectBy = [];
155	}
156
157	/**
158	 * Clear all expectations and hit counters and set new performance expectations
159	 *
160	 * Use this to apply a totally different set of expectations for a different part
161	 * of the request, such as during "post-send" (execution after HTTP response completion)
162	 *
163	 * @param array $expects Map of (event => limit)
164	 * @param string $fname
165	 * @since 1.33
166	 */
167	public function redefineExpectations( array $expects, $fname ) {
168		$this->resetExpectations();
169		$this->setExpectations( $expects, $fname );
170	}
171
172	/**
173	 * Mark a DB as having been connected to with a new handle
174	 *
175	 * Note that there can be multiple connections to a single DB.
176	 *
177	 * @param string $server DB server
178	 * @param string $db DB name
179	 * @param bool $isMaster
180	 */
181	public function recordConnection( $server, $db, $isMaster ) {
182		// Report when too many connections happen...
183		if ( $this->hits['conns']++ >= $this->expect['conns'] ) {
184			$this->reportExpectationViolated(
185				'conns', "[connect to $server ($db)]", $this->hits['conns'] );
186		}
187		if ( $isMaster && $this->hits['masterConns']++ >= $this->expect['masterConns'] ) {
188			$this->reportExpectationViolated(
189				'masterConns', "[connect to $server ($db)]", $this->hits['masterConns'] );
190		}
191	}
192
193	/**
194	 * Mark a DB as in a transaction with one or more writes pending
195	 *
196	 * Note that there can be multiple connections to a single DB.
197	 *
198	 * @param string $server DB server
199	 * @param string $db DB name
200	 * @param string $id ID string of transaction
201	 */
202	public function transactionWritingIn( $server, $db, $id ) {
203		$name = "{$server} ({$db}) (TRX#$id)";
204		if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
205			$this->logger->warning( "Nested transaction for '$name' - out of sync." );
206		}
207		$this->dbTrxHoldingLocks[$name] = [
208			'start' => microtime( true ),
209			'conns' => [], // all connections involved
210		];
211		$this->dbTrxMethodTimes[$name] = [];
212
213		foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
214			// Track all DBs in transactions for this transaction
215			$info['conns'][$name] = 1;
216		}
217	}
218
219	/**
220	 * Register the name and time of a method for slow DB trx detection
221	 *
222	 * This assumes that all queries are synchronous (non-overlapping)
223	 *
224	 * @param string|GeneralizedSql $query Function name or generalized SQL
225	 * @param float $sTime Starting UNIX wall time
226	 * @param bool $isWrite Whether this is a write query
227	 * @param int $n Number of affected/read rows
228	 */
229	public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
230		$eTime = microtime( true );
231		$elapsed = ( $eTime - $sTime );
232
233		if ( $isWrite && $n > $this->expect['maxAffected'] ) {
234			$this->logger->warning(
235				"Query affected $n row(s):\n" . self::queryString( $query ) . "\n" .
236				( new RuntimeException() )->getTraceAsString() );
237		} elseif ( !$isWrite && $n > $this->expect['readQueryRows'] ) {
238			$this->logger->warning(
239				"Query returned $n row(s):\n" . self::queryString( $query ) . "\n" .
240				( new RuntimeException() )->getTraceAsString() );
241		}
242
243		// Report when too many writes/queries happen...
244		if ( $this->hits['queries']++ >= $this->expect['queries'] ) {
245			$this->reportExpectationViolated( 'queries', $query, $this->hits['queries'] );
246		}
247		if ( $isWrite && $this->hits['writes']++ >= $this->expect['writes'] ) {
248			$this->reportExpectationViolated( 'writes', $query, $this->hits['writes'] );
249		}
250		// Report slow queries...
251		if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
252			$this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
253		}
254		if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
255			$this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
256		}
257
258		if ( !$this->dbTrxHoldingLocks ) {
259			// Short-circuit
260			return;
261		} elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
262			// Not an important query nor slow enough
263			return;
264		}
265
266		foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
267			$lastQuery = end( $this->dbTrxMethodTimes[$name] );
268			if ( $lastQuery ) {
269				// Additional query in the trx...
270				$lastEnd = $lastQuery[2];
271				if ( $sTime >= $lastEnd ) { // sanity check
272					if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
273						// Add an entry representing the time spent doing non-queries
274						$this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
275					}
276					$this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
277				}
278			} else {
279				// First query in the trx...
280				if ( $sTime >= $info['start'] ) { // sanity check
281					$this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
282				}
283			}
284		}
285	}
286
287	/**
288	 * Mark a DB as no longer in a transaction
289	 *
290	 * This will check if locks are possibly held for longer than
291	 * needed and log any affected transactions to a special DB log.
292	 * Note that there can be multiple connections to a single DB.
293	 *
294	 * @param string $server DB server
295	 * @param string $db DB name
296	 * @param string $id ID string of transaction
297	 * @param float $writeTime Time spent in write queries
298	 * @param int $affected Number of rows affected by writes
299	 */
300	public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
301		$name = "{$server} ({$db}) (TRX#$id)";
302		if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
303			$this->logger->warning( "Detected no transaction for '$name' - out of sync." );
304			return;
305		}
306
307		$slow = false;
308
309		// Warn if too much time was spend writing...
310		if ( $writeTime > $this->expect['writeQueryTime'] ) {
311			$this->reportExpectationViolated(
312				'writeQueryTime',
313				"[transaction $id writes to {$server} ({$db})]",
314				$writeTime
315			);
316			$slow = true;
317		}
318		// Warn if too many rows were changed...
319		if ( $affected > $this->expect['maxAffected'] ) {
320			$this->reportExpectationViolated(
321				'maxAffected',
322				"[transaction $id writes to {$server} ({$db})]",
323				$affected
324			);
325		}
326		// Fill in the last non-query period...
327		$lastQuery = end( $this->dbTrxMethodTimes[$name] );
328		if ( $lastQuery ) {
329			$now = microtime( true );
330			$lastEnd = $lastQuery[2];
331			if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
332				$this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
333			}
334		}
335		// Check for any slow queries or non-query periods...
336		foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
337			$elapsed = ( $info[2] - $info[1] );
338			if ( $elapsed >= $this->dbLockThreshold ) {
339				$slow = true;
340				break;
341			}
342		}
343		if ( $slow ) {
344			$trace = '';
345			foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
346				list( $query, $sTime, $end ) = $info;
347				$trace .= sprintf(
348					"%d\t%.6f\t%s\n", $i, ( $end - $sTime ), self::queryString( $query ) );
349			}
350			$this->logger->warning( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
351				'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
352				'trace' => $trace
353			] );
354		}
355		unset( $this->dbTrxHoldingLocks[$name] );
356		unset( $this->dbTrxMethodTimes[$name] );
357	}
358
359	/**
360	 * @param string $expect
361	 * @param string|GeneralizedSql $query
362	 * @param string|float|int $actual
363	 */
364	protected function reportExpectationViolated( $expect, $query, $actual ) {
365		if ( $this->silenced ) {
366			return;
367		}
368
369		$this->logger->warning(
370			"Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):\n{query}\n" .
371			( new RuntimeException() )->getTraceAsString(),
372			[
373				'measure' => $expect,
374				'max' => $this->expect[$expect],
375				'by' => $this->expectBy[$expect],
376				'actual' => $actual,
377				'query' => self::queryString( $query )
378			]
379		);
380	}
381
382	/**
383	 * @param GeneralizedSql|string $query
384	 * @return string
385	 */
386	private static function queryString( $query ) {
387		return $query instanceof GeneralizedSql ? $query->stringify() : $query;
388	}
389}
390