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 = .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                 'readQueryTime'  => INF,
  66                 'writeQueryTime' => INF
  67         ];
  68         /** @var array */
  69         protected $expectBy = [];
  70
  71         /**
  72          * @var LoggerInterface
  73          */
  74         private $logger;
  75
  76         public function __construct() {
  77                 $this->setLogger( new NullLogger() );
  78         }
  79
  80         public function setLogger( LoggerInterface $logger ) {
  81                 $this->logger = $logger;
  82         }
  83
  84         /**
  85          * @param bool $value New value
  86          * @return bool Old value
  87          * @since 1.28
  88          */
  89         public function setSilenced( $value ) {
  90                 $old = $this->silenced;
  91                 $this->silenced = $value;
  92
  93                 return $old;
  94         }
  95
  96         /**
  97          * Set performance expectations
  98          *
  99          * With conflicting expectations, the most narrow ones will be used
 100          *
 101          * @param string $event (writes,queries,conns,mConns)
 102          * @param integer $value Maximum count of the event
 103          * @param string $fname Caller
 104          * @since 1.25
 105          */
 106         public function setExpectation( $event, $value, $fname ) {
 107                 $this->expect[$event] = isset( $this->expect[$event] )
 108                         ? min( $this->expect[$event], $value )
 109                         : $value;
 110                 if ( $this->expect[$event] == $value ) {
 111                         $this->expectBy[$event] = $fname;
 112                 }
 113         }
 114
 115         /**
 116          * Set multiple performance expectations
 117          *
 118          * With conflicting expectations, the most narrow ones will be used
 119          *
 120          * @param array $expects Map of (event => limit)
 121          * @param $fname
 122          * @since 1.26
 123          */
 124         public function setExpectations( array $expects, $fname ) {
 125                 foreach ( $expects as $event => $value ) {
 126                         $this->setExpectation( $event, $value, $fname );
 127                 }
 128         }
 129
 130         /**
 131          * Reset performance expectations and hit counters
 132          *
 133          * @since 1.25
 134          */
 135         public function resetExpectations() {
 136                 foreach ( $this->hits as &$val ) {
 137                         $val = 0;
 138                 }
 139                 unset( $val );
 140                 foreach ( $this->expect as &$val ) {
 141                         $val = INF;
 142                 }
 143                 unset( $val );
 144                 $this->expectBy = [];
 145         }
 146
 147         /**
 148          * Mark a DB as having been connected to with a new handle
 149          *
 150          * Note that there can be multiple connections to a single DB.
 151          *
 152          * @param string $server DB server
 153          * @param string $db DB name
 154          * @param bool $isMaster
 155          */
 156         public function recordConnection( $server, $db, $isMaster ) {
 157                 // Report when too many connections happen...
 158                 if ( $this->hits['conns']++ == $this->expect['conns'] ) {
 159                         $this->reportExpectationViolated( 'conns', "[connect to $server ($db)]" );
 160                 }
 161                 if ( $isMaster && $this->hits['masterConns']++ == $this->expect['masterConns'] ) {
 162                         $this->reportExpectationViolated( 'masterConns', "[connect to $server ($db)]" );
 163                 }
 164         }
 165
 166         /**
 167          * Mark a DB as in a transaction with one or more writes pending
 168          *
 169          * Note that there can be multiple connections to a single DB.
 170          *
 171          * @param string $server DB server
 172          * @param string $db DB name
 173          * @param string $id ID string of transaction
 174          */
 175         public function transactionWritingIn( $server, $db, $id ) {
 176                 $name = "{$server} ({$db}) (TRX#$id)";
 177                 if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
 178                         $this->logger->info( "Nested transaction for '$name' - out of sync." );
 179                 }
 180                 $this->dbTrxHoldingLocks[$name] = [
 181                         'start' => microtime( true ),
 182                         'conns' => [], // all connections involved
 183                 ];
 184                 $this->dbTrxMethodTimes[$name] = [];
 185
 186                 foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
 187                         // Track all DBs in transactions for this transaction
 188                         $info['conns'][$name] = 1;
 189                 }
 190         }
 191
 192         /**
 193          * Register the name and time of a method for slow DB trx detection
 194          *
 195          * This assumes that all queries are synchronous (non-overlapping)
 196          *
 197          * @param string $query Function name or generalized SQL
 198          * @param float $sTime Starting UNIX wall time
 199          * @param bool $isWrite Whether this is a write query
 200          * @param integer $n Number of affected rows
 201          */
 202         public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
 203                 $eTime = microtime( true );
 204                 $elapsed = ( $eTime - $sTime );
 205
 206                 if ( $isWrite && $n > $this->expect['maxAffected'] ) {
 207                         $this->logger->info(
 208                                 "Query affected $n row(s):\n" . $query . "\n" .
 209                                 ( new RuntimeException() )->getTraceAsString() );
 210                 }
 211
 212                 // Report when too many writes/queries happen...
 213                 if ( $this->hits['queries']++ == $this->expect['queries'] ) {
 214                         $this->reportExpectationViolated( 'queries', $query );
 215                 }
 216                 if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) {
 217                         $this->reportExpectationViolated( 'writes', $query );
 218                 }
 219                 // Report slow queries...
 220                 if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
 221                         $this->reportExpectationViolated( 'readQueryTime', $query, $elapsed );
 222                 }
 223                 if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
 224                         $this->reportExpectationViolated( 'writeQueryTime', $query, $elapsed );
 225                 }
 226
 227                 if ( !$this->dbTrxHoldingLocks ) {
 228                         // Short-circuit
 229                         return;
 230                 } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
 231                         // Not an important query nor slow enough
 232                         return;
 233                 }
 234
 235                 foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
 236                         $lastQuery = end( $this->dbTrxMethodTimes[$name] );
 237                         if ( $lastQuery ) {
 238                                 // Additional query in the trx...
 239                                 $lastEnd = $lastQuery[2];
 240                                 if ( $sTime >= $lastEnd ) { // sanity check
 241                                         if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
 242                                                 // Add an entry representing the time spent doing non-queries
 243                                                 $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $sTime ];
 244                                         }
 245                                         $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
 246                                 }
 247                         } else {
 248                                 // First query in the trx...
 249                                 if ( $sTime >= $info['start'] ) { // sanity check
 250                                         $this->dbTrxMethodTimes[$name][] = [ $query, $sTime, $eTime ];
 251                                 }
 252                         }
 253                 }
 254         }
 255
 256         /**
 257          * Mark a DB as no longer in a transaction
 258          *
 259          * This will check if locks are possibly held for longer than
 260          * needed and log any affected transactions to a special DB log.
 261          * Note that there can be multiple connections to a single DB.
 262          *
 263          * @param string $server DB server
 264          * @param string $db DB name
 265          * @param string $id ID string of transaction
 266          * @param float $writeTime Time spent in write queries
 267          * @param integer $affected Number of rows affected by writes
 268          */
 269         public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0, $affected = 0 ) {
 270                 $name = "{$server} ({$db}) (TRX#$id)";
 271                 if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
 272                         $this->logger->info( "Detected no transaction for '$name' - out of sync." );
 273                         return;
 274                 }
 275
 276                 $slow = false;
 277
 278                 // Warn if too much time was spend writing...
 279                 if ( $writeTime > $this->expect['writeQueryTime'] ) {
 280                         $this->reportExpectationViolated(
 281                                 'writeQueryTime',
 282                                 "[transaction $id writes to {$server} ({$db})]",
 283                                 $writeTime
 284                         );
 285                         $slow = true;
 286                 }
 287                 // Warn if too many rows were changed...
 288                 if ( $affected > $this->expect['maxAffected'] ) {
 289                         $this->reportExpectationViolated(
 290                                 'maxAffected',
 291                                 "[transaction $id writes to {$server} ({$db})]",
 292                                 $affected
 293                         );
 294                 }
 295                 // Fill in the last non-query period...
 296                 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
 297                 if ( $lastQuery ) {
 298                         $now = microtime( true );
 299                         $lastEnd = $lastQuery[2];
 300                         if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
 301                                 $this->dbTrxMethodTimes[$name][] = [ '...delay...', $lastEnd, $now ];
 302                         }
 303                 }
 304                 // Check for any slow queries or non-query periods...
 305                 foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
 306                         $elapsed = ( $info[2] - $info[1] );
 307                         if ( $elapsed >= $this->dbLockThreshold ) {
 308                                 $slow = true;
 309                                 break;
 310                         }
 311                 }
 312                 if ( $slow ) {
 313                         $trace = '';
 314                         foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
 315                                 list( $query, $sTime, $end ) = $info;
 316                                 $trace .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
 317                         }
 318                         $this->logger->info( "Sub-optimal transaction on DB(s) [{dbs}]: \n{trace}", [
 319                                 'dbs' => implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) ),
 320                                 'trace' => $trace
 321                         ] );
 322                 }
 323                 unset( $this->dbTrxHoldingLocks[$name] );
 324                 unset( $this->dbTrxMethodTimes[$name] );
 325         }
 326
 327         /**
 328          * @param string $expect
 329          * @param string $query
 330          * @param string|float|int $actual [optional]
 331          */
 332         protected function reportExpectationViolated( $expect, $query, $actual = null ) {
 333                 if ( $this->silenced ) {
 334                         return;
 335                 }
 336
 337                 $n = $this->expect[$expect];
 338                 $by = $this->expectBy[$expect];
 339                 $actual = ( $actual !== null ) ? " (actual: $actual)" : "";
 340
 341                 $this->logger->info(
 342                         "Expectation ($expect <= $n) by $by not met$actual:\n$query\n" .
 343                         ( new RuntimeException() )->getTraceAsString()
 344                 );
 345         }
 346 }