includes/profiler/TransactionProfiler.php

   1 <?php
   2 /**
   3  * Transaction profiling.
   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 Profiler, as the later already knows
  29  * when methods start and finish (which may take place during transactions).
  30  *
  31  * @since 1.24
  32  */
  33 class TransactionProfiler {
  34         /** @var float Seconds */
  35         protected $dbLockThreshold = 3.0;
  36         /** @var array DB/server name => (active trx count, time, DBs involved) */
  37         protected $dbTrxHoldingLocks = array();
  38         /** @var array DB/server name => list of (function name, elapsed time) */
  39         protected $dbTrxMethodTimes = array();
  40
  41         /**
  42          * Mark a DB as in a transaction with one or more writes pending
  43          *
  44          * Note that there can be multiple connections to a single DB.
  45          *
  46          * @param string $server DB server
  47          * @param string $db DB name
  48          * @param string $id ID string of transaction
  49          */
  50         public function transactionWritingIn( $server, $db, $id ) {
  51                 $name = "{$server} ({$db}) (TRX#$id)";
  52                 if ( isset( $this->dbTrxHoldingLocks[$name] ) ) {
  53                         wfDebugLog( 'DBPerformance', "Nested transaction for '$name' - out of sync." );
  54                 }
  55                 $this->dbTrxHoldingLocks[$name] = array(
  56                         'start' => microtime( true ),
  57                         'conns' => array(),
  58                 );
  59                 $this->dbTrxMethodTimes[$name] = array();
  60
  61                 foreach ( $this->dbTrxHoldingLocks as $name => &$info ) {
  62                         // Track all DBs in transactions for this transaction
  63                         $info['conns'][$name] = 1;
  64                 }
  65         }
  66
  67         /**
  68          * Register the name and time of a method for slow DB trx detection
  69          *
  70          * This method is only to be called by the Profiler class as methods finish
  71          *
  72          * @param string $method Function name
  73          * @param float $realtime Wall time ellapsed
  74          */
  75         public function recordFunctionCompletion( $method, $realtime ) {
  76                 if ( !$this->dbTrxHoldingLocks ) {
  77                         // Short-circuit
  78                         return;
  79                 // @todo hardcoded check is a tad janky
  80                 } elseif ( !preg_match( '/^query-m: /', $method ) && $realtime < 1.0 ) {
  81                         // Not a DB master query nor slow enough
  82                         return;
  83                 }
  84
  85                 $now = microtime( true );
  86                 foreach ( $this->dbTrxHoldingLocks as $name => $info ) {
  87                         // Hacky check to exclude entries from before the first TRX write
  88                         if ( ( $now - $realtime ) >= $info['start'] ) {
  89                                 $this->dbTrxMethodTimes[$name][] = array( $method, $realtime );
  90                         }
  91                 }
  92         }
  93
  94         /**
  95          * Mark a DB as no longer in a transaction
  96          *
  97          * This will check if locks are possibly held for longer than
  98          * needed and log any affected transactions to a special DB log.
  99          * Note that there can be multiple connections to a single DB.
 100          *
 101          * @param string $server DB server
 102          * @param string $db DB name
 103          * @param string $id ID string of transaction
 104          */
 105         public function transactionWritingOut( $server, $db, $id ) {
 106                 $name = "{$server} ({$db}) (TRX#$id)";
 107                 if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
 108                         wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." );
 109                         return;
 110                 }
 111                 $slow = false;
 112                 foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
 113                         $realtime = $info[1];
 114                         if ( $realtime >= $this->dbLockThreshold ) {
 115                                 $slow = true;
 116                                 break;
 117                         }
 118                 }
 119                 if ( $slow ) {
 120                         $dbs = implode( ', ', array_keys( $this->dbTrxHoldingLocks[$name]['conns'] ) );
 121                         $msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n";
 122                         foreach ( $this->dbTrxMethodTimes[$name] as $i => $info ) {
 123                                 list( $method, $realtime ) = $info;
 124                                 $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
 125                         }
 126                         wfDebugLog( 'DBPerformance', $msg );
 127                 }
 128                 unset( $this->dbTrxHoldingLocks[$name] );
 129                 unset( $this->dbTrxMethodTimes[$name] );
 130         }
 131 }