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 8a9dd1f..92eb4c8 100644 (file)
--- 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 cd804b5..d310836 100644 (file)
--- 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$limitReport-->\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$profileReport-->\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 4825f7a..d75ae9e 100644 (file)
--- 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 (file)
index 0000000..a418d30
--- /dev/null
+++ b/includes/profiler/SectionProfiler.php
@@ -0,0 +1,108 @@
+<?php
+/**
+ * Arbitrary section name based PHP profiling.
+ *
+ * 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
+ * @author Aaron Schulz
+ */
+
+/**
+ * Custom PHP profiler for parser/DB type section names that xhprof/xdebug can't handle
+ *
+ * @TODO: refactor implementation by moving Profiler code to here when non-automatic
+ * profiler support is dropped.
+ *
+ * @since 1.25
+ */
+class SectionProfiler {
+       /** @var ProfilerStandard */
+       protected $profiler;
+
+       public function __construct() {
+               // This does *not* care about PHP request start time
+               $this->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;
+       }
+}