jenkins-bot has submitted this change and it was merged. Change subject: Backport ProfilerOutputStats ......................................................................
Backport ProfilerOutputStats Cherry-picks the following changes from master: * I7e07e22ea: Make WebRequest objects time-aware * Icf644ad34: Introduce ProfilerOutputStats * Ib3585303b: Follow-up to Icf644ad34: Introduce ProfilerOutputStats Change-Id: I6cc22664b60b34d699d7e8ea71d55eaa22ae61fb --- M autoload.php M includes/DefaultSettings.php M includes/GlobalFunctions.php M includes/WebRequest.php M includes/WebStart.php M includes/profiler/Profiler.php M includes/profiler/ProfilerStub.php A includes/profiler/output/ProfilerOutputStats.php 8 files changed, 198 insertions(+), 53 deletions(-) Approvals: Catrope: Looks good to me, approved jenkins-bot: Verified diff --git a/autoload.php b/autoload.php index 892a1f7..aae272b 100644 --- a/autoload.php +++ b/autoload.php @@ -911,6 +911,7 @@ 'ProfilerOutput' => __DIR__ . '/includes/profiler/output/ProfilerOutput.php', 'ProfilerOutputDb' => __DIR__ . '/includes/profiler/output/ProfilerOutputDb.php', 'ProfilerOutputDump' => __DIR__ . '/includes/profiler/output/ProfilerOutputDump.php', + 'ProfilerOutputStats' => __DIR__ . '/includes/profiler/output/ProfilerOutputStats.php', 'ProfilerOutputText' => __DIR__ . '/includes/profiler/output/ProfilerOutputText.php', 'ProfilerOutputUdp' => __DIR__ . '/includes/profiler/output/ProfilerOutputUdp.php', 'ProfilerSectionOnly' => __DIR__ . '/includes/profiler/ProfilerSectionOnly.php', diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php index ae8de0e..79c83f9 100644 --- a/includes/DefaultSettings.php +++ b/includes/DefaultSettings.php @@ -5413,6 +5413,7 @@ /** * Only record profiling info for pages that took longer than this + * @deprecated since 1.25: set $wgProfiler['threshold'] instead. */ $wgProfileLimit = 0.0; diff --git a/includes/GlobalFunctions.php b/includes/GlobalFunctions.php index 47e7a15..0995f8c 100644 --- a/includes/GlobalFunctions.php +++ b/includes/GlobalFunctions.php @@ -1245,10 +1245,15 @@ * @todo document */ function wfLogProfilingData() { - global $wgRequestTime, $wgDebugLogGroups, $wgDebugRawPage; - global $wgProfileLimit, $wgUser, $wgRequest; + global $wgDebugLogGroups, $wgDebugRawPage; $context = RequestContext::getMain(); + $request = $context->getRequest(); + + $profiler = Profiler::instance(); + $profiler->setContext( $context ); + $profiler->logData(); + $config = $context->getConfig(); if ( $config->has( 'StatsdServer' ) ) { $statsdServer = explode( ':', $config->get( 'StatsdServer' ) ); @@ -1259,21 +1264,10 @@ $statsdClient->send( $context->getStats()->getBuffer() ); } - $profiler = Profiler::instance(); - # Profiling must actually be enabled... if ( $profiler instanceof ProfilerStub ) { return; } - - // Get total page request time and only show pages that longer than - // $wgProfileLimit time (default is 0) - $elapsed = microtime( true ) - $wgRequestTime; - if ( $elapsed <= $wgProfileLimit ) { - return; - } - - $profiler->logData(); if ( isset( $wgDebugLogGroups['profileoutput'] ) && $wgDebugLogGroups['profileoutput'] === false @@ -1285,7 +1279,7 @@ return; } - $ctx = array( 'elapsed' => $elapsed ); + $ctx = array( 'elapsed' => $request->getElapsedTime() ); if ( !empty( $_SERVER['HTTP_X_FORWARDED_FOR'] ) ) { $ctx['forwarded_for'] = $_SERVER['HTTP_X_FORWARDED_FOR']; } @@ -1304,16 +1298,13 @@ // Don't load $wgUser at this late stage just for statistics purposes // @todo FIXME: We can detect some anons even if it is not loaded. // See User::getId() - if ( $wgUser->isItemLoaded( 'id' ) && $wgUser->isAnon() ) { - $ctx['anon'] = true; - } else { - $ctx['anon'] = false; - } + $user = $context->getUser(); + $ctx['anon'] = $user->isItemLoaded( 'id' ) && $user->isAnon(); // Command line script uses a FauxRequest object which does not have // any knowledge about an URL and throw an exception instead. try { - $ctx['url'] = urldecode( $wgRequest->getRequestURL() ); + $ctx['url'] = urldecode( $request->getRequestURL() ); } catch ( Exception $ignored ) { // no-op } diff --git a/includes/WebRequest.php b/includes/WebRequest.php index f86a454..93cc04e 100644 --- a/includes/WebRequest.php +++ b/includes/WebRequest.php @@ -51,15 +51,20 @@ private $ip; /** + * The timestamp of the start of the request, with microsecond precision. + * @var float + */ + protected $requestTime; + + /** * Cached URL protocol * @var string */ protected $protocol; public function __construct() { - if ( function_exists( 'get_magic_quotes_gpc' ) && get_magic_quotes_gpc() ) { - throw new MWException( "MediaWiki does not function when magic quotes are enabled." ); - } + $this->requestTime = isset( $_SERVER['REQUEST_TIME_FLOAT'] ) + ? $_SERVER['REQUEST_TIME_FLOAT'] : microtime( true ); // POST overrides GET data // We don't use $_REQUEST here to avoid interference from cookies... @@ -214,6 +219,17 @@ } else { return 'http'; } + } + + /** + * Get the number of seconds to have elapsed since request start, + * in fractional seconds, with microsecond resolution. + * + * @return float + * @since 1.25 + */ + public function getElapsedTime() { + return microtime( true ) - $this->requestTime; } /** @@ -1274,6 +1290,8 @@ public function __construct( $data = array(), $wasPosted = false, $session = null, $protocol = 'http' ) { + $this->requestTime = microtime( true ); + if ( is_array( $data ) ) { $this->data = $data; } else { @@ -1497,4 +1515,8 @@ public function getProtocol() { return $this->base->getProtocol(); } + + public function getElapsedTime() { + return $this->base->getElapsedTime(); + } } diff --git a/includes/WebStart.php b/includes/WebStart.php index da4bc87..9c71f3e 100644 --- a/includes/WebStart.php +++ b/includes/WebStart.php @@ -34,12 +34,30 @@ . 'for help on how to disable it.' ); } +if ( function_exists( 'get_magic_quotes_gpc' ) && get_magic_quotes_gpc() ) { + die( 'MediaWiki does not function when magic quotes are enabled. ' + . 'Please see the <a href="https://php.net/manual/security.magicquotes.disabling.php">PHP Manual</a> ' + . 'for help on how to disable magic quotes.' ); +} + + # bug 15461: Make IE8 turn off content sniffing. Everybody else should ignore this # We're adding it here so that it's *always* set, even for alternate entry # points and when $wgOut gets disabled or overridden. header( 'X-Content-Type-Options: nosniff' ); -$wgRequestTime = microtime( true ); +# Approximate $_SERVER['REQUEST_TIME_FLOAT'] for PHP<5.4 +if ( !isset( $_SERVER['REQUEST_TIME_FLOAT'] ) ) { + $_SERVER['REQUEST_TIME_FLOAT'] = microtime( true ); +} + +/** + * @var float Request start time as fractional seconds since epoch + * @deprecated since 1.25; use $_SERVER['REQUEST_TIME_FLOAT'] or + * WebRequest::getElapsedTime() instead. + */ +$wgRequestTime = $_SERVER['REQUEST_TIME_FLOAT']; + unset( $IP ); # Valid web server entry point, enable includes. diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index 69470fd..210041a 100644 --- a/includes/profiler/Profiler.php +++ b/includes/profiler/Profiler.php @@ -35,6 +35,8 @@ protected $templated = false; /** @var array All of the params passed from $wgProfiler */ protected $params = array(); + /** @var IContextSource Current request context */ + protected $context = null; /** @var TransactionProfiler */ protected $trxProfiler; @@ -47,6 +49,7 @@ 'text' => 'ProfilerOutputText', 'udp' => 'ProfilerOutputUdp', 'dump' => 'ProfilerOutputDump', + 'stats' => 'ProfilerOutputStats', ); /** @var Profiler */ @@ -69,17 +72,28 @@ */ final public static function instance() { if ( self::$instance === null ) { - global $wgProfiler; + global $wgProfiler, $wgProfileLimit; + + $params = array( + 'class' => 'ProfilerStub', + 'sampling' => 1, + 'threshold' => $wgProfileLimit, + 'output' => array(), + ); if ( is_array( $wgProfiler ) ) { - $class = isset( $wgProfiler['class'] ) ? $wgProfiler['class'] : 'ProfilerStub'; - $factor = isset( $wgProfiler['sampling'] ) ? $wgProfiler['sampling'] : 1; - if ( PHP_SAPI === 'cli' || mt_rand( 0, $factor - 1 ) != 0 ) { - $class = 'ProfilerStub'; - } - self::$instance = new $class( $wgProfiler ); - } else { - self::$instance = new ProfilerStub( array() ); + $params = array_merge( $params, $wgProfiler ); } + + $inSample = mt_rand( 0, $params['sampling'] - 1 ) === 0; + if ( PHP_SAPI === 'cli' || !$inSample ) { + $params['class'] = 'ProfilerStub'; + } + + if ( !is_array( $params['output'] ) ) { + $params['output'] = array( $params['output'] ); + } + + self::$instance = new $params['class']( $params ); } return self::$instance; } @@ -114,6 +128,32 @@ return wfWikiID(); } else { return $this->profileID; + } + } + + /** + * Sets the context for this Profiler + * + * @param IContextSource $context + * @since 1.25 + */ + public function setContext( $context ) { + $this->context = $context; + } + + /** + * Gets the context for this Profiler + * + * @return IContextSource + * @since 1.25 + */ + public function getContext() { + if ( $this->context ) { + return $this->context; + } else { + wfDebug( __METHOD__ . " called and \$context is null. " . + "Return RequestContext::getMain(); for sanity\n" ); + return RequestContext::getMain(); } } @@ -152,37 +192,49 @@ abstract public function close(); /** - * Log the data to some store or even the page output + * Get all usable outputs. * * @throws MWException + * @return array Array of ProfilerOutput instances. + * @since 1.25 + */ + private function getOutputs() { + $outputs = array(); + foreach ( $this->params['output'] as $outputType ) { + if ( !isset( self::$outputTypes[$outputType] ) ) { + throw new MWException( "'$outputType' is an invalid output type" ); + } + $outputClass = self::$outputTypes[$outputType]; + $outputInstance = new $outputClass( $this, $this->params ); + if ( $outputInstance->canUse() ) { + $outputs[] = $outputInstance; + } + } + return $outputs; + } + + /** + * Log the data to some store or even the page output + * * @since 1.25 */ public function logData() { - $output = isset( $this->params['output'] ) ? $this->params['output'] : null; + $request = $this->getContext()->getRequest(); - if ( !$output || $this instanceof ProfilerStub ) { - // return early when no output classes defined or we're a stub + $timeElapsed = $request->getElapsedTime(); + $timeElapsedThreshold = $this->params['threshold']; + if ( $timeElapsed <= $timeElapsedThreshold ) { return; } - if ( !is_array( $output ) ) { - $output = array( $output ); + $outputs = $this->getOutputs(); + if ( !$outputs ) { + return; } - $stats = null; - foreach ( $output as $outType ) { - if ( !isset( self::$outputTypes[$outType] ) ) { - throw new MWException( "'$outType' is an invalid output type" ); - } - $class = self::$outputTypes[$outType]; - /** @var ProfilerOutput $profileOut */ - $profileOut = new $class( $this, $this->params ); - if ( $profileOut->canUse() ) { - if ( is_null( $stats ) ) { - $stats = $this->getFunctionStats(); - } - $profileOut->log( $stats ); - } + $stats = $this->getFunctionStats(); + foreach ( $outputs as $output ) { + $output->log( $stats ); } } diff --git a/includes/profiler/ProfilerStub.php b/includes/profiler/ProfilerStub.php index 5580f94..527ef1f 100644 --- a/includes/profiler/ProfilerStub.php +++ b/includes/profiler/ProfilerStub.php @@ -43,4 +43,7 @@ public function getCurrentSection() { return ''; } + + public function logData() { + } } diff --git a/includes/profiler/output/ProfilerOutputStats.php b/includes/profiler/output/ProfilerOutputStats.php new file mode 100644 index 0000000..ef6ef7c --- /dev/null +++ b/includes/profiler/output/ProfilerOutputStats.php @@ -0,0 +1,57 @@ +<?php +/** + * ProfilerOutput class that flushes profiling data to the profiling + * context's stats buffer. + * + * 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 + */ + +/** + * ProfilerOutput class that flushes profiling data to the profiling + * context's stats buffer. + * + * @ingroup Profiler + * @since 1.25 + */ +class ProfilerOutputStats extends ProfilerOutput { + + /** + * Flush profiling data to the current profiling context's stats buffer. + * + * @param array $stats + */ + public function log( array $stats ) { + $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, '_.' ); + + // Convert fractional seconds to whole milliseconds + $cpu = round( $stat['cpu'] * 1000 ); + $real = round( $stat['real'] * 1000 ); + + $contextStats->increment( "{$key}.calls" ); + $contextStats->timing( "{$key}.cpu", $cpu ); + $contextStats->timing( "{$key}.real", $real ); + } + } +} -- To view, visit https://gerrit.wikimedia.org/r/201443 To unsubscribe, visit https://gerrit.wikimedia.org/r/settings Gerrit-MessageType: merged Gerrit-Change-Id: I6cc22664b60b34d699d7e8ea71d55eaa22ae61fb Gerrit-PatchSet: 1 Gerrit-Project: mediawiki/core Gerrit-Branch: wmf/1.25wmf23 Gerrit-Owner: Ori.livneh <o...@wikimedia.org> Gerrit-Reviewer: Catrope <roan.katt...@gmail.com> Gerrit-Reviewer: Daniel Friesen <dan...@nadir-seen-fire.com> Gerrit-Reviewer: TTO <at.li...@live.com.au> Gerrit-Reviewer: jenkins-bot <> _______________________________________________ MediaWiki-commits mailing list MediaWiki-commits@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits