summaryrefslogtreecommitdiff
path: root/includes/profiler
diff options
context:
space:
mode:
Diffstat (limited to 'includes/profiler')
-rw-r--r--includes/profiler/ProfileSection.php5
-rw-r--r--includes/profiler/Profiler.php26
-rw-r--r--includes/profiler/ProfilerFunctions.php2
-rw-r--r--includes/profiler/ProfilerStub.php3
-rw-r--r--includes/profiler/ProfilerXhprof.php45
-rw-r--r--includes/profiler/SectionProfiler.php9
-rw-r--r--includes/profiler/TransactionProfiler.php56
-rw-r--r--includes/profiler/output/ProfilerOutputDump.php6
-rw-r--r--includes/profiler/output/ProfilerOutputStats.php6
-rw-r--r--includes/profiler/output/ProfilerOutputText.php2
-rw-r--r--includes/profiler/output/ProfilerOutputUdp.php2
11 files changed, 124 insertions, 38 deletions
diff --git a/includes/profiler/ProfileSection.php b/includes/profiler/ProfileSection.php
index 68ef6680..d787edb7 100644
--- a/includes/profiler/ProfileSection.php
+++ b/includes/profiler/ProfileSection.php
@@ -35,9 +35,10 @@ class ProfileSection {
* the same moment that the function to be profiled terminates.
*
* This is typically called like:
- * <code>$section = new ProfileSection( __METHOD__ );</code>
+ * @code$section = new ProfileSection( __METHOD__ );@endcode
*
* @param string $name Name of the function to profile
*/
- public function __construct( $name ) {}
+ public function __construct( $name ) {
+ }
}
diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php
index dbf80fa1..9fd5a364 100644
--- a/includes/profiler/Profiler.php
+++ b/includes/profiler/Profiler.php
@@ -145,8 +145,11 @@ abstract class Profiler {
}
// Kept BC for now, remove when possible
- public function profileIn( $functionname ) {}
- public function profileOut( $functionname ) {}
+ public function profileIn( $functionname ) {
+ }
+
+ public function profileOut( $functionname ) {
+ }
/**
* Mark the start of a custom profiling frame (e.g. DB queries).
@@ -231,6 +234,21 @@ abstract class Profiler {
}
/**
+ * Output current data to the page output if configured to do so
+ *
+ * @throws MWException
+ * @since 1.26
+ */
+ public function logDataPageOutputOnly() {
+ foreach ( $this->getOutputs() as $output ) {
+ if ( $output instanceof ProfilerOutputText ) {
+ $stats = $this->getFunctionStats();
+ $output->log( $stats );
+ }
+ }
+ }
+
+ /**
* Get the content type sent out to the client.
* Used for profilers that output instead of store data.
* @return string
@@ -279,9 +297,9 @@ abstract class Profiler {
* @return array List of method entries arrays, each having:
* - name : method name
* - calls : the number of invoking calls
- * - real : real time ellapsed (ms)
+ * - real : real time elapsed (ms)
* - %real : percent real time
- * - cpu : CPU time ellapsed (ms)
+ * - cpu : CPU time elapsed (ms)
* - %cpu : percent CPU time
* - memory : memory used (bytes)
* - %memory : percent memory used
diff --git a/includes/profiler/ProfilerFunctions.php b/includes/profiler/ProfilerFunctions.php
index 4984e77d..6c584532 100644
--- a/includes/profiler/ProfilerFunctions.php
+++ b/includes/profiler/ProfilerFunctions.php
@@ -32,7 +32,7 @@
function wfGetRusage() {
if ( !function_exists( 'getrusage' ) ) {
return false;
- } elseif ( defined ( 'HHVM_VERSION' ) ) {
+ } elseif ( defined( 'HHVM_VERSION' ) ) {
return getrusage( 2 /* RUSAGE_THREAD */ );
} else {
return getrusage( 0 /* RUSAGE_SELF */ );
diff --git a/includes/profiler/ProfilerStub.php b/includes/profiler/ProfilerStub.php
index 244b4e4b..3fe9cddb 100644
--- a/includes/profiler/ProfilerStub.php
+++ b/includes/profiler/ProfilerStub.php
@@ -46,4 +46,7 @@ class ProfilerStub extends Profiler {
public function logData() {
}
+
+ public function logDataPageOutputOnly() {
+ }
}
diff --git a/includes/profiler/ProfilerXhprof.php b/includes/profiler/ProfilerXhprof.php
index f36cdc1a..5f7fc002 100644
--- a/includes/profiler/ProfilerXhprof.php
+++ b/includes/profiler/ProfilerXhprof.php
@@ -40,12 +40,8 @@
*
* To restrict the functions for which profiling data is collected, you can
* use either a whitelist ($wgProfiler['include']) or a blacklist
- * ($wgProfiler['exclude']) containing an array of function names. The
- * blacklist functionality is built into HHVM and will completely exclude the
- * named functions from profiling collection. The whitelist is implemented by
- * Xhprof class which will filter the data collected by XHProf before reporting.
- * See documentation for the Xhprof class and the XHProf extension for
- * additional information.
+ * ($wgProfiler['exclude']) containing an array of function names.
+ * Shell-style patterns are also accepted.
*
* @author Bryan Davis <bd808@wikimedia.org>
* @copyright © 2014 Bryan Davis and Wikimedia Foundation.
@@ -77,7 +73,8 @@ class ProfilerXhprof extends Profiler {
}
public function scopedProfileIn( $section ) {
- return $this->sprofiler->scopedProfileIn( $section );
+ $key = 'section.' . ltrim( $section, '.' );
+ return $this->sprofiler->scopedProfileIn( $key );
}
/**
@@ -86,12 +83,43 @@ class ProfilerXhprof extends Profiler {
public function close() {
}
+ /**
+ * Check if a function or section should be excluded from the output.
+ *
+ * @param string $name Function or section name.
+ * @return bool
+ */
+ private function shouldExclude( $name ) {
+ if ( $name === '-total' ) {
+ return true;
+ }
+ if ( !empty( $this->params['include'] ) ) {
+ foreach ( $this->params['include'] as $pattern ) {
+ if ( fnmatch( $pattern, $name, FNM_NOESCAPE ) ) {
+ return false;
+ }
+ }
+ return true;
+ }
+ if ( !empty( $this->params['exclude'] ) ) {
+ foreach ( $this->params['exclude'] as $pattern ) {
+ if ( fnmatch( $pattern, $name, FNM_NOESCAPE ) ) {
+ return true;
+ }
+ }
+ }
+ return false;
+ }
+
public function getFunctionStats() {
$metrics = $this->xhprof->getCompleteMetrics();
$profile = array();
$main = null; // units in ms
foreach ( $metrics as $fname => $stats ) {
+ if ( $this->shouldExclude( $fname ) ) {
+ continue;
+ }
// Convert elapsed times from μs to ms to match interface
$entry = array(
'name' => $fname,
@@ -113,8 +141,7 @@ class ProfilerXhprof extends Profiler {
// Merge in all of the custom profile sections
foreach ( $this->sprofiler->getFunctionStats() as $stats ) {
- if ( $stats['name'] === '-total' ) {
- // Discard section profiler running totals
+ if ( $this->shouldExclude( $stats['name'] ) ) {
continue;
}
diff --git a/includes/profiler/SectionProfiler.php b/includes/profiler/SectionProfiler.php
index 245022df..63940bc9 100644
--- a/includes/profiler/SectionProfiler.php
+++ b/includes/profiler/SectionProfiler.php
@@ -89,9 +89,9 @@ class SectionProfiler {
* @return array List of method entries arrays, each having:
* - name : method name
* - calls : the number of invoking calls
- * - real : real time ellapsed (ms)
+ * - real : real time elapsed (ms)
* - %real : percent real time
- * - cpu : real time ellapsed (ms)
+ * - cpu : real time elapsed (ms)
* - %cpu : percent real time
* - memory : memory used (bytes)
* - %memory : percent memory used
@@ -451,15 +451,14 @@ class SectionProfiler {
}
/**
- * Get the initial time of the request, based either on $wgRequestTime or
- * $wgRUstart. Will return null if not able to find data.
+ * Get the initial time of the request, based on getrusage()
*
* @param string|bool $metric Metric to use, with the following possibilities:
* - user: User CPU time (without system calls)
* - cpu: Total CPU time (user and system calls)
* - wall (or any other string): elapsed time
* - false (default): will fall back to default metric
- * @return float|null
+ * @return float
*/
protected function getTime( $metric = 'wall' ) {
if ( $metric === 'cpu' || $metric === 'user' ) {
diff --git a/includes/profiler/TransactionProfiler.php b/includes/profiler/TransactionProfiler.php
index f02d66f8..46d6119b 100644
--- a/includes/profiler/TransactionProfiler.php
+++ b/includes/profiler/TransactionProfiler.php
@@ -25,6 +25,7 @@
use Psr\Log\LoggerInterface;
use Psr\Log\LoggerAwareInterface;
use Psr\Log\NullLogger;
+
/**
* Helper class that detects high-contention DB queries via profiling calls
*
@@ -52,11 +53,13 @@ class TransactionProfiler implements LoggerAwareInterface {
);
/** @var array */
protected $expect = array(
- 'writes' => INF,
- 'queries' => INF,
- 'conns' => INF,
- 'masterConns' => INF,
- 'maxAffected' => INF
+ 'writes' => INF,
+ 'queries' => INF,
+ 'conns' => INF,
+ 'masterConns' => INF,
+ 'maxAffected' => INF,
+ 'readQueryTime' => INF,
+ 'writeQueryTime' => INF
);
/** @var array */
protected $expectBy = array();
@@ -77,7 +80,7 @@ class TransactionProfiler implements LoggerAwareInterface {
/**
* Set performance expectations
*
- * With conflicting expect, the most specific ones will be used
+ * With conflicting expectations, the most narrow ones will be used
*
* @param string $event (writes,queries,conns,mConns)
* @param integer $value Maximum count of the event
@@ -94,6 +97,21 @@ class TransactionProfiler implements LoggerAwareInterface {
}
/**
+ * Set multiple performance expectations
+ *
+ * With conflicting expectations, the most narrow ones will be used
+ *
+ * @param array $expects Map of (event => limit)
+ * @param $fname
+ * @since 1.26
+ */
+ public function setExpectations( array $expects, $fname ) {
+ foreach ( $expects as $event => $value ) {
+ $this->setExpectation( $event, $value, $fname );
+ }
+ }
+
+ /**
* Reset performance expectations and hit counters
*
* @since 1.25
@@ -170,7 +188,8 @@ class TransactionProfiler implements LoggerAwareInterface {
$elapsed = ( $eTime - $sTime );
if ( $isWrite && $n > $this->expect['maxAffected'] ) {
- $this->logger->info( "Query affected $n row(s):\n" . $query . "\n" . wfBacktrace( true ) );
+ $this->logger->info( "Query affected $n row(s):\n" . $query . "\n" .
+ wfBacktrace( true ) );
}
// Report when too many writes/queries happen...
@@ -180,6 +199,13 @@ class TransactionProfiler implements LoggerAwareInterface {
if ( $isWrite && $this->hits['writes']++ == $this->expect['writes'] ) {
$this->reportExpectationViolated( 'writes', $query );
}
+ // Report slow queries...
+ if ( !$isWrite && $elapsed > $this->expect['readQueryTime'] ) {
+ $this->reportExpectationViolated( 'readQueryTime', $query );
+ }
+ if ( $isWrite && $elapsed > $this->expect['writeQueryTime'] ) {
+ $this->reportExpectationViolated( 'writeQueryTime', $query );
+ }
if ( !$this->dbTrxHoldingLocks ) {
// Short-circuit
@@ -220,13 +246,23 @@ class TransactionProfiler implements LoggerAwareInterface {
* @param string $server DB server
* @param string $db DB name
* @param string $id ID string of transaction
+ * @param float $writeTime Time spent in write queries
*/
- public function transactionWritingOut( $server, $db, $id ) {
+ public function transactionWritingOut( $server, $db, $id, $writeTime = 0.0 ) {
$name = "{$server} ({$db}) (TRX#$id)";
if ( !isset( $this->dbTrxMethodTimes[$name] ) ) {
$this->logger->info( "Detected no transaction for '$name' - out of sync." );
return;
}
+
+ $slow = false;
+
+ // Warn if too much time was spend writing...
+ if ( $writeTime > $this->expect['writeQueryTime'] ) {
+ $this->reportExpectationViolated( 'writeQueryTime',
+ "[transaction $id writes to {$server} ({$db})]" );
+ $slow = true;
+ }
// Fill in the last non-query period...
$lastQuery = end( $this->dbTrxMethodTimes[$name] );
if ( $lastQuery ) {
@@ -237,7 +273,6 @@ class TransactionProfiler implements LoggerAwareInterface {
}
}
// Check for any slow queries or non-query periods...
- $slow = false;
foreach ( $this->dbTrxMethodTimes[$name] as $info ) {
$elapsed = ( $info[2] - $info[1] );
if ( $elapsed >= $this->dbLockThreshold ) {
@@ -268,7 +303,8 @@ class TransactionProfiler implements LoggerAwareInterface {
$n = $this->expect[$expect];
$by = $this->expectBy[$expect];
$this->logger->info(
- "[{$wgRequest->getMethod()}] Expectation ($expect <= $n) by $by not met:\n$query\n" . wfBacktrace( true )
+ "[{$wgRequest->getMethod()}] Expectation ($expect <= $n) by $by not met:\n$query\n" .
+ wfBacktrace( true )
);
}
}
diff --git a/includes/profiler/output/ProfilerOutputDump.php b/includes/profiler/output/ProfilerOutputDump.php
index bf4b85c2..09f56887 100644
--- a/includes/profiler/output/ProfilerOutputDump.php
+++ b/includes/profiler/output/ProfilerOutputDump.php
@@ -45,7 +45,11 @@ class ProfilerOutputDump extends ProfilerOutput {
public function log( array $stats ) {
$data = $this->collector->getRawData();
- $filename = sprintf( "%s/%s.%s%s", $this->params['outputDir'], uniqid(), $this->collector->getProfileID(), $this->suffix );
+ $filename = sprintf( "%s/%s.%s%s",
+ $this->params['outputDir'],
+ uniqid(),
+ $this->collector->getProfileID(),
+ $this->suffix );
file_put_contents( $filename, serialize( $data ) );
}
}
diff --git a/includes/profiler/output/ProfilerOutputStats.php b/includes/profiler/output/ProfilerOutputStats.php
index ef6ef7c9..52aa54ac 100644
--- a/includes/profiler/output/ProfilerOutputStats.php
+++ b/includes/profiler/output/ProfilerOutputStats.php
@@ -37,13 +37,11 @@ class ProfilerOutputStats extends ProfilerOutput {
* @param array $stats
*/
public function log( array $stats ) {
+ $prefix = isset( $this->params['prefix'] ) ? $this->params['prefix'] : '';
$contextStats = $this->collector->getContext()->getStats();
foreach ( $stats as $stat ) {
- // Sanitize the key
- $key = str_replace( '::', '.', $stat['name'] );
- $key = preg_replace( '/[^a-z.]+/i', '_', $key );
- $key = trim( $key, '_.' );
+ $key = "{$prefix}.{$stat['name']}";
// Convert fractional seconds to whole milliseconds
$cpu = round( $stat['cpu'] * 1000 );
diff --git a/includes/profiler/output/ProfilerOutputText.php b/includes/profiler/output/ProfilerOutputText.php
index 67527798..dc24f181 100644
--- a/includes/profiler/output/ProfilerOutputText.php
+++ b/includes/profiler/output/ProfilerOutputText.php
@@ -35,7 +35,7 @@ class ProfilerOutputText extends ProfilerOutput {
parent::__construct( $collector, $params );
$this->thresholdMs = isset( $params['thresholdMs'] )
? $params['thresholdMs']
- : .25;
+ : 1.0;
}
public function log( array $stats ) {
if ( $this->collector->getTemplated() ) {
diff --git a/includes/profiler/output/ProfilerOutputUdp.php b/includes/profiler/output/ProfilerOutputUdp.php
index 7da03c11..a5626779 100644
--- a/includes/profiler/output/ProfilerOutputUdp.php
+++ b/includes/profiler/output/ProfilerOutputUdp.php
@@ -23,7 +23,7 @@
/**
* ProfilerSimpleUDP class, that sends out messages for 'udpprofile' daemon
- * (see http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile)
+ * (see https://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile)
*
* @ingroup Profiler
* @since 1.25
generated by cgit v1.2.3-54-g00ecf (git 2.45.2) at 2024-11-05 22:01:18 +0000