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         /**
  46          * Mark a DB as in a transaction with one or more writes pending
  47          *
  48          * Note that there can be multiple connections to a single DB.
  49          *
  50          * @param string $server DB server
  51          * @param string $db DB name
  52          * @param string $id ID string of transaction
  53          */
  54         public function transactionWritingIn( $server, $db, $id ) {
  55                 $name = "{$server} ({$db}) (TRX#$id)";
  56                 if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
  57                         wfDebugLog( 'DBPerformance', "Nested transaction for '$name' - out of sync." );
  58                 }
  59                 $this->dbTrxHoldingLocks[$name] = array(
  60                         'start' => microtime( true ),
  61                         'conns' => array(), // all connections involved
  62                 );
  63                 $this->dbTrxMethodTimes[$name] = array();
  64
  65                 foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
  66                         // Track all DBs in transactions for this transaction
  67                         $info['conns'][$name] = 1;
  68                 }
  69         }
  70
  71         /**
  72          * Register the name and time of a method for slow DB trx detection
  73          *
  74          * This assumes that all queries are synchronous (non-overlapping)
  75          *
  76          * @param string $query Function name or generalized SQL
  77          * @param float $sTime Starting UNIX wall time
  78          * @param bool $isWrite Whether this is a write query
  79          * @param integer $n Number of affected rows
  80          */
  81         public function recordQueryCompletion( $query, $sTime, $isWrite = false, $n = 0 ) {
  82                 $eTime = microtime( true );
  83                 $elapsed = ( $eTime - $sTime );
  84
  85                 if ( $isWrite && $n > $this->affectedThreshold && PHP_SAPI !== 'cli' ) {
  86                         wfDebugLog( 'DBPerformance',
  87                                 "Query affected $n rows:\n" . $query . "\n" . wfBacktrace( true ) );
  88                 }
  89
  90                 if ( !$this->dbTrxHoldingLocks ) {
  91                         // Short-circuit
  92                         return;
  93                 } elseif ( !$isWrite && $elapsed < $this->eventThreshold ) {
  94                         // Not an important query nor slow enough
  95                         return;
  96                 }
  97
  98                 foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
  99                         $lastQuery = end( $this->dbTrxMethodTimes[$name] );
 100                         if ( $lastQuery ) {
 101                                 // Additional query in the trx...
 102                                 $lastEnd = $lastQuery[2];
 103                                 if ( $sTime >= $lastEnd ) { // sanity check
 104                                         if ( ( $sTime - $lastEnd ) > $this->eventThreshold ) {
 105                                                 // Add an entry representing the time spent doing non-queries
 106                                                 $this->dbTrxMethodTimes[$name][] = array( '...delay...', $lastEnd, $sTime );
 107                                         }
 108                                         $this->dbTrxMethodTimes[$name][] = array( $query, $sTime, $eTime );
 109                                 }
 110                         } else {
 111                                 // First query in the trx...
 112                                 if ( $sTime >= $info['start'] ) { // sanity check
 113                                         $this->dbTrxMethodTimes[$name][] = array( $query, $sTime, $eTime );
 114                                 }
 115                         }
 116                 }
 117         }
 118
 119         /**
 120          * Mark a DB as no longer in a transaction
 121          *
 122          * This will check if locks are possibly held for longer than
 123          * needed and log any affected transactions to a special DB log.
 124          * Note that there can be multiple connections to a single DB.
 125          *
 126          * @param string $server DB server
 127          * @param string $db DB name
 128          * @param string $id ID string of transaction
 129          */
 130         public function transactionWritingOut( $server, $db, $id ) {
 131                 $name = "{$server} ({$db}) (TRX#$id)";
 132                 if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
 133                         wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." );
 134                         return;
 135                 }
 136                 // Fill in the last non-query period...
 137                 $lastQuery = end( $this->dbTrxMethodTimes[$name] );
 138                 if ( $lastQuery ) {
 139                         $now = microtime( true );
 140                         $lastEnd = $lastQuery[2];
 141                         if ( ( $now - $lastEnd ) > $this->eventThreshold ) {
 142                                 $this->dbTrxMethodTimes[$name][] = array( '...delay...', $lastEnd, $now );
 143                         }
 144                 }
 145                 // Check for any slow queries or non-query periods...
 146                 $slow = false;
 147                 foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
 148                         $elapsed = ( $info[2] - $info[1] );
 149                         if ( $elapsed >= $this->dbLockThreshold ) {
 150                                 $slow = true;
 151                                 break;
 152                         }
 153                 }
 154                 if ( $slow ) {
 155                         $dbs = implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) );
 156                         $msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n";
 157                         foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
 158                                 list( $query, $sTime, $end ) = $info;
 159                                 $msg .= sprintf( "%d\t%.6f\t%s\n", $i, ( $end - $sTime ), $query );
 160                         }
 161                         wfDebugLog( 'DBPerformance', $msg );
 162                 }
 163                 unset( $this->dbTrxHoldingLocks[$name] );
 164                 unset( $this->dbTrxMethodTimes[$name] );
 165         }
 166 }