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