Enable profiling via xhprof
authorBryan Davis <bd808@wikimedia.org>
Mon, 27 Oct 2014 04:27:59 +0000 (22:27 -0600)
committerBryan Davis <bd808@wikimedia.org>
Sat, 8 Nov 2014 18:47:25 +0000 (11:47 -0700)
Add a helper class to assist in collecting profiling information using
XHProf <https://github.com/phacility/xhprof> and a Profiler
implementation to hook it into the existing MediaWiki profiling system.

The Profiler includes support for generating tabular reports similar to
the traditional output of ProfilerSimpleText and ProfilerSimpleTrace or
sending data to a udpprofile daemon as supported by ProfilerSimpleUDP.
It also produces data compatible with the debugging toolbar.

Bug: T759
Change-Id: I16a75cb7636cb5dcef3830d738b2dcd2047d0aaa

includes/AutoLoader.php
includes/libs/RunningStat.php
includes/libs/Xhprof.php [new file with mode: 0644]
includes/profiler/Profiler.php
includes/profiler/ProfilerXhprof.php [new file with mode: 0644]
tests/phpunit/includes/libs/XhprofTest.php [new file with mode: 0644]

index e89e500..ffd361c 100644 (file)
@@ -700,6 +700,7 @@ $wgAutoloadLocalClasses = array(
        'SwiftVirtualRESTService' => 'includes/libs/virtualrest/SwiftVirtualRESTService.php',
        'VirtualRESTService' => 'includes/libs/virtualrest/VirtualRESTService.php',
        'VirtualRESTServiceClient' => 'includes/libs/virtualrest/VirtualRESTServiceClient.php',
+       'Xhprof' => 'includes/libs/Xhprof.php',
        'XmlTypeCheck' => 'includes/libs/XmlTypeCheck.php',
 
        # includes/libs/lessphp
@@ -876,6 +877,7 @@ $wgAutoloadLocalClasses = array(
        'ProfilerSimpleUDP' => 'includes/profiler/ProfilerSimpleUDP.php',
        'ProfilerStandard' => 'includes/profiler/ProfilerStandard.php',
        'ProfilerStub' => 'includes/profiler/ProfilerStub.php',
+       'ProfilerXhprof' => 'includes/profiler/ProfilerXhprof.php',
        'ProfileSection' => 'includes/profiler/ProfileSection.php',
        'TransactionProfiler' => 'includes/profiler/TransactionProfiler.php',
 
index dda5254..f09d101 100644 (file)
@@ -126,7 +126,7 @@ class RunningStat implements Countable {
        }
 
        /**
-        * Get the estimated stanard deviation.
+        * Get the estimated standard deviation.
         *
         * The standard deviation of a statistical population is the square root of
         * its variance. It shows shows how much variation from the mean exists. In
diff --git a/includes/libs/Xhprof.php b/includes/libs/Xhprof.php
new file mode 100644 (file)
index 0000000..1ad01cc
--- /dev/null
@@ -0,0 +1,443 @@
+<?php
+/**
+ * @section LICENSE
+ * 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
+ */
+
+/**
+ * Convenience class for working with XHProf
+ * <https://github.com/phacility/xhprof>. XHProf can be installed as a PECL
+ * package for use with PHP5 (Zend PHP) and is built-in to HHVM 3.3.0.
+ *
+ * @author Bryan Davis <bd808@wikimedia.org>
+ * @copyright © 2014 Bryan Davis and Wikimedia Foundation.
+ * @since 1.25
+ */
+class Xhprof {
+
+       /**
+        * @var array $config
+        */
+       protected $config;
+
+       /**
+        * Hierarchical profiling data returned by xhprof.
+        * @var array $hieraData
+        */
+       protected $hieraData;
+
+       /**
+        * Per-function inclusive data.
+        * @var array $inclusive
+        */
+       protected $inclusive;
+
+       /**
+        * Per-function inclusive and exclusive data.
+        * @var array $complete
+        */
+       protected $complete;
+
+       /**
+        * Configuration data can contain:
+        * - flags:   Optional flags to add additional information to the
+        *            profiling data collected.
+        *            (XHPROF_FLAGS_NO_BUILTINS, XHPROF_FLAGS_CPU,
+        *            XHPROF_FLAGS_MEMORY)
+        * - exclude: Array of function names to exclude from profiling.
+        * - include: Array of function names to include in profiling.
+        * - sort:    Key to sort per-function reports on.
+        *
+        * Note: When running under HHVM, xhprof will always behave as though the
+        * XHPROF_FLAGS_NO_BUILTINS flag has been used unless the
+        * Eval.JitEnableRenameFunction option is enabled for the HHVM process.
+        *
+        * @param array $config
+        */
+       public function __construct( array $config = array() ) {
+               $this->config = array_merge(
+                       array(
+                               'flags' => 0,
+                               'exclude' => array(),
+                               'include' => null,
+                               'sort' => 'wt',
+                       ),
+                       $config
+               );
+
+               xhprof_enable( $this->config['flags'], array(
+                       'ignored_functions' => $this->config['exclude']
+               ) );
+       }
+
+       /**
+        * Stop collecting profiling data.
+        *
+        * Only the first invocation of this method will effect the internal
+        * object state. Subsequent calls will return the data collected by the
+        * initial call.
+        *
+        * @return array Collected profiling data (possibly cached)
+        */
+       public function stop() {
+               if ( $this->hieraData === null ) {
+                       $this->hieraData = $this->pruneData( xhprof_disable() );
+               }
+               return $this->hieraData;
+       }
+
+       /**
+        * Load raw data from a prior run for analysis.
+        * Stops any existing data collection and clears internal caches.
+        *
+        * Any 'include' filters configured for this Xhprof instance will be
+        * enforced on the data as it is loaded. 'exclude' filters will however
+        * not be enforced as they are an XHProf intrinsic behavior.
+        *
+        * @param array $data
+        * @see getRawData()
+        */
+       public function loadRawData( array $data ) {
+               $this->stop();
+               $this->inclusive = null;
+               $this->complete = null;
+               $this->hieraData = $this->pruneData( $data );
+       }
+
+       /**
+        * Get raw data collected by xhprof.
+        *
+        * If data collection has not been stopped yet this method will halt
+        * collection to gather the profiling data.
+        *
+        * Each key in the returned array is an edge label for the call graph in
+        * the form "caller==>callee". There is once special case edge labled
+        * simply "main()" which represents the global scope entry point of the
+        * application.
+        *
+        * XHProf will collect different data depending on the flags that are used:
+        * - ct:    Number of matching events seen.
+        * - wt:    Inclusive elapsed wall time for this event in microseconds.
+        * - cpu:   Inclusive elapsed cpu time for this event in microseconds.
+        *          (XHPROF_FLAGS_CPU)
+        * - mu:    Delta of memory usage from start to end of callee in bytes.
+        *          (XHPROF_FLAGS_MEMORY)
+        * - pmu:   Delta of peak memory usage from start to end of callee in
+        *          bytes. (XHPROF_FLAGS_MEMORY)
+        * - alloc: Delta of amount memory requested from malloc() by the callee,
+        *          in bytes. (XHPROF_FLAGS_MALLOC)
+        * - free:  Delta of amount of memory passed to free() by the callee, in
+        *          bytes. (XHPROF_FLAGS_MALLOC)
+        *
+        * @return array
+        * @see stop()
+        * @see getInclusiveMetrics()
+        * @see getCompleteMetrics()
+        */
+       public function getRawData() {
+               return $this->stop();
+       }
+
+       /**
+        * Convert an xhprof data key into an array of ['parent', 'child']
+        * function names.
+        *
+        * The resulting array is left padded with nulls, so a key
+        * with no parent (eg 'main()') will return [null, 'function'].
+        *
+        * @return array
+        */
+       public static function splitKey( $key ) {
+               return array_pad( explode( '==>', $key, 2 ), -2, null );
+       }
+
+       /**
+        * Remove data for functions that are not included in the 'include'
+        * configuration array.
+        *
+        * @param array $data Raw xhprof data
+        * @return array
+        */
+       protected function pruneData( $data ) {
+               if ( !$this->config['include'] ) {
+                       return $data;
+               }
+
+               $want = array_fill_keys( $this->config['include'], true );
+               $want['main()'] = true;
+
+               $keep = array();
+               foreach ( $data as $key => $stats ) {
+                       list( $parent, $child ) = self::splitKey( $key );
+                       if ( isset( $want[$parent] ) || isset( $want[$child] ) ) {
+                               $keep[$key] = $stats;
+                       }
+               }
+               return $keep;
+       }
+
+       /**
+        * Get the inclusive metrics for each function call. Inclusive metrics
+        * for given function include the metrics for all functions that were
+        * called from that function during the measurement period.
+        *
+        * If data collection has not been stopped yet this method will halt
+        * collection to gather the profiling data.
+        *
+        * See getRawData() for a description of the metric that are returned for
+        * each funcition call. The values for the wt, cpu, mu and pmu metrics are
+        * arrays with these values:
+        * - total: Cumulative value
+        * - min: Minimum value
+        * - mean: Mean (average) value
+        * - max: Maximum value
+        * - variance: Variance (spread) of the values
+        *
+        * @return array
+        * @see getRawData()
+        * @see getCompleteMetrics()
+        */
+       public function getInclusiveMetrics() {
+               if ( $this->inclusive === null ) {
+                       // Make sure we have data to work with
+                       $this->stop();
+
+                       $main = $this->hieraData['main()'];
+                       $hasCpu = isset( $main['cpu'] );
+                       $hasMu = isset( $main['mu'] );
+                       $hasAlloc = isset( $main['alloc'] );
+
+                       $this->inclusive = array();
+                       foreach ( $this->hieraData as $key => $stats ) {
+                               list( $parent, $child ) = self::splitKey( $key );
+                               if ( !isset( $this->inclusive[$child] ) ) {
+                                       $this->inclusive[$child] = array(
+                                               'ct' => 0,
+                                               'wt' => new RunningStat(),
+                                       );
+                                       if ( $hasCpu ) {
+                                               $this->inclusive[$child]['cpu'] = new RunningStat();
+                                       }
+                                       if ( $hasMu ) {
+                                               $this->inclusive[$child]['mu'] = new RunningStat();
+                                               $this->inclusive[$child]['pmu'] = new RunningStat();
+                                       }
+                                       if ( $hasAlloc ) {
+                                               $this->inclusive[$child]['alloc'] = new RunningStat();
+                                               $this->inclusive[$child]['free'] = new RunningStat();
+                                       }
+                               }
+
+                               $this->inclusive[$child]['ct'] += $stats['ct'];
+                               foreach ( $stats as $stat => $value ) {
+                                       if ( $stat === 'ct' ) {
+                                               continue;
+                                       }
+
+                                       if ( !isset( $this->inclusive[$child][$stat] ) ) {
+                                               // Ignore unknown stats
+                                               continue;
+                                       }
+
+                                       for ( $i = 0; $i < $stats['ct']; $i++ ) {
+                                               $this->inclusive[$child][$stat]->push(
+                                                       $value / $stats['ct']
+                                               );
+                                       }
+                               }
+                       }
+
+                       // Convert RunningStat instances to static arrays and add
+                       // percentage stats.
+                       foreach ( $this->inclusive as $func => $stats ) {
+                               foreach ( $stats as $name => $value ) {
+                                       if ( $value instanceof RunningStat ) {
+                                               $total = $value->m1 * $value->n;
+                                               $this->inclusive[$func][$name] = array(
+                                                       'total' => $total,
+                                                       'min' => $value->min,
+                                                       'mean' => $value->m1,
+                                                       'max' => $value->max,
+                                                       'variance' => $value->m2,
+                                                       'percent' => 100 * $total / $main[$name],
+                                               );
+                                       }
+                               }
+                       }
+
+                       uasort( $this->inclusive, self::makeSortFunction(
+                               $this->config['sort'], 'total'
+                       ) );
+               }
+               return $this->inclusive;
+       }
+
+       /**
+        * Get the inclusive and exclusive metrics for each function call.
+        *
+        * If data collection has not been stopped yet this method will halt
+        * collection to gather the profiling data.
+        *
+        * In addition to the normal data contained in the inclusive metrics, the
+        * metrics have an additional 'exclusive' measurement which is the total
+        * minus the totals of all child function calls.
+        *
+        * @return array
+        * @see getRawData()
+        * @see getInclusiveMetrics()
+        */
+       public function getCompleteMetrics() {
+               if ( $this->complete === null ) {
+                       // Start with inclusive data
+                       $this->complete = $this->getInclusiveMetrics();
+
+                       foreach ( $this->complete as $func => $stats ) {
+                               foreach ( $stats as $stat => $value ) {
+                                       if ( $stat === 'ct' ) {
+                                               continue;
+                                       }
+                                       // Initialize exclusive data with inclusive totals
+                                       $this->complete[$func][$stat]['exclusive'] = $value['total'];
+                               }
+                               // Add sapce for call tree information to be filled in later
+                               $this->complete[$func]['calls'] = array();
+                               $this->complete[$func]['subcalls'] = array();
+                       }
+
+                       foreach( $this->hieraData as $key => $stats ) {
+                               list( $parent, $child ) = self::splitKey( $key );
+                               if ( $parent !== null ) {
+                                       // Track call tree information
+                                       $this->complete[$child]['calls'][$parent] = $stats;
+                                       $this->complete[$parent]['subcalls'][$child] = $stats;
+                               }
+
+                               if ( isset( $this->complete[$parent] ) ) {
+                                       // Deduct child inclusive data from exclusive data
+                                       foreach ( $stats as $stat => $value ) {
+                                               if ( $stat === 'ct' ) {
+                                                       continue;
+                                               }
+
+                                               if ( !isset( $this->complete[$parent][$stat] ) ) {
+                                                       // Ignore unknown stats
+                                                       continue;
+                                               }
+
+                                               $this->complete[$parent][$stat]['exclusive'] -= $value;
+                                       }
+                               }
+                       }
+
+                       uasort( $this->complete, self::makeSortFunction(
+                               $this->config['sort'], 'exclusive'
+                       ) );
+               }
+               return $this->complete;
+       }
+
+       /**
+        * Get a list of all callers of a given function.
+        *
+        * @param string $function Function name
+        * @return array
+        * @see getEdges()
+        */
+       public function getCallers( $function ) {
+               $edges = $this->getCompleteMetrics();
+               if ( isset( $edges[$function]['calls'] ) ) {
+                       return array_keys( $edges[$function]['calls'] );
+               } else {
+                       return array();
+               }
+       }
+
+       /**
+        * Get a list of all callees from a given function.
+        *
+        * @param string $function Function name
+        * @return array
+        * @see getEdges()
+        */
+       public function getCallees( $function ) {
+               $edges = $this->getCompleteMetrics();
+               if ( isset( $edges[$function]['subcalls'] ) ) {
+                       return array_keys( $edges[$function]['subcalls'] );
+               } else {
+                       return array();
+               }
+       }
+
+       /**
+        * Find the critical path for the given metric.
+        *
+        * @param string $metric Metric to find critical path for
+        * @return array
+        */
+       public function getCriticalPath( $metric = 'wt' ) {
+               $this->stop();
+               $func = 'main()';
+               $path = array(
+                       $func => $this->hieraData[$func],
+               );
+               while ( $func ) {
+                       $callees = $this->getCallees( $func );
+                       $maxCallee = null;
+                       $maxCall = null;
+                       foreach ( $callees as $callee ) {
+                               $call = "{$func}==>{$callee}";
+                               if ( $maxCall === null ||
+                                       $this->hieraData[$call][$metric] >
+                                               $this->hieraData[$maxCall][$metric]
+                               ) {
+                                       $maxCallee = $callee;
+                                       $maxCall = $call;
+                               }
+                       }
+                       if ( $maxCall !== null ) {
+                               $path[$maxCall] = $this->hieraData[$maxCall];
+                       }
+                       $func = $maxCallee;
+               }
+               return $path;
+       }
+
+       /**
+        * Make a closure to use as a sort function. The resulting function will
+        * sort by descending numeric values (largest value first).
+        *
+        * @param string $key Data key to sort on
+        * @param string $sub Sub key to sort array values on
+        * @return Closure
+        */
+       public static function makeSortFunction( $key, $sub ) {
+               return function ( $a, $b ) use ( $key, $sub ) {
+                       if ( isset( $a[$key] ) && isset( $b[$key] ) ) {
+                               // Descending sort: larger values will be first in result.
+                               // Assumes all values are numeric.
+                               // Values for 'main()' will not have sub keys
+                               $valA = is_array( $a[$key] ) ? $a[$key][$sub] : $a[$key];
+                               $valB = is_array( $b[$key] ) ? $b[$key][$sub] : $b[$key];
+                               return $valB - $valA;
+                       } else {
+                               // Sort datum with the key before those without
+                               return isset( $a[$key] ) ? -1 : 1;
+                       }
+               };
+       }
+}
index 4c12b10..380d80f 100644 (file)
@@ -159,6 +159,8 @@ abstract class Profiler {
        abstract public function getOutput();
 
        /**
+        * Get data for the debugging toolbar.
+        *
         * @return array
         */
        abstract public function getRawData();
diff --git a/includes/profiler/ProfilerXhprof.php b/includes/profiler/ProfilerXhprof.php
new file mode 100644 (file)
index 0000000..acfe7e0
--- /dev/null
@@ -0,0 +1,479 @@
+<?php
+/**
+ * @section LICENSE
+ * 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
+ */
+
+/**
+ * Profiler wrapper for XHProf extension.
+ *
+ * Mimics the output of ProfilerSimpleText, ProfilerSimpleUDP or
+ * ProfilerSimpleTrace but using data collected via the XHProf PHP extension.
+ * This Profiler also produces data compatable with the debugging toolbar.
+ *
+ * To mimic ProfilerSimpleText results:
+ * @code
+ * $wgProfiler['class'] = 'ProfilerXhprof';
+ * $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
+ * $wgProfiler['log'] = 'text';
+ * $wgProfiler['visible'] = true;
+ * @endcode
+ *
+ * To mimic ProfilerSimpleUDP results:
+ * @code
+ * $wgProfiler['class'] = 'ProfilerXhprof';
+ * $wgProfiler['flags'] = XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY | XHPROF_FLAGS_NO_BUILTINS;
+ * $wgProfiler['log'] = 'udpprofile';
+ * @endcode
+ *
+ * Similar to ProfilerSimpleTrace results, report the most expensive path
+ * through the application:
+ * @code
+ * $wgProfiler['class'] = 'ProfilerXhprof';
+ * $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
+ * $wgProfiler['log'] = 'critpath';
+ * $wgProfiler['visible'] = true;
+ * @endcode
+ *
+ * Rather than obeying wfProfileIn() and wfProfileOut() calls placed in the
+ * application code, ProfilerXhprof profiles all functions using the XHProf
+ * PHP extenstion. For PHP5 users, this extension can be installed via PECL or
+ * your operating system's package manager. XHProf support is built into HHVM.
+ *
+ * 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 funcitonality is built into HHVM and will completely exclude the
+ * named functions from profiling collection. The whitelist is implemented by
+ * Xhprof class and will filter the data collected by XHProf before reporting.
+ * See documentation for the Xhprof class and the XHProf extension for
+ * additional information.
+ *
+ * Data reported to debug toolbar via getRawData() can be restricted by
+ * setting $wgProfiler['toolbarCutoff'] to a minumum cumulative wall clock
+ * percentage. Functions in the call graph which contribute less than this
+ * percentage to the total wall clock time measured will be excluded from the
+ * data sent to debug toolbar. The default cutoff is 0.1 (1/1000th of the
+ * total time measured).
+ *
+ * @author Bryan Davis <bd808@wikimedia.org>
+ * @copyright © 2014 Bryan Davis and Wikimedia Foundation.
+ * @ingroup Profiler
+ * @see Xhprof
+ * @see https://php.net/xhprof
+ * @see https://github.com/facebook/hhvm/blob/master/hphp/doc/profiling.md
+ */
+class ProfilerXhprof extends Profiler {
+
+       /**
+        * @var Xhprof $xhprof
+        */
+       protected $xhprof;
+
+       /**
+        * Type of report to send when logData() is called.
+        * @var string $logType
+        */
+       protected $logType;
+
+       /**
+        * Should profile report sent to in page content be visible?
+        * @var bool $visible
+        */
+       protected $visible;
+
+       /**
+        * Minimum wall time precentage for a fucntion to be reported to the debug
+        * toolbar via getRawData().
+        * @var float $toolbarCutoff
+        */
+       protected $toolbarCutoff;
+
+       /**
+        * @param array $params
+        * @see Xhprof::__construct()
+        */
+       public function __construct( array $params = array() ) {
+               $params = array_merge(
+                       array(
+                               'log' => 'text',
+                               'visible' => false,
+                               'toolbarCutoff' => 0.1,
+                       ),
+                       $params
+               );
+               parent::__construct( $params );
+               $this->logType = $params['log'];
+               $this->visible = $params['visible'];
+               $this->xhprof = new Xhprof( $params );
+       }
+
+       public function isStub() {
+               return false;
+       }
+
+       public function isPersistent() {
+               // Disable per-title profiling sections
+               return true;
+       }
+
+       /**
+        * No-op for xhprof profiling.
+        *
+        * Use the 'include' configuration key instead if you need to constrain
+        * the functions that are profiled.
+        *
+        * @param string $functionname
+        */
+       public function profileIn( $functionname ) {
+               global $wgDebugFunctionEntry;
+               if ( $wgDebugFunctionEntry ) {
+                       $this->debug( "Entering {$functionname}" );
+               }
+       }
+
+       /**
+        * No-op for xhprof profiling.
+        *
+        * Use the 'include' configuration key instead if you need to constrain
+        * the functions that are profiled.
+        *
+        * @param string $functionname
+        */
+       public function profileOut( $functionname ) {
+               global $wgDebugFunctionEntry;
+               if ( $wgDebugFunctionEntry ) {
+                       $this->debug( "Exiting {$functionname}" );
+               }
+       }
+
+       /**
+        * No-op for xhprof profiling.
+        */
+       public function close() {
+       }
+
+       /**
+        * Get data for the debugging toolbar.
+        *
+        * @return array
+        * @see https://www.mediawiki.org/wiki/Debugging_toolbar
+        */
+       public function getRawData() {
+               $metrics = $this->xhprof->getCompleteMetrics();
+               $endEpoch = $this->getTime();
+               $profile = array();
+
+               foreach ( $metrics as $fname => $stats ) {
+                       if ( $stats['wt']['percent'] < $this->toolbarCutoff ) {
+                               // Ignore functions which are not significant contributors
+                               // to the total elapsed time.
+                               continue;
+                       }
+
+                       $record = array(
+                               'name' => $fname,
+                               'calls' => $stats['ct'],
+                               'elapsed' => $stats['wt']['total'] / 1000,
+                               'percent' => $stats['wt']['percent'],
+                               'memory' => isset( $stats['mu'] ) ? $stats['mu']['total'] : 0,
+                               'min' => $stats['wt']['min'] / 1000,
+                               'max' => $stats['wt']['max'] / 1000,
+                               'overhead' => array_reduce(
+                                       $stats['subcalls'],
+                                       function( $carry, $item ) {
+                                               return $carry + $item['ct'];
+                                       },
+                                       0
+                               ),
+                               'periods' => array(),
+                       );
+
+                       // We are making up periods based on the call segments we have.
+                       // What we don't have is the start time for each call (which
+                       // actually may be a collection of multiple calls from the
+                       // caller). We will pretend that all the calls happen sequentially
+                       // and finish at the end of the end of the request.
+                       foreach ( $stats['calls'] as $call ) {
+                               $avgElapsed = $call['wt'] / 1000 / $call['ct'];
+                               $avgMem = isset( $call['mu'] ) ? $call['mu'] / $call['ct'] : 0;
+                               $start = $endEpoch - $avgElapsed;
+                               for ( $i = 0; $i < $call['ct']; $i++ ) {
+                                       $callStart = $start + ( $avgElapsed * $i );
+                                       $record['periods'][] = array(
+                                               'start' => $callStart,
+                                               'end' => $callStart + $avgElapsed,
+                                               'memory' => $avgMem,
+                                               'subcalls' => 0,
+                                       );
+                               }
+                       }
+
+                       $profile[] = $record;
+               }
+               return $profile;
+       }
+
+       /**
+        * Log the data to some store or even the page output.
+        */
+       public function logData() {
+               if ( $this->logType === 'text' ) {
+                       $this->logText();
+               } elseif ( $this->logType === 'udpprofile' ) {
+                       $this->logToUdpprofile();
+               } elseif ( $this->logType === 'critpath' ){
+                       $this->logCriticalPath();
+               } else {
+                       wfLogWarning(
+                               "Unknown ProfilerXhprof log type '{$this->logType}'"
+                       );
+               }
+       }
+
+       /**
+        * Write a brief profile report to stdout.
+        */
+       protected function logText() {
+               if ( $this->templated ) {
+                       $ct = $this->getContentType();
+                       if ( $ct === 'text/html' && $this->visible ) {
+                               $prefix = '<pre>';
+                               $suffix = '</pre>';
+                       } elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) {
+                               $prefix = "\n/*";
+                               $suffix = "*/\n";
+                       } else {
+                               $prefix = "<!--";
+                               $suffix = "-->\n";
+                       }
+
+                       print $this->getSummaryReport( $prefix, $suffix );
+               }
+       }
+
+       /**
+        * Send collected information to a udpprofile daemon.
+        *
+        * @see http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile
+        * @see $wgUDPProfilerHost
+        * @see $wgUDPProfilerPort
+        * @see $wgUDPProfilerFormatString
+        */
+       protected function logToUdpprofile() {
+               global $wgUDPProfilerHost, $wgUDPProfilerPort;
+               global $wgUDPProfilerFormatString;
+
+               if ( !function_exists( 'socket_create' ) ) {
+                       return;
+               }
+
+               $metrics = $this->xhprof->getInclusiveMetrics();
+
+               $sock = socket_create( AF_INET, SOCK_DGRAM, SOL_UDP );
+               $buffer = '';
+               $bufferSize = 0;
+               foreach ( $metrics as $func => $data ) {
+                       $line = sprintf( $wgUDPProfilerFormatString,
+                               $this->getProfileID(),
+                               $data['ct'],
+                               isset( $data['cpu'] ) ? $data['cpu']['total'] : 0,
+                               isset( $data['cpu'] ) ? $data['cpu']['variance'] : 0,
+                               $data['wt']['total'] / 1000,
+                               $data['wt']['variance'],
+                               $func,
+                               isset( $data['mu'] ) ? $data['mu']['total'] : 0
+                       );
+                       $lineLength = strlen( $line );
+                       if ( $lineLength + $bufferSize > 1400 ) {
+                               // Line would exceed max packet size, send packet before
+                               // appending to buffer.
+                               socket_sendto( $sock, $buffer, $bufferSize, 0,
+                                       $wgUDPProfilerHost, $wgUDPProfilerPort
+                               );
+                               $buffer = '';
+                               $bufferSize = 0;
+                       }
+                       $buffer .= $line;
+                       $bufferSize += $lineLength;
+               }
+               // Send final buffer
+               socket_sendto( $sock, $buffer, $bufferSize, 0x100 /* EOF */,
+                       $wgUDPProfilerHost, $wgUDPProfilerPort
+               );
+       }
+
+       /**
+        * Write a critical path report to stdout.
+        */
+       protected function logCriticalPath() {
+               if ( $this->templated ) {
+                       $ct = $this->getContentType();
+                       if ( $ct === 'text/html' && $this->visible ) {
+                               $prefix = '<pre>Critical path:';
+                               $suffix = '</pre>';
+                       } elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) {
+                               $prefix = "\n/* Critical path:";
+                               $suffix = "*/\n";
+                       } else {
+                               $prefix = "<!-- Critical path:";
+                               $suffix = "-->\n";
+                       }
+
+                       print $this->getCriticalPathReport( $prefix, $suffix );
+               }
+       }
+
+       /**
+        * Get the content type of the current request.
+        * @return string
+        */
+       protected function getContentType() {
+               foreach ( headers_list() as $header ) {
+                       if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {
+                               return $m[1];
+                       }
+               }
+               return 'application/octet-stream';
+       }
+
+       /**
+        * Returns a profiling output to be stored in debug file
+        *
+        * @return string
+        */
+       public function getOutput() {
+               return $this->getFunctionReport();
+       }
+
+       /**
+        * Get a report of profiled functions sorted by inclusive wall clock time
+        * in descending order.
+        *
+        * Each line of the report includes this data:
+        * - Function name
+        * - Number of times function was called
+        * - Total wall clock time spent in function in microseconds
+        * - Minimum wall clock time spent in function in microseconds
+        * - Average wall clock time spent in function in microseconds
+        * - Maximum wall clock time spent in function in microseconds
+        * - Percentage of total wall clock time spent in function
+        * - Total delta of memory usage from start to end of function in bytes
+        *
+        * @return string
+        */
+       protected function getFunctionReport() {
+               $data = $this->xhprof->getInclusiveMetrics();
+               uasort( $data, Xhprof::makeSortFunction( 'wt', 'total' ) );
+
+               $width = 140;
+               $nameWidth = $width - 65;
+               $format = "%-{$nameWidth}s %6d %9d %9d %9d %9d %7.3f%% %9d";
+               $out = array();
+               $out[] = sprintf( "%-{$nameWidth}s %6s %9s %9s %9s %9s %7s %9s",
+                       'Name', 'Calls', 'Total', 'Min', 'Each', 'Max', '%', 'Mem'
+               );
+               foreach ( $data as $func => $stats ) {
+                       $out[] = sprintf( $format,
+                               $func,
+                               $stats['ct'],
+                               $stats['wt']['total'],
+                               $stats['wt']['min'],
+                               $stats['wt']['mean'],
+                               $stats['wt']['max'],
+                               $stats['wt']['percent'],
+                               isset( $stats['mu'] ) ? $stats['mu']['total'] : 0
+                       );
+               }
+               return implode( "\n", $out );
+       }
+
+       /**
+        * Get a brief report of profiled functions sorted by inclusive wall clock
+        * time in descending order.
+        *
+        * Each line of the report includes this data:
+        * - Percentage of total wall clock time spent in function
+        * - Total wall clock time spent in function in seconds
+        * - Number of times function was called
+        * - Function name
+        *
+        * @param string $header Header text to prepend to report
+        * @param string $footer Footer text to append to report
+        * @return string
+        */
+       protected function getSummaryReport( $header = '', $footer = '' ) {
+               $data = $this->xhprof->getInclusiveMetrics();
+               uasort( $data, Xhprof::makeSortFunction( 'wt', 'total' ) );
+
+               $format = '%6.2f%% %3.6f %6d - %s';
+               $out = array( $header );
+               foreach ( $data as $func => $stats ) {
+                       $out[] = sprintf( $format,
+                               $stats['wt']['percent'],
+                               $stats['wt']['total'] / 1e6,
+                               $stats['ct'],
+                               $func
+                       );
+               }
+               $out[] = $footer;
+               return implode( "\n", $out );
+       }
+
+       /**
+        * Get a brief report of the most costly code path by wall clock time.
+        *
+        * Each line of the report includes this data:
+        * - Total wall clock time spent in function in seconds
+        * - Function name
+        *
+        * @param string $header Header text to prepend to report
+        * @param string $footer Footer text to append to report
+        * @return string
+        */
+       protected function getCriticalPathReport( $header = '', $footer = '' ) {
+               $data = $this->xhprof->getCriticalPath();
+
+               $out = array( $header );
+               $out[] = sprintf( "%7s %9s %9s %6s %4s",
+                       'Time%', 'Time', 'Mem', 'Calls', 'Name'
+               );
+
+               $format = '%6.2f%% %9.6f %9d %6d %s%s';
+               $total = null;
+               $nest = 0;
+               foreach ( $data as $key => $stats ) {
+                       list( $parent, $child ) = Xhprof::splitKey( $key );
+                       if ( $total === null ) {
+                               $total = $stats;
+                       }
+                       $out[] = sprintf( $format,
+                               100 * $stats['wt'] / $total['wt'],
+                               $stats['wt'] / 1e6,
+                               isset( $stats['mu'] ) ? $stats['mu'] : 0,
+                               $stats['ct'],
+                               //$nest ? str_repeat( ' ', $nest - 1 ) . '┗ ' : '',
+                               $nest ? str_repeat( ' ', $nest - 1 ) . '└─' : '',
+                               $child
+                       );
+                       $nest++;
+               }
+               $out[] = $footer;
+               return implode( "\n", $out );
+       }
+}
diff --git a/tests/phpunit/includes/libs/XhprofTest.php b/tests/phpunit/includes/libs/XhprofTest.php
new file mode 100644 (file)
index 0000000..e0e68e0
--- /dev/null
@@ -0,0 +1,312 @@
+<?php
+/**
+ * @section LICENSE
+ * 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
+ */
+
+/**
+ * @uses Xhprof
+ * @uses AutoLoader
+ * @author Bryan Davis <bd808@wikimedia.org>
+ * @copyright © 2014 Bryan Davis and Wikimedia Foundation.
+ * @since 1.25
+ */
+class XhprofTest extends PHPUnit_Framework_TestCase {
+
+       public function setUp() {
+               if ( !function_exists( 'xhprof_enable' ) ) {
+                       $this->markTestSkipped( 'No xhprof support detected.' );
+               }
+       }
+
+       /**
+        * @covers Xhprof::splitKey
+        * @dataProvider provideSplitKey
+        */
+       public function testSplitKey( $key, $expect ) {
+               $this->assertSame( $expect, Xhprof::splitKey( $key ) );
+       }
+
+       public function provideSplitKey() {
+               return array(
+                       array( 'main()', array( null, 'main()' ) ),
+                       array( 'foo==>bar', array( 'foo', 'bar' ) ),
+                       array( 'bar@1==>bar@2', array( 'bar@1', 'bar@2' ) ),
+                       array( 'foo==>bar==>baz', array( 'foo', 'bar==>baz' ) ),
+                       array( '==>bar', array( '', 'bar' ) ),
+                       array( '', array( null, '' ) ),
+               );
+       }
+
+       /**
+        * @covers Xhprof::__construct
+        * @covers Xhprof::stop
+        * @covers Xhprof::getRawData
+        * @dataProvider provideRawData
+        */
+       public function testRawData( $flags, $keys ) {
+               $xhprof = new Xhprof( array( 'flags' => $flags ) );
+               $raw = $xhprof->getRawData();
+               $this->assertArrayHasKey( 'main()', $raw );
+               foreach ( $keys as $key ) {
+                       $this->assertArrayHasKey( $key, $raw['main()'] );
+               }
+       }
+
+       public function provideRawData() {
+               return array(
+                       array( 0, array( 'ct', 'wt' ) ),
+                       array( XHPROF_FLAGS_MEMORY, array( 'ct', 'wt', 'mu', 'pmu' ) ),
+                       array( XHPROF_FLAGS_CPU, array( 'ct', 'wt', 'cpu' ) ),
+                       array( XHPROF_FLAGS_MEMORY | XHPROF_FLAGS_CPU, array(
+                               'ct', 'wt', 'mu', 'pmu', 'cpu',
+                       ) ),
+               );
+       }
+
+       /**
+        * @covers Xhprof::pruneData
+        */
+       public function testInclude() {
+               $xhprof = $this->getXhprofFixture( array(
+                       'include' => array( 'main()' ),
+               ) );
+               $raw = $xhprof->getRawData();
+               $this->assertArrayHasKey( 'main()', $raw );
+               $this->assertArrayHasKey( 'main()==>foo', $raw );
+               $this->assertArrayHasKey( 'main()==>xhprof_disable', $raw );
+               $this->assertSame( 3, count( $raw ) );
+       }
+
+       /**
+        * Validate the structure of data returned by
+        * Xhprof::getInclusiveMetrics(). This acts as a guard against unexpected
+        * structural changes to the returned data in lieu of using a more heavy
+        * weight typed response object.
+        *
+        * @covers Xhprof::getInclusiveMetrics
+        */
+       public function testInclusiveMetricsStructure() {
+               $metricStruct = array(
+                       'ct' => 'int',
+                       'wt' => 'array',
+                       'cpu' => 'array',
+                       'mu' => 'array',
+                       'pmu' => 'array',
+               );
+               $statStruct = array(
+                       'total' => 'numeric',
+                       'min' => 'numeric',
+                       'mean' => 'numeric',
+                       'max' => 'numeric',
+                       'variance' => 'numeric',
+                       'percent' => 'numeric',
+               );
+
+               $xhprof = $this->getXhprofFixture();
+               $metrics = $xhprof->getInclusiveMetrics();
+
+               foreach ( $metrics as $name => $metric ) {
+                       $this->assertArrayStructure( $metricStruct, $metric );
+
+                       foreach ( $metricStruct as $key => $type ) {
+                               if ( $type === 'array' ) {
+                                       $this->assertArrayStructure( $statStruct, $metric[$key] );
+                                       if ( $name === 'main()' ) {
+                                               $this->assertEquals( 100, $metric[$key]['percent'] );
+                                       }
+                               }
+                       }
+               }
+       }
+
+       /**
+        * Validate the structure of data returned by
+        * Xhprof::getCompleteMetrics(). This acts as a guard against unexpected
+        * structural changes to the returned data in lieu of using a more heavy
+        * weight typed response object.
+        *
+        * @covers Xhprof::getCompleteMetrics
+        */
+       public function testCompleteMetricsStructure() {
+               $metricStruct = array(
+                       'ct' => 'int',
+                       'wt' => 'array',
+                       'cpu' => 'array',
+                       'mu' => 'array',
+                       'pmu' => 'array',
+                       'calls' => 'array',
+                       'subcalls' => 'array',
+               );
+               $statsMetrics = array( 'wt', 'cpu', 'mu', 'pmu' );
+               $statStruct = array(
+                       'total' => 'numeric',
+                       'min' => 'numeric',
+                       'mean' => 'numeric',
+                       'max' => 'numeric',
+                       'variance' => 'numeric',
+                       'percent' => 'numeric',
+                       'exclusive' => 'numeric',
+               );
+
+               $xhprof = $this->getXhprofFixture();
+               $metrics = $xhprof->getCompleteMetrics();
+
+               foreach ( $metrics as $name => $metric ) {
+                       $this->assertArrayStructure( $metricStruct, $metric, $name );
+
+                       foreach ( $metricStruct as $key => $type ) {
+                               if ( in_array( $key, $statsMetrics ) ) {
+                                       $this->assertArrayStructure(
+                                               $statStruct, $metric[$key], $key
+                                       );
+                                       $this->assertLessThanOrEqual(
+                                               $metric[$key]['total'], $metric[$key]['exclusive']
+                                       );
+                               }
+                       }
+               }
+       }
+
+       /**
+        * @covers Xhprof::getCallers
+        * @covers Xhprof::getCallees
+        * @uses Xhprof
+        */
+       public function testEdges() {
+               $xhprof = $this->getXhprofFixture();
+               $this->assertSame( array(), $xhprof->getCallers( 'main()' ) );
+               $this->assertSame( array( 'foo', 'xhprof_disable' ),
+                       $xhprof->getCallees( 'main()' )
+               );
+               $this->assertSame( array( 'main()' ),
+                       $xhprof->getCallers( 'foo' )
+               );
+               $this->assertSame( array(), $xhprof->getCallees( 'strlen' ) );
+       }
+
+       /**
+        * @covers Xhprof::getCriticalPath
+        * @uses Xhprof
+        */
+       public function testCriticalPath() {
+               $xhprof = $this->getXhprofFixture();
+               $path = $xhprof->getCriticalPath();
+
+               $last = null;
+               foreach ( $path as $key => $value ) {
+                       list( $func, $call ) = Xhprof::splitKey( $key );
+                       $this->assertSame( $last, $func );
+                       $last = $call;
+               }
+               $this->assertSame( $last, 'bar@1' );
+       }
+
+       /**
+        * Get an Xhprof instance that has been primed with a set of known testing
+        * data. Tests for the Xhprof class should laregly be concerned with
+        * evaluating the manipulations of the data collected by xhprof rather
+        * than the data collection process itself.
+        *
+        * The returned Xhprof instance primed will be with a data set created by
+        * running this trivial program using the PECL xhprof implementation:
+        * @code
+        * function bar( $x ) {
+        *   if ( $x > 0 ) {
+        *     bar($x - 1);
+        *   }
+        * }
+        * function foo() {
+        *   for ( $idx = 0; $idx < 2; $idx++ ) {
+        *     bar( $idx );
+        *     $x = strlen( 'abc' );
+        *   }
+        * }
+        * xhprof_enable( XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY );
+        * foo();
+        * $x = xhprof_disable();
+        * var_export( $x );
+        * @endcode
+        *
+        * @return Xhprof
+        */
+       protected function getXhprofFixture( array $opts = array() ) {
+               $xhprof = new Xhprof( $opts );
+               $xhprof->loadRawData( array (
+                       'foo==>bar' => array (
+                               'ct' => 2,
+                               'wt' => 57,
+                               'cpu' => 92,
+                               'mu' => 1896,
+                               'pmu' => 0,
+                       ),
+                       'foo==>strlen' => array (
+                               'ct' => 2,
+                               'wt' => 21,
+                               'cpu' => 141,
+                               'mu' => 752,
+                               'pmu' => 0,
+                       ),
+                       'bar==>bar@1' => array (
+                               'ct' => 1,
+                               'wt' => 18,
+                               'cpu' => 19,
+                               'mu' => 752,
+                               'pmu' => 0,
+                       ),
+                       'main()==>foo' => array (
+                               'ct' => 1,
+                               'wt' => 304,
+                               'cpu' => 307,
+                               'mu' => 4008,
+                               'pmu' => 0,
+                       ),
+                       'main()==>xhprof_disable' => array (
+                               'ct' => 1,
+                               'wt' => 8,
+                               'cpu' => 10,
+                               'mu' => 768,
+                               'pmu' => 392,
+                       ),
+                       'main()' => array (
+                               'ct' => 1,
+                               'wt' => 353,
+                               'cpu' => 351,
+                               'mu' => 6112,
+                               'pmu' => 1424,
+                       ),
+               ) );
+               return $xhprof;
+       }
+
+       /**
+        * Assert that the given array has the described structure.
+        *
+        * @param array $struct Array of key => type mappings
+        * @param array $actual Array to check
+        * @param string $label
+        */
+       protected function assertArrayStructure( $struct, $actual, $label = null ) {
+               $this->assertInternalType( 'array', $actual, $label );
+               $this->assertCount( count($struct), $actual, $label );
+               foreach ( $struct as $key => $type ) {
+                       $this->assertArrayHasKey( $key, $actual );
+                       $this->assertInternalType( $type, $actual[$key] );
+               }
+       }
+}