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          */
 209         public function transactionWritingIn( $server, $db ) {
 210                 $this->trxProfiler->transactionWritingIn( $server, $db );
 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          */
 223         public function transactionWritingOut( $server, $db ) {
 224                 $this->trxProfiler->transactionWritingOut( $server, $db );
 225         }
 226
 227         /**
 228          * Close opened profiling sections
 229          */
 230         abstract public function close();
 231
 232         /**
 233          * Log the data to some store or even the page output
 234          */
 235         abstract public function logData();
 236
 237         /**
 238          * Mark this call as templated or not
 239          *
 240          * @param bool $t
 241          */
 242         public function setTemplated( $t ) {
 243                 $this->mTemplated = $t;
 244         }
 245
 246         /**
 247          * Returns a profiling output to be stored in debug file
 248          *
 249          * @return string
 250          */
 251         abstract public function getOutput();
 252
 253         /**
 254          * @return array
 255          */
 256         abstract public function getRawData();
 257
 258         /**
 259          * Get the initial time of the request, based either on $wgRequestTime or
 260          * $wgRUstart. Will return null if not able to find data.
 261          *
 262          * @param string|bool $metric Metric to use, with the following possibilities:
 263          *   - user: User CPU time (without system calls)
 264          *   - cpu: Total CPU time (user and system calls)
 265          *   - wall (or any other string): elapsed time
 266          *   - false (default): will fall back to default metric
 267          * @return float|null
 268          */
 269         protected function getTime( $metric = 'wall' ) {
 270                 if ( $metric === 'cpu' || $metric === 'user' ) {
 271                         if ( !function_exists( 'getrusage' ) ) {
 272                                 return 0;
 273                         }
 274                         $ru = getrusage();
 275                         $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
 276                         if ( $metric === 'cpu' ) {
 277                                 # This is the time of system calls, added to the user time
 278                                 # it gives the total CPU time
 279                                 $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
 280                         }
 281                         return $time;
 282                 } else {
 283                         return microtime( true );
 284                 }
 285         }
 286
 287         /**
 288          * Get the initial time of the request, based either on $wgRequestTime or
 289          * $wgRUstart. Will return null if not able to find data.
 290          *
 291          * @param string|bool $metric Metric to use, with the following possibilities:
 292          *   - user: User CPU time (without system calls)
 293          *   - cpu: Total CPU time (user and system calls)
 294          *   - wall (or any other string): elapsed time
 295          *   - false (default): will fall back to default metric
 296          * @return float|null
 297          */
 298         protected function getInitialTime( $metric = 'wall' ) {
 299                 global $wgRequestTime, $wgRUstart;
 300
 301                 if ( $metric === 'cpu' || $metric === 'user' ) {
 302                         if ( !count( $wgRUstart ) ) {
 303                                 return null;
 304                         }
 305
 306                         $time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
 307                         if ( $metric === 'cpu' ) {
 308                                 # This is the time of system calls, added to the user time
 309                                 # it gives the total CPU time
 310                                 $time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
 311                         }
 312                         return $time;
 313                 } else {
 314                         if ( empty( $wgRequestTime ) ) {
 315                                 return null;
 316                         } else {
 317                                 return $wgRequestTime;
 318                         }
 319                 }
 320         }
 321
 322         /**
 323          * Add an entry in the debug log file
 324          *
 325          * @param string $s to output
 326          */
 327         protected function debug( $s ) {
 328                 if ( function_exists( 'wfDebug' ) ) {
 329                         wfDebug( $s );
 330                 }
 331         }
 332
 333         /**
 334          * Add an entry in the debug log group
 335          *
 336          * @param string $group Group to send the message to
 337          * @param string $s to output
 338          */
 339         protected function debugGroup( $group, $s ) {
 340                 if ( function_exists( 'wfDebugLog' ) ) {
 341                         wfDebugLog( $group, $s );
 342                 }
 343         }
 344 }
 345
 346 /**
 347  * Helper class that detects high-contention DB queries via profiling calls
 348  *
 349  * This class is meant to work with a Profiler, as the later already knows
 350  * when methods start and finish (which may take place during transactions).
 351  *
 352  * @since 1.24
 353  */
 354 class TransactionProfiler {
 355         /** @var float seconds */
 356         protected $mDBLockThreshold = 5.0;
 357         /** @var array DB/server name => (active trx count,timestamp) */
 358         protected $mDBTrxHoldingLocks = array();
 359         /** @var array DB/server name => list of (function name, elapsed time) */
 360         protected $mDBTrxMethodTimes = array();
 361
 362         /**
 363          * Mark a DB as in a transaction with one or more writes pending
 364          *
 365          * Note that there can be multiple connections to a single DB.
 366          *
 367          * @param string $server DB server
 368          * @param string $db DB name
 369          */
 370         public function transactionWritingIn( $server, $db ) {
 371                 $name = "{$server} ({$db})";
 372                 if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
 373                         ++$this->mDBTrxHoldingLocks[$name]['refs'];
 374                 } else {
 375                         $this->mDBTrxHoldingLocks[$name] = array( 'refs' => 1, 'start' => microtime( true ) );
 376                         $this->mDBTrxMethodTimes[$name] = array();
 377                 }
 378         }
 379
 380         /**
 381          * Register the name and time of a method for slow DB trx detection
 382          *
 383          * This method is only to be called by the Profiler class as methods finish
 384          *
 385          * @param string $method Function name
 386          * @param float $realtime Wal time ellapsed
 387          */
 388         public function recordFunctionCompletion( $method, $realtime ) {
 389                 if ( !$this->mDBTrxHoldingLocks ) {
 390                         return; // short-circuit
 391                 // @TODO: hardcoded check is a tad janky (what about FOR UPDATE?)
 392                 } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
 393                         && $realtime < $this->mDBLockThreshold
 394                 ) {
 395                         return; // not a DB master query nor slow enough
 396                 }
 397                 $now = microtime( true );
 398                 foreach ( $this->mDBTrxHoldingLocks as $name => $info ) {
 399                         // Hacky check to exclude entries from before the first TRX write
 400                         if ( ( $now - $realtime ) >= $info['start'] ) {
 401                                 $this->mDBTrxMethodTimes[$name][] = array( $method, $realtime );
 402                         }
 403                 }
 404         }
 405
 406         /**
 407          * Mark a DB as no longer in a transaction
 408          *
 409          * This will check if locks are possibly held for longer than
 410          * needed and log any affected transactions to a special DB log.
 411          * Note that there can be multiple connections to a single DB.
 412          *
 413          * @param string $server DB server
 414          * @param string $db DB name
 415          */
 416         public function transactionWritingOut( $server, $db ) {
 417                 $name = "{$server} ({$db})";
 418                 if ( --$this->mDBTrxHoldingLocks[$name]['refs'] <= 0 ) {
 419                         $slow = false;
 420                         foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
 421                                 list( $method, $realtime ) = $info;
 422                                 if ( $realtime >= $this->mDBLockThreshold ) {
 423                                         $slow = true;
 424                                         break;
 425                                 }
 426                         }
 427                         if ( $slow ) {
 428                                 $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks ) );
 429                                 $msg = "Sub-optimal transaction on DB(s) {$dbs}:\n";
 430                                 foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) {
 431                                         list( $method, $realtime ) = $info;
 432                                         $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
 433                                 }
 434                                 wfDebugLog( 'DBPerformance', $msg );
 435                         }
 436                         unset( $this->mDBTrxHoldingLocks[$name] );
 437                         unset( $this->mDBTrxMethodTimes[$name] );
 438                 }
 439         }
 440 }