Merge commit 'fa89acd'

# Conflicts:
#	.gitignore
#	extensions/ArchInterWiki.sql

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