From: Bryan Davis Date: Mon, 27 Oct 2014 04:27:59 +0000 (-0600) Subject: Enable profiling via xhprof X-Git-Tag: 1.31.0-rc.0~13320^2 X-Git-Url: http://git.cyclocoop.org/%7B%24www_url%7Dadmin/compta/categories/modifier.php?a=commitdiff_plain;h=46c47e11bc27e8acaf7ea3e5972989e2d0801370;p=lhc%2Fweb%2Fwiklou.git Enable profiling via xhprof Add a helper class to assist in collecting profiling information using 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 --- diff --git a/includes/AutoLoader.php b/includes/AutoLoader.php index e89e5006a9..ffd361c999 100644 --- a/includes/AutoLoader.php +++ b/includes/AutoLoader.php @@ -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', diff --git a/includes/libs/RunningStat.php b/includes/libs/RunningStat.php index dda5254e3b..f09d101826 100644 --- a/includes/libs/RunningStat.php +++ b/includes/libs/RunningStat.php @@ -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 index 0000000000..1ad01ccc9f --- /dev/null +++ b/includes/libs/Xhprof.php @@ -0,0 +1,443 @@ +. 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 + * @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; + } + }; + } +} diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index 4c12b103e1..380d80fddc 100644 --- a/includes/profiler/Profiler.php +++ b/includes/profiler/Profiler.php @@ -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 index 0000000000..acfe7e0b7f --- /dev/null +++ b/includes/profiler/ProfilerXhprof.php @@ -0,0 +1,479 @@ + + * @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 = '
';
+				$suffix = '
'; + } elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) { + $prefix = "\n/*"; + $suffix = "*/\n"; + } else { + $prefix = "\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 = '
Critical path:';
+				$suffix = '
'; + } elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) { + $prefix = "\n/* Critical path:"; + $suffix = "*/\n"; + } else { + $prefix = "\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 index 0000000000..e0e68e0d32 --- /dev/null +++ b/tests/phpunit/includes/libs/XhprofTest.php @@ -0,0 +1,312 @@ + + * @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] ); + } + } +}