8c819ff5672f992bfa807de9eea2a2456fff3ceb
3 * Base class and functions for profiling.
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.
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.
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
22 * @defgroup Profiler Profiler
23 * This file is only included if profiling is enabled
27 * Begin profiling of a function
28 * @param string $functionname name of the function we will profile
30 function wfProfileIn( $functionname ) {
31 if ( Profiler
::$__instance === null ) { // use this directly to reduce overhead
34 if ( !( Profiler
::$__instance instanceof ProfilerStub
) ) {
35 Profiler
::$__instance->profileIn( $functionname );
40 * Stop profiling of a function
41 * @param string $functionname name of the function we have profiled
43 function wfProfileOut( $functionname = 'missing' ) {
44 if ( Profiler
::$__instance === null ) { // use this directly to reduce overhead
47 if ( !( Profiler
::$__instance instanceof ProfilerStub
) ) {
48 Profiler
::$__instance->profileOut( $functionname );
53 * Class for handling function-scope profiling
57 class ProfileSection
{
58 protected $name; // string; method name
59 protected $enabled = false; // boolean; whether profiling is enabled
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.
67 * This is typically called like:
68 * <code>$section = new ProfileSection( __METHOD__ );</code>
70 * @param string $name Name of the function to profile
72 public function __construct( $name ) {
74 if ( Profiler
::$__instance === null ) { // use this directly to reduce overhead
77 if ( !( Profiler
::$__instance instanceof ProfilerStub
) ) {
78 $this->enabled
= true;
79 Profiler
::$__instance->profileIn( $this->name
);
83 function __destruct() {
84 if ( $this->enabled
) {
85 Profiler
::$__instance->profileOut( $this->name
);
91 * Profiler base class that defines the interface and some trivial functionality
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;
101 /** @var TransactionProfiler */
102 protected $trxProfiler;
105 public static $__instance = null; // do not call this outside Profiler and ProfileSection
108 * @param array $params
110 public function __construct( array $params ) {
111 if ( isset( $params['profileID'] ) ) {
112 $this->mProfileID
= $params['profileID'];
114 $this->trxProfiler
= new TransactionProfiler();
121 final public static function instance() {
122 if ( self
::$__instance === null ) {
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
130 $class = $wgProfiler['class'];
132 self
::$__instance = new $class( $wgProfiler );
133 } elseif ( $wgProfiler instanceof Profiler
) {
134 self
::$__instance = $wgProfiler; // back-compat
136 self
::$__instance = new ProfilerStub( array() );
139 return self
::$__instance;
143 * Set the profiler to a specific profiler instance. Mostly for dumpHTML
146 final public static function setInstance( Profiler
$p ) {
147 self
::$__instance = $p;
151 * Return whether this a stub profiler
155 abstract public function isStub();
158 * Return whether this profiler stores data
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.
164 * @see Profiler::logData()
167 abstract public function isPersistent();
172 public function setProfileID( $id ) {
173 $this->mProfileID
= $id;
179 public function getProfileID() {
180 if ( $this->mProfileID
=== false ) {
183 return $this->mProfileID
;
188 * Called by wfProfieIn()
190 * @param string $functionname
192 abstract public function profileIn( $functionname );
195 * Called by wfProfieOut()
197 * @param string $functionname
199 abstract public function profileOut( $functionname );
202 * Mark a DB as in a transaction with one or more writes pending
204 * Note that there can be multiple connections to a single DB.
206 * @param string $server DB server
207 * @param string $db DB name
209 public function transactionWritingIn( $server, $db ) {
210 $this->trxProfiler
->transactionWritingIn( $server, $db );
214 * Mark a DB as no longer in a transaction
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.
220 * @param string $server DB server
221 * @param string $db DB name
223 public function transactionWritingOut( $server, $db ) {
224 $this->trxProfiler
->transactionWritingOut( $server, $db );
228 * Close opened profiling sections
230 abstract public function close();
233 * Log the data to some store or even the page output
235 abstract public function logData();
238 * Mark this call as templated or not
242 public function setTemplated( $t ) {
243 $this->mTemplated
= $t;
247 * Returns a profiling output to be stored in debug file
251 abstract public function getOutput();
256 abstract public function getRawData();
259 * Get the initial time of the request, based either on $wgRequestTime or
260 * $wgRUstart. Will return null if not able to find data.
262 * @param string|false $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
269 protected function getTime( $metric = 'wall' ) {
270 if ( $metric === 'cpu' ||
$metric === 'user' ) {
271 if ( !function_exists( '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
;
283 return microtime( true );
288 * Get the initial time of the request, based either on $wgRequestTime or
289 * $wgRUstart. Will return null if not able to find data.
291 * @param string|false $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
298 protected function getInitialTime( $metric = 'wall' ) {
299 global $wgRequestTime, $wgRUstart;
301 if ( $metric === 'cpu' ||
$metric === 'user' ) {
302 if ( !count( $wgRUstart ) ) {
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
;
314 if ( empty( $wgRequestTime ) ) {
317 return $wgRequestTime;
323 * Add an entry in the debug log file
325 * @param string $s to output
327 protected function debug( $s ) {
328 if ( function_exists( 'wfDebug' ) ) {
334 * Add an entry in the debug log group
336 * @param string $group Group to send the message to
337 * @param string $s to output
339 protected function debugGroup( $group, $s ) {
340 if ( function_exists( 'wfDebugLog' ) ) {
341 wfDebugLog( $group, $s );
347 * Helper class that detects high-contention DB queries via profiling calls
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).
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();
363 * Mark a DB as in a transaction with one or more writes pending
365 * Note that there can be multiple connections to a single DB.
367 * @param string $server DB server
368 * @param string $db DB name
370 public function transactionWritingIn( $server, $db ) {
371 $name = "{$server} ({$db})";
372 if ( isset( $this->mDBTrxHoldingLocks
[$name] ) ) {
373 ++
$this->mDBTrxHoldingLocks
[$name]['refs'];
375 $this->mDBTrxHoldingLocks
[$name] = array( 'refs' => 1, 'start' => microtime( true ) );
376 $this->mDBTrxMethodTimes
[$name] = array();
381 * Register the name and time of a method for slow DB trx detection
383 * This method is only to be called by the Profiler class as methods finish
385 * @param string $method Function name
386 * @param float $realtime Wal time ellapsed
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
395 return; // not a DB master query nor slow enough
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 );
407 * Mark a DB as no longer in a transaction
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.
413 * @param string $server DB server
414 * @param string $db DB name
416 public function transactionWritingOut( $server, $db ) {
417 $name = "{$server} ({$db})";
418 if ( --$this->mDBTrxHoldingLocks
[$name]['refs'] <= 0 ) {
420 foreach ( $this->mDBTrxMethodTimes
[$name] as $info ) {
421 list( $method, $realtime ) = $info;
422 if ( $realtime >= $this->mDBLockThreshold
) {
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 );
434 $this->debugGroup( 'DBPerformance', $msg );
436 unset( $this->mDBTrxHoldingLocks
[$name] );
437 unset( $this->mDBTrxMethodTimes
[$name] );