Refactor profiling output from profiling
[lhc/web/wiklou.git] / includes / profiler / ProfilerXhprof.php
index 5e70aa9..9379379 100644 (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.
+ * Mimics the output of ProfilerStandard using data collected via the XHProf
+ * PHP extension.
  *
- * To mimic ProfilerSimpleText results:
  * @code
  * $wgProfiler['class'] = 'ProfilerXhprof';
  * $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
- * $wgProfiler['log'] = 'text';
+ * $wgProfiler['output'] = '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;
+ * $wgProfiler['output'] = 'udp';
  * @endcode
  *
  * Rather than obeying wfProfileIn() and wfProfileOut() calls placed in the
  * 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
+ * blacklist functionality 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.
+ * Xhprof class which 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
@@ -97,13 +78,6 @@ class ProfilerXhprof extends Profiler {
         */
        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()
@@ -112,8 +86,7 @@ class ProfilerXhprof extends Profiler {
                $params = array_merge(
                        array(
                                'log' => 'text',
-                               'visible' => false,
-                               'toolbarCutoff' => 0.1,
+                               'visible' => false
                        ),
                        $params
                );
@@ -163,191 +136,27 @@ class ProfilerXhprof extends Profiler {
        public function close() {
        }
 
-       /**
-        * Get data for the debugging toolbar.
-        *
-        * @return array
-        * @see https://www.mediawiki.org/wiki/Debugging_toolbar
-        */
-       public function getRawData() {
+       public function getFunctionStats() {
                $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(
+                       // Convert elapsed times from μs to ms to match ProfilerStandard
+                       $profile[] = array(
                                'name' => $fname,
                                'calls' => $stats['ct'],
-                               'elapsed' => $stats['wt']['total'] / 1000,
-                               'percent' => $stats['wt']['percent'],
+                               'real' => $stats['wt']['total'] / 1000,
+                               '%real' => $stats['wt']['percent'],
+                               'cpu' => isset( $stats['cpu'] ) ? $stats['cpu']['total'] / 1000 : 0,
+                               '%cpu' => isset( $stats['cpu'] ) ? $stats['cpu']['percent'] : 0,
                                'memory' => isset( $stats['mu'] ) ? $stats['mu']['total'] : 0,
+                               '%memory' => isset( $stats['mu'] ) ? $stats['mu']['percent'] : 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 ) {
-                       if ( strpos( $func, '@' ) !== false ) {
-                               continue; // ignore cyclic re-entries to functions
-                       }
-                       $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
+                               'max' => $stats['wt']['max'] / 1000
                        );
-                       $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';
+               return $profile;
        }
 
        /**
@@ -432,46 +241,4 @@ class ProfilerXhprof extends Profiler {
                $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 );
-       }
 }