From: Ori Livneh Date: Wed, 1 Apr 2015 23:30:16 +0000 (-0700) Subject: Introduce ProfilerOutputStats X-Git-Tag: 1.31.0-rc.0~11884 X-Git-Url: http://git.cyclocoop.org//%22%22._DIR_PLUGIN_FULLCALENDAR.%22prive/themes/spip/images/event_edit.png/%22?a=commitdiff_plain;h=1b6f70089d47facd887ef3e1708780eff56c2465;p=lhc%2Fweb%2Fwiklou.git Introduce ProfilerOutputStats * Associate Profiler objects with a request context by adding a $context property with a getter and a setter. * Introduce ProfilerOutputStats, which writes profiling data to the stats buffer associated with the current request context. * Make it the Profiler class's responsibility to enforce $wgProfilerLimit. * Deprecate $wgProfilerLimit in favor of the (more aptly named, IMO) $wgProfiler['threshold'] config setting. * Tidy up Profiler instance creation code in Profiler::instance(). * Add Profiler::getOutputs, which returns an array of ProfilerOutput instances which are configured for the current profiler and whose canUse() method returns true. * Make ProfilerStub not log by creating a stub ProfilerStub::logData() method which does not call the parent. Previously the parent class checked if $this was an instance of ProfilerStub and returned early if so. Task: T90623 Task: T85641 Change-Id: Icf644ad3435c1f30d0a49957a97b481808a3153d --- diff --git a/autoload.php b/autoload.php index dcd787972f..da661a2eeb 100644 --- a/autoload.php +++ b/autoload.php @@ -910,6 +910,7 @@ $wgAutoloadLocalClasses = array( '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 84dc3aa7b8..5e81d0f364 100644 --- a/includes/DefaultSettings.php +++ b/includes/DefaultSettings.php @@ -5423,6 +5423,7 @@ $wgDeprecationReleaseLimit = false; /** * 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 70473ca77b..24a3c332db 100644 --- a/includes/GlobalFunctions.php +++ b/includes/GlobalFunctions.php @@ -1237,10 +1237,15 @@ function wfErrorLog( $text, $file, array $context = array() ) { * @todo document */ function wfLogProfilingData() { - global $wgDebugLogGroups, $wgDebugRawPage, $wgProfileLimit; + 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' ) ); @@ -1251,22 +1256,11 @@ function wfLogProfilingData() { $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 = $request->getElapsedTime(); - if ( $elapsed <= $wgProfileLimit ) { - return; - } - - $profiler->logData(); - if ( isset( $wgDebugLogGroups['profileoutput'] ) && $wgDebugLogGroups['profileoutput'] === false ) { @@ -1277,7 +1271,7 @@ function wfLogProfilingData() { 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']; } diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index 1c9824ab9c..0718875327 100644 --- a/includes/profiler/Profiler.php +++ b/includes/profiler/Profiler.php @@ -35,6 +35,8 @@ abstract class Profiler { 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 @@ abstract class Profiler { 'text' => 'ProfilerOutputText', 'udp' => 'ProfilerOutputUdp', 'dump' => 'ProfilerOutputDump', + 'context' => 'ProfilerOutputStats', ); /** @var Profiler */ @@ -69,17 +72,28 @@ abstract class Profiler { */ 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; } @@ -117,6 +131,32 @@ abstract class Profiler { } } + /** + * 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(); + } + } + // Kept BC for now, remove when possible public function profileIn( $functionname ) {} public function profileOut( $functionname ) {} @@ -152,37 +192,49 @@ abstract class Profiler { 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 1d04536ee3..244b4e4b39 100644 --- a/includes/profiler/ProfilerStub.php +++ b/includes/profiler/ProfilerStub.php @@ -43,4 +43,7 @@ class ProfilerStub extends Profiler { 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 0000000000..ef6ef7c918 --- /dev/null +++ b/includes/profiler/output/ProfilerOutputStats.php @@ -0,0 +1,57 @@ +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 ); + } + } +}