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         // @codingStandardsIgnoreStart PSR2.Classes.PropertyDeclaration.Underscore
 105         /** @var Profiler Do not call this outside Profiler and ProfileSection */
 106         public static $__instance = null;
 107         // @codingStandardsIgnoreEnd
 108
 109         /**
 110          * @param array $params
 111          */
 112         public function __construct( array $params ) {
 113                 if ( isset( $params['profileID'] ) ) {
 114                         $this->mProfileID = $params['profileID'];
 115                 }
 116                 $this->trxProfiler = new TransactionProfiler();
 117         }
 118
 119         /**
 120          * Singleton
 121          * @return Profiler
 122          */
 123         final public static function instance() {
 124                 if ( self::$__instance === null ) {
 125                         global $wgProfiler;
 126                         if ( is_array( $wgProfiler ) ) {
 127                                 if ( !isset( $wgProfiler['class'] ) ) {
 128                                         $class = 'ProfilerStub';
 129                                 } elseif ( $wgProfiler['class'] === 'Profiler'  ) {
 130                                         $class = 'ProfilerStub'; // b/c; don't explode
 131                                 } else {
 132                                         $class = $wgProfiler['class'];
 133                                 }
 134                                 self::$__instance = new $class( $wgProfiler );
 135                         } elseif ( $wgProfiler instanceof Profiler ) {
 136                                 self::$__instance = $wgProfiler; // back-compat
 137                         } else {
 138                                 self::$__instance = new ProfilerStub( array() );
 139                         }
 140                 }
 141                 return self::$__instance;
 142         }
 143
 144         /**
 145          * Set the profiler to a specific profiler instance. Mostly for dumpHTML
 146          * @param Profiler $p
 147          */
 148         final public static function setInstance( Profiler $p ) {
 149                 self::$__instance = $p;
 150         }
 151
 152         /**
 153          * Return whether this a stub profiler
 154          *
 155          * @return bool
 156          */
 157         abstract public function isStub();
 158
 159         /**
 160          * Return whether this profiler stores data
 161          *
 162          * Called by Parser::braceSubstitution. If true, the parser will not
 163          * generate per-title profiling sections, to avoid overloading the
 164          * profiling data collector.
 165          *
 166          * @see Profiler::logData()
 167          * @return bool
 168          */
 169         abstract public function isPersistent();
 170
 171         /**
 172          * @param string $id
 173          */
 174         public function setProfileID( $id ) {
 175                 $this->mProfileID = $id;
 176         }
 177
 178         /**
 179          * @return string
 180          */
 181         public function getProfileID() {
 182                 if ( $this->mProfileID === false ) {
 183                         return wfWikiID();
 184                 } else {
 185                         return $this->mProfileID;
 186                 }
 187         }
 188
 189         /**
 190          * Called by wfProfieIn()
 191          *
 192          * @param string $functionname
 193          */
 194         abstract public function profileIn( $functionname );
 195
 196         /**
 197          * Called by wfProfieOut()
 198          *
 199          * @param  string $functionname
 200          */
 201         abstract public function profileOut( $functionname );
 202
 203         /**
 204          * Mark a DB as in a transaction with one or more writes pending
 205          *
 206          * Note that there can be multiple connections to a single DB.
 207          *
 208          * @param string $server DB server
 209          * @param string $db DB name
 210          * @param string $id Resource ID string of connection
 211          */
 212         public function transactionWritingIn( $server, $db, $id = '' ) {
 213                 $this->trxProfiler->transactionWritingIn( $server, $db, $id );
 214         }
 215
 216         /**
 217          * Mark a DB as no longer in a transaction
 218          *
 219          * This will check if locks are possibly held for longer than
 220          * needed and log any affected transactions to a special DB log.
 221          * Note that there can be multiple connections to a single DB.
 222          *
 223          * @param string $server DB server
 224          * @param string $db DB name
 225          * @param string $id Resource ID string of connection
 226          */
 227         public function transactionWritingOut( $server, $db, $id = '' ) {
 228                 $this->trxProfiler->transactionWritingOut( $server, $db, $id );
 229         }
 230
 231         /**
 232          * Close opened profiling sections
 233          */
 234         abstract public function close();
 235
 236         /**
 237          * Log the data to some store or even the page output
 238          */
 239         abstract public function logData();
 240
 241         /**
 242          * Mark this call as templated or not
 243          *
 244          * @param bool $t
 245          */
 246         public function setTemplated( $t ) {
 247                 $this->mTemplated = $t;
 248         }
 249
 250         /**
 251          * Returns a profiling output to be stored in debug file
 252          *
 253          * @return string
 254          */
 255         abstract public function getOutput();
 256
 257         /**
 258          * @return array
 259          */
 260         abstract public function getRawData();
 261
 262         /**
 263          * Get the initial time of the request, based either on $wgRequestTime or
 264          * $wgRUstart. Will return null if not able to find data.
 265          *
 266          * @param string|bool $metric Metric to use, with the following possibilities:
 267          *   - user: User CPU time (without system calls)
 268          *   - cpu: Total CPU time (user and system calls)
 269          *   - wall (or any other string): elapsed time
 270          *   - false (default): will fall back to default metric
 271          * @return float|null
 272          */
 273         protected function getTime( $metric = 'wall' ) {
 274                 if ( $metric === 'cpu' || $metric === 'user' ) {
 275                         if ( !function_exists( 'getrusage' ) ) {
 276                                 return 0;
 277                         }
 278                         $ru = getrusage();
 279                         $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
 280                         if ( $metric === 'cpu' ) {
 281                                 # This is the time of system calls, added to the user time
 282                                 # it gives the total CPU time
 283                                 $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
 284                         }
 285                         return $time;
 286                 } else {
 287                         return microtime( true );
 288                 }
 289         }
 290
 291         /**
 292          * Get the initial time of the request, based either on $wgRequestTime or
 293          * $wgRUstart. Will return null if not able to find data.
 294          *
 295          * @param string|bool $metric Metric to use, with the following possibilities:
 296          *   - user: User CPU time (without system calls)
 297          *   - cpu: Total CPU time (user and system calls)
 298          *   - wall (or any other string): elapsed time
 299          *   - false (default): will fall back to default metric
 300          * @return float|null
 301          */
 302         protected function getInitialTime( $metric = 'wall' ) {
 303                 global $wgRequestTime, $wgRUstart;
 304
 305                 if ( $metric === 'cpu' || $metric === 'user' ) {
 306                         if ( !count( $wgRUstart ) ) {
 307                                 return null;
 308                         }
 309
 310                         $time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
 311                         if ( $metric === 'cpu' ) {
 312                                 # This is the time of system calls, added to the user time
 313                                 # it gives the total CPU time
 314                                 $time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
 315                         }
 316                         return $time;
 317                 } else {
 318                         if ( empty( $wgRequestTime ) ) {
 319                                 return null;
 320                         } else {
 321                                 return $wgRequestTime;
 322                         }
 323                 }
 324         }
 325
 326         /**
 327          * Add an entry in the debug log file
 328          *
 329          * @param string $s to output
 330          */
 331         protected function debug( $s ) {
 332                 if ( function_exists( 'wfDebug' ) ) {
 333                         wfDebug( $s );
 334                 }
 335         }
 336
 337         /**
 338          * Add an entry in the debug log group
 339          *
 340          * @param string $group Group to send the message to
 341          * @param string $s to output
 342          */
 343         protected function debugGroup( $group, $s ) {
 344                 if ( function_exists( 'wfDebugLog' ) ) {
 345                         wfDebugLog( $group, $s );
 346                 }
 347         }
 348 }
 349
 350 /**
 351  * Helper class that detects high-contention DB queries via profiling calls
 352  *
 353  * This class is meant to work with a Profiler, as the later already knows
 354  * when methods start and finish (which may take place during transactions).
 355  *
 356  * @since 1.24
 357  */
 358 class TransactionProfiler {
 359         /** @var float seconds */
 360         protected $mDBLockThreshold = 3.0;
 361         /** @var array DB/server name => (active trx count, time, DBs involved) */
 362         protected $mDBTrxHoldingLocks = array();
 363         /** @var array DB/server name => list of (function name, elapsed time) */
 364         protected $mDBTrxMethodTimes = array();
 365
 366         /**
 367          * Mark a DB as in a transaction with one or more writes pending
 368          *
 369          * Note that there can be multiple connections to a single DB.
 370          *
 371          * @param string $server DB server
 372          * @param string $db DB name
 373          * @param string $id ID string of transaction
 374          */
 375         public function transactionWritingIn( $server, $db, $id ) {
 376                 $name = "{$server} ({$db}) (TRX#$id)";
 377                 if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
 378                         wfDebugLog( 'DBPerformance', "Nested transaction for '$name' - out of sync." );
 379                 }
 380                 $this->mDBTrxHoldingLocks[$name] =
 381                         array( 'start' => microtime( true ), 'conns' => array() );
 382                 $this->mDBTrxMethodTimes[$name] = array();
 383
 384                 foreach ( $this->mDBTrxHoldingLocks as $name => &$info ) {
 385                         $info['conns'][$name] = 1; // track all DBs in transactions for this transaction
 386                 }
 387         }
 388
 389         /**
 390          * Register the name and time of a method for slow DB trx detection
 391          *
 392          * This method is only to be called by the Profiler class as methods finish
 393          *
 394          * @param string $method Function name
 395          * @param float $realtime Wal time ellapsed
 396          */
 397         public function recordFunctionCompletion( $method, $realtime ) {
 398                 if ( !$this->mDBTrxHoldingLocks ) {
 399                         return; // short-circuit
 400                 // @TODO: hardcoded check is a tad janky (what about FOR UPDATE?)
 401                 } elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
 402                         && $realtime < $this->mDBLockThreshold
 403                 ) {
 404                         return; // not a DB master query nor slow enough
 405                 }
 406                 $now = microtime( true );
 407                 foreach ( $this->mDBTrxHoldingLocks as $name => $info ) {
 408                         // Hacky check to exclude entries from before the first TRX write
 409                         if ( ( $now - $realtime ) >= $info['start'] ) {
 410                                 $this->mDBTrxMethodTimes[$name][] = array( $method, $realtime );
 411                         }
 412                 }
 413         }
 414
 415         /**
 416          * Mark a DB as no longer in a transaction
 417          *
 418          * This will check if locks are possibly held for longer than
 419          * needed and log any affected transactions to a special DB log.
 420          * Note that there can be multiple connections to a single DB.
 421          *
 422          * @param string $server DB server
 423          * @param string $db DB name
 424          * @param string $id ID string of transaction
 425          */
 426         public function transactionWritingOut( $server, $db, $id ) {
 427                 $name = "{$server} ({$db}) (TRX#$id)";
 428                 if ( !isset( $this->mDBTrxMethodTimes[$name] ) ) {
 429                         wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." );
 430                         return;
 431                 }
 432                 $slow = false;
 433                 foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
 434                         $realtime = $info[1];
 435                         if ( $realtime >= $this->mDBLockThreshold ) {
 436                                 $slow = true;
 437                                 break;
 438                         }
 439                 }
 440                 if ( $slow ) {
 441                         $dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks[$name]['conns'] ) );
 442                         $msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n";
 443                         foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) {
 444                                 list( $method, $realtime ) = $info;
 445                                 $msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
 446                         }
 447                         wfDebugLog( 'DBPerformance', $msg );
 448                 }
 449                 unset( $this->mDBTrxHoldingLocks[$name] );
 450                 unset( $this->mDBTrxMethodTimes[$name] );
 451         }
 452 }