includes/profiler/Profiler.php

   1 <?php
   2 /**
   3  * Base class and functions for 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  * @defgroup Profiler Profiler
  23  * This file is only included if profiling is enabled
  24  */
  25
  26 /**
  27  * Begin profiling of a function
  28  * @param string $functionname name of the function we will profile
  29  */
  30 function wfProfileIn( $functionname ) {
  31         if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
  32                 Profiler::instance();
  33         }
  34         if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
  35                 Profiler::$__instance->profileIn( $functionname );
  36         }
  37 }
  38
  39 /**
  40  * Stop profiling of a function
  41  * @param string $functionname name of the function we have profiled
  42  */
  43 function wfProfileOut( $functionname = 'missing' ) {
  44         if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
  45                 Profiler::instance();
  46         }
  47         if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
  48                 Profiler::$__instance->profileOut( $functionname );
  49         }
  50 }
  51
  52 /**
  53  * Class for handling function-scope profiling
  54  *
  55  * @since 1.22
  56  */
  57 class ProfileSection {
  58         protected $name; // string; method name
  59         protected $enabled = false; // boolean; whether profiling is enabled
  60
  61         /**
  62          * Begin profiling of a function and return an object that ends profiling of
  63          * the function when that object leaves scope. As long as the object is not
  64          * specifically linked to other objects, it will fall out of scope at the same
  65          * moment that the function to be profiled terminates.
  66          *
  67          * This is typically called like:
  68          * <code>$section = new ProfileSection( __METHOD__ );</code>
  69          *
  70          * @param string $name Name of the function to profile
  71          */
  72         public function __construct( $name ) {
  73                 $this->name = $name;
  74                 if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
  75                         Profiler::instance();
  76                 }
  77                 if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
  78                         $this->enabled = true;
  79                         Profiler::$__instance->profileIn( $this->name );
  80                 }
  81         }
  82
  83         function __destruct() {
  84                 if ( $this->enabled ) {
  85                         Profiler::$__instance->profileOut( $this->name );
  86                 }
  87         }
  88 }
  89
  90 /**
  91  * Profiler base class that defines the interface and some trivial functionality
  92  *
  93  * @ingroup Profiler
  94  */
  95 abstract class Profiler {
  96         /** @var string|bool Profiler ID for bucketing data */
  97         protected $mProfileID = false;
  98         /** @var bool Whether MediaWiki is in a SkinTemplate output context */
  99         protected $mTemplated = false;
 100
 101         /** @var TransactionProfiler */
 102         protected $trxProfiler;
 103
 104         /** @var Profiler */
 105         public static $__instance = null; // do not call this outside Profiler and ProfileSection
 106
 107         /**
 108          * @param array $params
 109          */
 110         public function __construct( array $params ) {
 111                 if ( isset( $params['profileID'] ) ) {
 112                         $this->mProfileID = $params['profileID'];
 113                 }
 114                 $this->trxProfiler = new TransactionProfiler();
 115         }
 116
 117         /**
 118          * Singleton
 119          * @return Profiler
 120          */
 121         final public static function instance() {
 122                 if ( self::$__instance === null ) {
 123                         global $wgProfiler;
 124                         if ( is_array( $wgProfiler ) ) {
 125                                 if ( !isset( $wgProfiler['class'] ) ) {
 126                                         $class = 'ProfilerStub';
 127                                 } elseif ( $wgProfiler['class'] === 'Profiler'  ) {
 128                                         $class = 'ProfilerStub'; // b/c; don't explode
 129                                 } else {
 130                                         $class = $wgProfiler['class'];
 131                                 }
 132                                 self::$__instance = new $class( $wgProfiler );
 133                         } elseif ( $wgProfiler instanceof Profiler ) {
 134                                 self::$__instance = $wgProfiler; // back-compat
 135                         } else {
 136                                 self::$__instance = new ProfilerStub( array() );
 137                         }
 138                 }
 139                 return self::$__instance;
 140         }
 141
 142         /**
 143          * Set the profiler to a specific profiler instance. Mostly for dumpHTML
 144          * @param Profiler $p
 145          */
 146         final public static function setInstance( Profiler $p ) {
 147                 self::$__instance = $p;
 148         }
 149
 150         /**
 151          * Return whether this a stub profiler
 152          *
 153          * @return bool
 154          */
 155         abstract public function isStub();
 156
 157         /**
 158          * Return whether this profiler stores data
 159          *
 160          * Called by Parser::braceSubstitution. If true, the parser will not
 161          * generate per-title profiling sections, to avoid overloading the
 162          * profiling data collector.
 163          *
 164          * @see Profiler::logData()
 165          * @return bool
 166          */
 167         abstract public function isPersistent();
 168
 169         /**
 170          * @param string $id
 171          */
 172         public function setProfileID( $id ) {
 173                 $this->mProfileID = $id;
 174         }
 175
 176         /**
 177          * @return string
 178          */
 179         public function getProfileID() {
 180                 if ( $this->mProfileID === false ) {
 181                         return wfWikiID();
 182                 } else {
 183                         return $this->mProfileID;
 184                 }
 185         }
 186
 187         /**
 188          * Called by wfProfieIn()
 189          *
 190          * @param string $functionname
 191          */
 192         abstract public function profileIn( $functionname );
 193
 194         /**
 195          * Called by wfProfieOut()
 196          *
 197          * @param  string $functionname
 198          */
 199         abstract public function profileOut( $functionname );
 200
 201         /**
 202          * Mark a DB as in a transaction with one or more writes pending
 203          *
 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 Resource ID string of connection
 209          */
 210         public function transactionWritingIn( $server, $db, $id = '' ) {
 211                 $this->trxProfiler->transactionWritingIn( $server, $db, $id );
 212         }
 213
 214         /**
 215          * Mark a DB as no longer in a transaction
 216          *
 217          * This will check if locks are possibly held for longer than
 218          * needed and log any affected transactions to a special DB log.
 219          * Note that there can be multiple connections to a single DB.
 220          *
 221          * @param string $server DB server
 222          * @param string $db DB name
 223          * @param string $id Resource ID string of connection
 224          */
 225         public function transactionWritingOut( $server, $db, $id = '' ) {
 226                 $this->trxProfiler->transactionWritingOut( $server, $db, $id );
 227         }
 228
 229         /**
 230          * Close opened profiling sections
 231          */
 232         abstract public function close();
 233
 234         /**
 235          * Log the data to some store or even the page output
 236          */
 237         abstract public function logData();
 238
 239         /**
 240          * Mark this call as templated or not
 241          *
 242          * @param bool $t
 243          */
 244         public function setTemplated( $t ) {
 245                 $this->mTemplated = $t;
 246         }
 247
 248         /**
 249          * Returns a profiling output to be stored in debug file
 250          *
 251          * @return string
 252          */
 253         abstract public function getOutput();
 254
 255         /**
 256          * @return array
 257          */
 258         abstract public function getRawData();
 259
 260         /**
 261          * Get the initial time of the request, based either on $wgRequestTime or
 262          * $wgRUstart. Will return null if not able to find data.
 263          *
 264          * @param string|bool $metric Metric to use, with the following possibilities:
 265          *   - user: User CPU time (without system calls)
 266          *   - cpu: Total CPU time (user and system calls)
 267          *   - wall (or any other string): elapsed time
 268          *   - false (default): will fall back to default metric
 269          * @return float|null
 270          */
 271         protected function getTime( $metric = 'wall' ) {
 272                 if ( $metric === 'cpu' || $metric === 'user' ) {
 273                         if ( !function_exists( 'getrusage' ) ) {
 274                                 return 0;
 275                         }
 276                         $ru = getrusage();
 277                         $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
 278                         if ( $metric === 'cpu' ) {
 279                                 # This is the time of system calls, added to the user time
 280                                 # it gives the total CPU time
 281                                 $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
 282                         }
 283                         return $time;
 284                 } else {
 285                         return microtime( true );
 286                 }
 287         }
 288
 289         /**
 290          * Get the initial time of the request, based either on $wgRequestTime or
 291          * $wgRUstart. Will return null if not able to find data.
 292          *
 293          * @param string|bool $metric Metric to use, with the following possibilities:
 294          *   - user: User CPU time (without system calls)
 295          *   - cpu: Total CPU time (user and system calls)
 296          *   - wall (or any other string): elapsed time
 297          *   - false (default): will fall back to default metric
 298          * @return float|null
 299          */
 300         protected function getInitialTime( $metric = 'wall' ) {
 301                 global $wgRequestTime, $wgRUstart;
 302
 303                 if ( $metric === 'cpu' || $metric === 'user' ) {
 304                         if ( !count( $wgRUstart ) ) {
 305                                 return null;
 306                         }
 307
 308                         $time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
 309                         if ( $metric === 'cpu' ) {
 310                                 # This is the time of system calls, added to the user time
 311                                 # it gives the total CPU time
 312                                 $time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
 313                         }
 314                         return $time;
 315                 } else {
 316                         if ( empty( $wgRequestTime ) ) {
 317                                 return null;
 318                         } else {
 319                                 return $wgRequestTime;
 320                         }
 321                 }
 322         }
 323
 324         /**
 325          * Add an entry in the debug log file
 326          *
 327          * @param string $s to output
 328          */
 329         protected function debug( $s ) {
 330                 if ( function_exists( 'wfDebug' ) ) {
 331                         wfDebug( $s );
 332                 }
 333         }
 334
 335         /**
 336          * Add an entry in the debug log group
 337          *
 338          * @param string $group Group to send the message to
 339          * @param string $s to output
 340          */
 341         protected function debugGroup( $group, $s ) {
 342                 if ( function_exists( 'wfDebugLog' ) ) {
 343                         wfDebugLog( $group, $s );
 344                 }
 345         }
 346 }
 347
 348 /**
 349  * Helper class that detects high-contention DB queries via profiling calls
 350  *
 351  * This class is meant to work with a Profiler, as the later already knows
 352  * when methods start and finish (which may take place during transactions).
 353  *
 354  * @since 1.24
 355  */
 356 class TransactionProfiler {
 357         /** @var float seconds */
 358         protected $mDBLockThreshold = 5.0;
 359         /** @var array DB/server name => (active trx count,timestamp) */
 360         protected $mDBTrxHoldingLocks = array();
 361         /** @var array DB/server name => list of (function name, elapsed time) */
 362         protected $mDBTrxMethodTimes = array();
 363
 364         /**
 365          * Mark a DB as in a transaction with one or more writes pending
 366          *
 367          * Note that there can be multiple connections to a single DB.
 368          *
 369          * @param string $server DB server
 370          * @param string $db DB name
 371          * @param string $id Resource ID string of connection
 372          */
 373         public function transactionWritingIn( $server, $db, $id ) {
 374                 $name = "{$server} ({$db}) ($id)";
 375                 if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
 376                         ++$this->mDBTrxHoldingLocks[$name]['refs'];
 377                 } else {
 378                         $this->mDBTrxHoldingLocks[$name] = array( 'refs' => 1, 'start' => microtime( true ) );
 379                         $this->mDBTrxMethodTimes[$name] = array();
 380                 }
 381         }
 382
 383         /**
 384          * Register the name and time of a method for slow DB trx detection
 385          *
 386          * This method is only to be called by the Profiler class as methods finish
 387          *
 388          * @param string $method Function name
 389          * @param float $realtime Wal time ellapsed
 390          */
 391         public function recordFunctionCompletion( $method, $realtime ) {
 392                 if ( !$this->mDBTrxHoldingLocks ) {
 393                         return; // short-circuit
 394                 // @TODO: hardcoded check is a tad janky (what about FOR UPDATE?)
 395                 } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
 396                         && $realtime < $this->mDBLockThreshold
 397                 ) {
 398                         return; // not a DB master query nor slow enough
 399                 }
 400                 $now = microtime( true );
 401                 foreach ( $this->mDBTrxHoldingLocks as $name => $info ) {
 402                         // Hacky check to exclude entries from before the first TRX write
 403                         if ( ( $now - $realtime ) >= $info['start'] ) {
 404                                 $this->mDBTrxMethodTimes[$name][] = array( $method, $realtime );
 405                         }
 406                 }
 407         }
 408
 409         /**
 410          * Mark a DB as no longer in a transaction
 411          *
 412          * This will check if locks are possibly held for longer than
 413          * needed and log any affected transactions to a special DB log.
 414          * Note that there can be multiple connections to a single DB.
 415          *
 416          * @param string $server DB server
 417          * @param string $db DB name
 418          * @param string $id Resource ID string of connection
 419          */
 420         public function transactionWritingOut( $server, $db, $id ) {
 421                 $name = "{$server} ({$db}) ($id)";
 422                 if ( --$this->mDBTrxHoldingLocks[$name]['refs'] <= 0 ) {
 423                         $slow = false;
 424                         foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
 425                                 list( $method, $realtime ) = $info;
 426                                 if ( $realtime >= $this->mDBLockThreshold ) {
 427                                         $slow = true;
 428                                         break;
 429                                 }
 430                         }
 431                         if ( $slow ) {
 432                                 $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks ) );
 433                                 $msg = "Sub-optimal transaction on DB(s) {$dbs}:\n";
 434                                 foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) {
 435                                         list( $method, $realtime ) = $info;
 436                                         $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
 437                                 }
 438                                 wfDebugLog( 'DBPerformance', $msg );
 439                         }
 440                         unset( $this->mDBTrxHoldingLocks[$name] );
 441                         unset( $this->mDBTrxMethodTimes[$name] );
 442                 }
 443         }
 444 }