Thijs/wiki.techinc.nl
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Profiler code cleanup

Browse source 
- Put Profiler, ProfileSection and TransactionProfiler in their own
  files and rely on Autoloader to use them (maintenance has been
  using the autoloader here for some time--we don't profile the
  autoloader manually)
- This reduces overhead in WebStart/doMaintenance by only loading
  three functions at profiler initialization and defers until the
  first profiling call happens
- Inline callback functions in ProfilerSimpleText rather than having
  public static functions.
- Small comment and code formatting changes in various touched files.

Change-Id: Idf27677c068c50b847152c523a33e7f0c33fdeeb
This commit is contained in:
Chad Horohoe 2014-11-04 09:40:40 -08:00 committed by BryanDavis
parent 6c7bb3a57c
commit 4e61f1bb8b
8 changed files with 291 additions and 212 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
includes/AutoLoader.php
View file

@ -877,8 +877,8 @@ $wgAutoloadLocalClasses = array(
'ProfilerSimpleUDP' => 'includes/profiler/ProfilerSimpleUDP.php',
'ProfilerStandard' => 'includes/profiler/ProfilerStandard.php',
'ProfilerStub' => 'includes/profiler/ProfilerStub.php',
'ProfileSection' => 'includes/profiler/Profiler.php',
'TransactionProfiler' => 'includes/profiler/Profiler.php',
'ProfileSection' => 'includes/profiler/ProfileSection.php',
'TransactionProfiler' => 'includes/profiler/TransactionProfiler.php',
# includes/rcfeed
'RCFeedEngine' => 'includes/rcfeed/RCFeedEngine.php',

4
includes/WebStart.php
View file

@ -58,8 +58,8 @@ if ( $IP === false ) {
$IP = realpath( '.' ) ?: dirname( __DIR__ );
}
# Load the profiler
require_once "$IP/includes/profiler/Profiler.php";
# Grab profiling functions
require_once "$IP/includes/profiler/ProfilerFunctions.php";
$wgRUstart = wfGetRusage() ?: array();
# Start the autoloader, so that extensions can derive classes from core files

63
includes/profiler/ProfileSection.php Normal file
View file

@ -0,0 +1,63 @@
<?php
/**
* Function scope profiling assistant
*
* This program is free software; you can redistribute it and/or modify
* it under the terms of the GNU General Public License as published by
* the Free Software Foundation; either version 2 of the License, or
* (at your option) any later version.
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License along
* with this program; if not, write to the Free Software Foundation, Inc.,
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
* http://www.gnu.org/copyleft/gpl.html
*
* @file
* @ingroup Profiler
*/
/**
* Class for handling function-scope profiling
*
* @since 1.22
*/
class ProfileSection {
/** @var string $name Method name */
protected $name;
/** @var boolean $enabled Is profiling enabled? */
protected $enabled = false;
/**
* Begin profiling of a function and return an object that ends profiling
* of the function when that object leaves scope. As long as the object is
* not specifically linked to other objects, it will fall out of scope at
* the same moment that the function to be profiled terminates.
*
* This is typically called like:
* <code>$section = new ProfileSection( __METHOD__ );</code>
*
* @param string $name Name of the function to profile
*/
public function __construct( $name ) {
$this->name = $name;
// Use Profiler member variable directly to reduce overhead
if ( Profiler::$__instance === null ) {
Profiler::instance();
}
if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
$this->enabled = true;
Profiler::$__instance->profileIn( $this->name );
}
}
function __destruct() {
if ( $this->enabled ) {
Profiler::$__instance->profileOut( $this->name );
}
}
}

191
includes/profiler/Profiler.php
View file

@ -1,6 +1,6 @@
<?php
/**
* Base class and functions for profiling.
* Base class for profiling.
*
* This program is free software; you can redistribute it and/or modify
* it under the terms of the GNU General Public License as published by
@ -23,89 +23,8 @@
*/
/**
* Get system resource usage of current request context.
* Invokes the getrusage(2) system call, requesting RUSAGE_SELF if on PHP5
* or RUSAGE_THREAD if on HHVM. Returns false if getrusage is not available.
*
* @since 1.24
* @return array|bool Resource usage data or false if no data available.
*/
function wfGetRusage() {
if ( !function_exists( 'getrusage' ) ) {
return false;
} elseif ( defined ( 'HHVM_VERSION' ) ) {
return getrusage( 2 /* RUSAGE_THREAD */ );
} else {
return getrusage( 0 /* RUSAGE_SELF */ );
}
}
/**
* Begin profiling of a function
* @param string $functionname Name of the function we will profile
*/
function wfProfileIn( $functionname ) {
if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
Profiler::instance();
}
if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
Profiler::$__instance->profileIn( $functionname );
}
}
/**
* Stop profiling of a function
* @param string $functionname Name of the function we have profiled
*/
function wfProfileOut( $functionname = 'missing' ) {
if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
Profiler::instance();
}
if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
Profiler::$__instance->profileOut( $functionname );
}
}
/**
* Class for handling function-scope profiling
*
* @since 1.22
*/
class ProfileSection {
protected $name; // string; method name
protected $enabled = false; // boolean; whether profiling is enabled
/**
* Begin profiling of a function and return an object that ends profiling of
* the function when that object leaves scope. As long as the object is not
* specifically linked to other objects, it will fall out of scope at the same
* moment that the function to be profiled terminates.
*
* This is typically called like:
* <code>$section = new ProfileSection( __METHOD__ );</code>
*
* @param string $name Name of the function to profile
*/
public function __construct( $name ) {
$this->name = $name;
if ( Profiler::$__instance === null ) { // use this directly to reduce overhead
Profiler::instance();
}
if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
$this->enabled = true;
Profiler::$__instance->profileIn( $this->name );
}
}
function __destruct() {
if ( $this->enabled ) {
Profiler::$__instance->profileOut( $this->name );
}
}
}
/**
* Profiler base class that defines the interface and some trivial functionality
* Profiler base class that defines the interface and some trivial
* functionality
*
* @ingroup Profiler
*/
@ -359,107 +278,3 @@ abstract class Profiler {
}
}
}
/**
* Helper class that detects high-contention DB queries via profiling calls
*
* This class is meant to work with a Profiler, as the later already knows
* when methods start and finish (which may take place during transactions).
*
* @since 1.24
*/
class TransactionProfiler {
/** @var float Seconds */
protected $mDBLockThreshold = 3.0;
/** @var array DB/server name => (active trx count, time, DBs involved) */
protected $mDBTrxHoldingLocks = array();
/** @var array DB/server name => list of (function name, elapsed time) */
protected $mDBTrxMethodTimes = array();
/**
* Mark a DB as in a transaction with one or more writes pending
*
* Note that there can be multiple connections to a single DB.
*
* @param string $server DB server
* @param string $db DB name
* @param string $id ID string of transaction
*/
public function transactionWritingIn( $server, $db, $id ) {
$name = "{$server} ({$db}) (TRX#$id)";
if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
wfDebugLog( 'DBPerformance', "Nested transaction for '$name' - out of sync." );
}
$this->mDBTrxHoldingLocks[$name] =
array( 'start' => microtime( true ), 'conns' => array() );
$this->mDBTrxMethodTimes[$name] = array();
foreach ( $this->mDBTrxHoldingLocks as $name => &$info ) {
$info['conns'][$name] = 1; // track all DBs in transactions for this transaction
}
}
/**
* Register the name and time of a method for slow DB trx detection
*
* This method is only to be called by the Profiler class as methods finish
*
* @param string $method Function name
* @param float $realtime Wal time ellapsed
*/
public function recordFunctionCompletion( $method, $realtime ) {
if ( !$this->mDBTrxHoldingLocks ) {
return; // short-circuit
// @todo hardcoded check is a tad janky (what about FOR UPDATE?)
} elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
&& $realtime < $this->mDBLockThreshold
) {
return; // not a DB master query nor slow enough
}
$now = microtime( true );
foreach ( $this->mDBTrxHoldingLocks as $name => $info ) {
// Hacky check to exclude entries from before the first TRX write
if ( ( $now - $realtime ) >= $info['start'] ) {
$this->mDBTrxMethodTimes[$name][] = array( $method, $realtime );
}
}
}
/**
* Mark a DB as no longer in a transaction
*
* This will check if locks are possibly held for longer than
* needed and log any affected transactions to a special DB log.
* Note that there can be multiple connections to a single DB.
*
* @param string $server DB server
* @param string $db DB name
* @param string $id ID string of transaction
*/
public function transactionWritingOut( $server, $db, $id ) {
$name = "{$server} ({$db}) (TRX#$id)";
if ( !isset( $this->mDBTrxMethodTimes[$name] ) ) {
wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." );
return;
}
$slow = false;
foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
$realtime = $info[1];
if ( $realtime >= $this->mDBLockThreshold ) {
$slow = true;
break;
}
}
if ( $slow ) {
$dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks[$name]['conns'] ) );
$msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n";
foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) {
list( $method, $realtime ) = $info;
$msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
}
wfDebugLog( 'DBPerformance', $msg );
}
unset( $this->mDBTrxHoldingLocks[$name] );
unset( $this->mDBTrxMethodTimes[$name] );
}
}

68
includes/profiler/ProfilerFunctions.php Normal file
View file

@ -0,0 +1,68 @@
<?php
/**
* Core profiling functions. Have to exist before basically anything.
*
* This program is free software; you can redistribute it and/or modify
* it under the terms of the GNU General Public License as published by
* the Free Software Foundation; either version 2 of the License, or
* (at your option) any later version.
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License along
* with this program; if not, write to the Free Software Foundation, Inc.,
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
* http://www.gnu.org/copyleft/gpl.html
*
* @file
* @ingroup Profiler
*/
/**
* Get system resource usage of current request context.
* Invokes the getrusage(2) system call, requesting RUSAGE_SELF if on PHP5
* or RUSAGE_THREAD if on HHVM. Returns false if getrusage is not available.
*
* @since 1.24
* @return array|bool Resource usage data or false if no data available.
*/
function wfGetRusage() {
if ( !function_exists( 'getrusage' ) ) {
return false;
} elseif ( defined ( 'HHVM_VERSION' ) ) {
return getrusage( 2 /* RUSAGE_THREAD */ );
} else {
return getrusage( 0 /* RUSAGE_SELF */ );
}
}
/**
* Begin profiling of a function
* @param string $functionname Name of the function we will profile
*/
function wfProfileIn( $functionname ) {
// Use Profiler member variable directly to reduce overhead
if ( Profiler::$__instance === null ) {
Profiler::instance();
}
if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
Profiler::$__instance->profileIn( $functionname );
}
}
/**
* Stop profiling of a function
* @param string $functionname Name of the function we have profiled
*/
function wfProfileOut( $functionname = 'missing' ) {
// Use Profiler member variable directly to reduce overhead
if ( Profiler::$__instance === null ) {
Profiler::instance();
}
if ( !( Profiler::$__instance instanceof ProfilerStub ) ) {
Profiler::$__instance->profileOut( $functionname );
}
}

38
includes/profiler/ProfilerSimpleText.php
View file

@ -33,7 +33,6 @@
*/
class ProfilerSimpleText extends ProfilerStandard {
public $visible = false; /* Show as <PRE> or <!-- ? */
static private $out;
public function __construct( $profileConfig ) {
if ( isset( $profileConfig['visible'] ) && $profileConfig['visible'] ) {
@ -43,37 +42,40 @@ class ProfilerSimpleText extends ProfilerStandard {
}
public function logData() {
$out = '';
if ( $this->mTemplated ) {
$this->close();
$totalReal = isset( $this->mCollated['-total'] )
? $this->mCollated['-total']['real']
: 0; // profiling mismatch error?
uasort( $this->mCollated, array( 'self', 'sort' ) );
array_walk( $this->mCollated, array( 'self', 'format' ), $totalReal );
uasort( $this->mCollated, function( $a, $b ) {
// sort descending by time elapsed
return $a['real'] < $b['real'];
} );
array_walk( $this->mCollated,
function( $item, $key ) use ( &$out, $totalReal ) {
$perc = $totalReal ? $item['real'] / $totalReal * 100 : 0;
$out .= sprintf( "%6.2f%% %3.6f %6d - %s\n",
$perc, $item['real'], $item['count'], $key );
}
);
$contentType = $this->getContentType();
if ( PHP_SAPI === 'cli' ) {
print "<!--\n" . self::$out . "\n-->\n";
print "<!--\n{$out}\n-->\n";
} elseif ( $contentType === 'text/html' ) {
if ( $this->visible ) {
print '<pre>' . self::$out . '</pre>';
print "<pre>{$out}</pre>";
} else {
print "<!--\n" . self::$out . "\n-->\n";
print "<!--\n{$out}\n-->\n";
}
} elseif ( $contentType === 'text/javascript' ) {
print "\n/*\n" . self::$out . "*/\n";
print "\n/*\n${$out}*/\n";
} elseif ( $contentType === 'text/css' ) {
print "\n/*\n" . self::$out . "*/\n";
print "\n/*\n{$out}*/\n";
}
}
}
static function sort( $a, $b ) {
return $a['real'] < $b['real']; /* sort descending by time elapsed */
}
static function format( $item, $key, $totalReal ) {
$perc = $totalReal ? $item['real'] / $totalReal * 100 : 0;
self::$out .= sprintf( "%6.2f%% %3.6f %6d - %s\n",
$perc, $item['real'], $item['count'], $key );
}
}

131
includes/profiler/TransactionProfiler.php Normal file
View file

@ -0,0 +1,131 @@
<?php
/**
* Transaction profiling.
*
* This program is free software; you can redistribute it and/or modify
* it under the terms of the GNU General Public License as published by
* the Free Software Foundation; either version 2 of the License, or
* (at your option) any later version.
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License along
* with this program; if not, write to the Free Software Foundation, Inc.,
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
* http://www.gnu.org/copyleft/gpl.html
*
* @file
* @ingroup Profiler
*/
/**
* Helper class that detects high-contention DB queries via profiling calls
*
* This class is meant to work with a Profiler, as the later already knows
* when methods start and finish (which may take place during transactions).
*
* @since 1.24
*/
class TransactionProfiler {
/** @var float Seconds */
protected $mDBLockThreshold = 3.0;
/** @var array DB/server name => (active trx count, time, DBs involved) */
protected $mDBTrxHoldingLocks = array();
/** @var array DB/server name => list of (function name, elapsed time) */
protected $mDBTrxMethodTimes = array();
/**
* Mark a DB as in a transaction with one or more writes pending
*
* Note that there can be multiple connections to a single DB.
*
* @param string $server DB server
* @param string $db DB name
* @param string $id ID string of transaction
*/
public function transactionWritingIn( $server, $db, $id ) {
$name = "{$server} ({$db}) (TRX#$id)";
if ( isset( $this->mDBTrxHoldingLocks[$name] ) ) {
wfDebugLog( 'DBPerformance', "Nested transaction for '$name' - out of sync." );
}
$this->mDBTrxHoldingLocks[$name] = array(
'start' => microtime( true ),
'conns' => array(),
);
$this->mDBTrxMethodTimes[$name] = array();
foreach ( $this->mDBTrxHoldingLocks as $name => &$info ) {
// Track all DBs in transactions for this transaction
$info['conns'][$name] = 1;
}
}
/**
* Register the name and time of a method for slow DB trx detection
*
* This method is only to be called by the Profiler class as methods finish
*
* @param string $method Function name
* @param float $realtime Wal time ellapsed
*/
public function recordFunctionCompletion( $method, $realtime ) {
if ( !$this->mDBTrxHoldingLocks ) {
// Short-circuit
return;
// @todo hardcoded check is a tad janky (what about FOR UPDATE?)
} elseif ( !preg_match( '/^query-m: (?!SELECT)/', $method )
&& $realtime < $this->mDBLockThreshold
) {
// Not a DB master query nor slow enough
return;
}
$now = microtime( true );
foreach ( $this->mDBTrxHoldingLocks as $name => $info ) {
// Hacky check to exclude entries from before the first TRX write
if ( ( $now - $realtime ) >= $info['start'] ) {
$this->mDBTrxMethodTimes[$name][] = array( $method, $realtime );
}
}
}
/**
* Mark a DB as no longer in a transaction
*
* This will check if locks are possibly held for longer than
* needed and log any affected transactions to a special DB log.
* Note that there can be multiple connections to a single DB.
*
* @param string $server DB server
* @param string $db DB name
* @param string $id ID string of transaction
*/
public function transactionWritingOut( $server, $db, $id ) {
$name = "{$server} ({$db}) (TRX#$id)";
if ( !isset( $this->mDBTrxMethodTimes[$name] ) ) {
wfDebugLog( 'DBPerformance', "Detected no transaction for '$name' - out of sync." );
return;
}
$slow = false;
foreach ( $this->mDBTrxMethodTimes[$name] as $info ) {
$realtime = $info[1];
if ( $realtime >= $this->mDBLockThreshold ) {
$slow = true;
break;
}
}
if ( $slow ) {
$dbs = implode( ', ', array_keys( $this->mDBTrxHoldingLocks[$name]['conns'] ) );
$msg = "Sub-optimal transaction on DB(s) [{$dbs}]:\n";
foreach ( $this->mDBTrxMethodTimes[$name] as $i => $info ) {
list( $method, $realtime ) = $info;
$msg .= sprintf( "%d\t%.6f\t%s\n", $i, $realtime, $method );
}
wfDebugLog( 'DBPerformance', $msg );
}
unset( $this->mDBTrxHoldingLocks[$name] );
unset( $this->mDBTrxMethodTimes[$name] );
}
}

4
maintenance/doMaintenance.php
View file

@ -56,8 +56,8 @@ $self = $maintenance->getName();
# Start the autoloader, so that extensions can derive classes from core files
require_once "$IP/includes/AutoLoader.php";
# Stub the profiler
require_once "$IP/includes/profiler/Profiler.php";
# Grab profiling functions
require_once "$IP/includes/profiler/ProfilerFunctions.php";
# Start the profiler
$wgProfiler = array();