From: Aaron Schulz Date: Wed, 12 Nov 2014 20:28:32 +0000 (-0800) Subject: Move request-only template profiling to an always-on parser report X-Git-Tag: 1.31.0-rc.0~13318 X-Git-Url: https://git.heureux-cyclage.org/?p=lhc%2Fweb%2Fwiklou.git;a=commitdiff_plain;h=0bfa6b6264b554d89e9ebb65e54d568d427badd4;hp=a4b1130772122455473c47217430d0acfe5e5c26 Move request-only template profiling to an always-on parser report Change-Id: I0660c8d6cac0dadab648eac9736504b7939320f3 --- diff --git a/includes/AutoLoader.php b/includes/AutoLoader.php index 8a9dd1fa62..92eb4c8805 100644 --- a/includes/AutoLoader.php +++ b/includes/AutoLoader.php @@ -888,6 +888,7 @@ $wgAutoloadLocalClasses = array( 'ProfilerStub' => 'includes/profiler/ProfilerStub.php', 'ProfilerXhprof' => 'includes/profiler/ProfilerXhprof.php', 'ProfileSection' => 'includes/profiler/ProfileSection.php', + 'SectionProfiler' => 'includes/profiler/SectionProfiler.php', 'TransactionProfiler' => 'includes/profiler/TransactionProfiler.php', # includes/rcfeed diff --git a/includes/parser/Parser.php b/includes/parser/Parser.php index cd804b5252..d310836498 100644 --- a/includes/parser/Parser.php +++ b/includes/parser/Parser.php @@ -224,6 +224,9 @@ class Parser { */ public $mInParse = false; + /** @var SectionProfiler */ + protected $mProfiler; + /** * @param array $conf */ @@ -365,6 +368,8 @@ class Parser { $this->mPreprocessor = null; } + $this->mProfiler = new SectionProfiler(); + wfRunHooks( 'ParserClearState', array( &$this ) ); wfProfileOut( __METHOD__ ); } @@ -526,6 +531,19 @@ class Parser { $limitReport = str_replace( array( '-', '&' ), array( '‐', '&' ), $limitReport ); $text .= "\n\n"; + // Add on template profiling data + $dataByFunc = $this->mProfiler->getFunctionStats(); + uasort( $dataByFunc, function( $a, $b ) { + return $a['elapsed'] < $b['elapsed']; // descending order + } ); + $profileReport = "Top template expansion time report (%,ms,calls,template)\n"; + foreach ( array_slice( $dataByFunc, 0, 10 ) as $item ) { + $profileReport .= sprintf( "%6.2f%% %3.6f %6d - %s\n", + $item['percent'], $item['elapsed'], $item['calls'], + htmlspecialchars($item['name'] ) ); + } + $text .= "\n\n"; + if ( $this->mGeneratedPPNodeCount > $this->mOptions->getMaxGeneratedPPNodeCount() / 10 ) { wfDebugLog( 'generated-pp-node-count', $this->mGeneratedPPNodeCount . ' ' . $this->mTitle->getPrefixedDBkey() ); @@ -3473,7 +3491,7 @@ class Parser { $args = ( null == $piece['parts'] ) ? array() : $piece['parts']; wfProfileOut( __METHOD__ . '-setup' ); - $titleProfileIn = null; // profile templates + $profileSection = null; // profile templates # SUBST wfProfileIn( __METHOD__ . '-modifiers' ); @@ -3594,11 +3612,7 @@ class Parser { # Load from database if ( !$found && $title ) { - if ( !Profiler::instance()->isPersistent() ) { - # Too many unique items can kill profiling DBs/collectors - $titleProfileIn = __METHOD__ . "-title-" . $title->getPrefixedDBkey(); - wfProfileIn( $titleProfileIn ); // template in - } + $profileSection = $this->mProfiler->scopedProfileIn( $title->getPrefixedDBkey() ); wfProfileIn( __METHOD__ . '-loadtpl' ); if ( !$title->isExternal() ) { if ( $title->isSpecialPage() @@ -3680,8 +3694,8 @@ class Parser { # Recover the source wikitext and return it if ( !$found ) { $text = $frame->virtualBracketedImplode( '{{', '|', '}}', $titleWithSpaces, $args ); - if ( $titleProfileIn ) { - wfProfileOut( $titleProfileIn ); // template out + if ( $profileSection ) { + $this->mProfiler->scopedProfileOut( $profileSection ); } wfProfileOut( __METHOD__ ); return array( 'object' => $text ); @@ -3707,8 +3721,8 @@ class Parser { $isLocalObj = false; } - if ( $titleProfileIn ) { - wfProfileOut( $titleProfileIn ); // template out + if ( $profileSection ) { + $this->mProfiler->scopedProfileOut( $profileSection ); } # Replace raw HTML by a placeholder diff --git a/includes/profiler/ProfilerStandard.php b/includes/profiler/ProfilerStandard.php index 4825f7acbf..d75ae9e3c4 100644 --- a/includes/profiler/ProfilerStandard.php +++ b/includes/profiler/ProfilerStandard.php @@ -47,11 +47,14 @@ class ProfilerStandard extends Profiler { /** * @param array $params + * - initTotal : set to false to omit -total/-setup entries (which use request start time) */ public function __construct( array $params ) { parent::__construct( $params ); - $this->addInitialStack(); + if ( !isset( $params['initTotal'] ) || $params['initTotal'] ) { + $this->addInitialStack(); + } } /** diff --git a/includes/profiler/SectionProfiler.php b/includes/profiler/SectionProfiler.php new file mode 100644 index 0000000000..a418d308c3 --- /dev/null +++ b/includes/profiler/SectionProfiler.php @@ -0,0 +1,108 @@ +profiler = new ProfilerStandard( array( 'initTotal' => false ) ); + } + + /** + * @param string $section + * @return ScopedCallback + */ + public function scopedProfileIn( $section ) { + $profiler = $this->profiler; + $sc = new ScopedCallback( function() use ( $profiler, $section ) { + $profiler->profileOut( $section ); + } ); + $profiler->profileIn( $section ); + + return $sc; + } + + /** + * @param ScopedCallback $section + */ + public function scopedProfileOut( ScopedCallback &$section ) { + $section = null; + } + + /** + * Get the raw and collated breakdown data for each method + * + * The percent time for each time is based on the current "total" time + * used is based on all methods so far. This method can therefore be + * called several times in between several profiling calls without the + * delays in usage of the profiler skewing the results. A "-total" entry + * is always included in the results. + * + * @return array List of method entries arrays, each having: + * - name : method name + * - calls : the number of method calls + * - elapsed : real time ellapsed (ms) + * - percent : percent real time + * - memory : memory used (bytes) + * - min : min real time of all calls (ms) + * - max : max real time of all calls (ms) + */ + public function getFunctionStats() { + $data = $this->profiler->getRawData(); + + $memoryTotal = 0; + $elapsedTotal = 0; + foreach ( $data as $item ) { + $memoryTotal += $item['memory']; + $elapsedTotal += $item['elapsed']; + } + + foreach ( $data as &$item ) { + $item['percent'] = $item['elapsed'] / $elapsedTotal * 100; + } + unset( $item ); + + $data[] = array( + 'name' => '-total', + 'calls' => 1, + 'elapsed' => $elapsedTotal, + 'percent' => 100, + 'memory' => $memoryTotal, + 'min' => $elapsedTotal, + 'max' => $elapsedTotal + ); + + return $data; + } +}