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