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