includes/libs/rdbms/TransactionProfiler.php

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