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