includes/profiler/ProfilerXhprof.php

   1 <?php
   2 /**
   3  * @section LICENSE
   4  * This program is free software; you can redistribute it and/or modify
   5  * it under the terms of the GNU General Public License as published by
   6  * the Free Software Foundation; either version 2 of the License, or
   7  * (at your option) any later version.
   8  *
   9  * This program is distributed in the hope that it will be useful,
  10  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  11  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
  12  * GNU General Public License for more details.
  13  *
  14  * You should have received a copy of the GNU General Public License along
  15  * with this program; if not, write to the Free Software Foundation, Inc.,
  16  * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
  17  * http://www.gnu.org/copyleft/gpl.html
  18  *
  19  * @file
  20  */
  21
  22 /**
  23  * Profiler wrapper for XHProf extension.
  24  *
  25  * Mimics the output of ProfilerSimpleText, ProfilerSimpleUDP or
  26  * ProfilerSimpleTrace but using data collected via the XHProf PHP extension.
  27  * This Profiler also produces data compatable with the debugging toolbar.
  28  *
  29  * To mimic ProfilerSimpleText results:
  30  * @code
  31  * $wgProfiler['class'] = 'ProfilerXhprof';
  32  * $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
  33  * $wgProfiler['log'] = 'text';
  34  * $wgProfiler['visible'] = true;
  35  * @endcode
  36  *
  37  * To mimic ProfilerSimpleUDP results:
  38  * @code
  39  * $wgProfiler['class'] = 'ProfilerXhprof';
  40  * $wgProfiler['flags'] = XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY | XHPROF_FLAGS_NO_BUILTINS;
  41  * $wgProfiler['log'] = 'udpprofile';
  42  * @endcode
  43  *
  44  * Similar to ProfilerSimpleTrace results, report the most expensive path
  45  * through the application:
  46  * @code
  47  * $wgProfiler['class'] = 'ProfilerXhprof';
  48  * $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
  49  * $wgProfiler['log'] = 'critpath';
  50  * $wgProfiler['visible'] = true;
  51  * @endcode
  52  *
  53  * Rather than obeying wfProfileIn() and wfProfileOut() calls placed in the
  54  * application code, ProfilerXhprof profiles all functions using the XHProf
  55  * PHP extenstion. For PHP5 users, this extension can be installed via PECL or
  56  * your operating system's package manager. XHProf support is built into HHVM.
  57  *
  58  * To restrict the functions for which profiling data is collected, you can
  59  * use either a whitelist ($wgProfiler['include']) or a blacklist
  60  * ($wgProfiler['exclude']) containing an array of function names. The
  61  * blacklist funcitonality is built into HHVM and will completely exclude the
  62  * named functions from profiling collection. The whitelist is implemented by
  63  * Xhprof class and will filter the data collected by XHProf before reporting.
  64  * See documentation for the Xhprof class and the XHProf extension for
  65  * additional information.
  66  *
  67  * Data reported to debug toolbar via getRawData() can be restricted by
  68  * setting $wgProfiler['toolbarCutoff'] to a minumum cumulative wall clock
  69  * percentage. Functions in the call graph which contribute less than this
  70  * percentage to the total wall clock time measured will be excluded from the
  71  * data sent to debug toolbar. The default cutoff is 0.1 (1/1000th of the
  72  * total time measured).
  73  *
  74  * @author Bryan Davis <bd808@wikimedia.org>
  75  * @copyright © 2014 Bryan Davis and Wikimedia Foundation.
  76  * @ingroup Profiler
  77  * @see Xhprof
  78  * @see https://php.net/xhprof
  79  * @see https://github.com/facebook/hhvm/blob/master/hphp/doc/profiling.md
  80  */
  81 class ProfilerXhprof extends Profiler {
  82
  83         /**
  84          * @var Xhprof $xhprof
  85          */
  86         protected $xhprof;
  87
  88         /**
  89          * Type of report to send when logData() is called.
  90          * @var string $logType
  91          */
  92         protected $logType;
  93
  94         /**
  95          * Should profile report sent to in page content be visible?
  96          * @var bool $visible
  97          */
  98         protected $visible;
  99
 100         /**
 101          * Minimum wall time precentage for a fucntion to be reported to the debug
 102          * toolbar via getRawData().
 103          * @var float $toolbarCutoff
 104          */
 105         protected $toolbarCutoff;
 106
 107         /**
 108          * @param array $params
 109          * @see Xhprof::__construct()
 110          */
 111         public function __construct( array $params = array() ) {
 112                 $params = array_merge(
 113                         array(
 114                                 'log' => 'text',
 115                                 'visible' => false,
 116                                 'toolbarCutoff' => 0.1,
 117                         ),
 118                         $params
 119                 );
 120                 parent::__construct( $params );
 121                 $this->logType = $params['log'];
 122                 $this->visible = $params['visible'];
 123                 $this->xhprof = new Xhprof( $params );
 124         }
 125
 126         public function isStub() {
 127                 return false;
 128         }
 129
 130         /**
 131          * No-op for xhprof profiling.
 132          *
 133          * Use the 'include' configuration key instead if you need to constrain
 134          * the functions that are profiled.
 135          *
 136          * @param string $functionname
 137          */
 138         public function profileIn( $functionname ) {
 139                 global $wgDebugFunctionEntry;
 140                 if ( $wgDebugFunctionEntry ) {
 141                         $this->debug( "Entering {$functionname}" );
 142                 }
 143         }
 144
 145         /**
 146          * No-op for xhprof profiling.
 147          *
 148          * Use the 'include' configuration key instead if you need to constrain
 149          * the functions that are profiled.
 150          *
 151          * @param string $functionname
 152          */
 153         public function profileOut( $functionname ) {
 154                 global $wgDebugFunctionEntry;
 155                 if ( $wgDebugFunctionEntry ) {
 156                         $this->debug( "Exiting {$functionname}" );
 157                 }
 158         }
 159
 160         /**
 161          * No-op for xhprof profiling.
 162          */
 163         public function close() {
 164         }
 165
 166         /**
 167          * Get data for the debugging toolbar.
 168          *
 169          * @return array
 170          * @see https://www.mediawiki.org/wiki/Debugging_toolbar
 171          */
 172         public function getRawData() {
 173                 $metrics = $this->xhprof->getCompleteMetrics();
 174                 $endEpoch = $this->getTime();
 175                 $profile = array();
 176
 177                 foreach ( $metrics as $fname => $stats ) {
 178                         if ( $stats['wt']['percent'] < $this->toolbarCutoff ) {
 179                                 // Ignore functions which are not significant contributors
 180                                 // to the total elapsed time.
 181                                 continue;
 182                         }
 183
 184                         $record = array(
 185                                 'name' => $fname,
 186                                 'calls' => $stats['ct'],
 187                                 'elapsed' => $stats['wt']['total'] / 1000,
 188                                 'percent' => $stats['wt']['percent'],
 189                                 'memory' => isset( $stats['mu'] ) ? $stats['mu']['total'] : 0,
 190                                 'min' => $stats['wt']['min'] / 1000,
 191                                 'max' => $stats['wt']['max'] / 1000,
 192                                 'overhead' => array_reduce(
 193                                         $stats['subcalls'],
 194                                         function( $carry, $item ) {
 195                                                 return $carry + $item['ct'];
 196                                         },
 197                                         0
 198                                 ),
 199                                 'periods' => array(),
 200                         );
 201
 202                         // We are making up periods based on the call segments we have.
 203                         // What we don't have is the start time for each call (which
 204                         // actually may be a collection of multiple calls from the
 205                         // caller). We will pretend that all the calls happen sequentially
 206                         // and finish at the end of the end of the request.
 207                         foreach ( $stats['calls'] as $call ) {
 208                                 $avgElapsed = $call['wt'] / 1000 / $call['ct'];
 209                                 $avgMem = isset( $call['mu'] ) ? $call['mu'] / $call['ct'] : 0;
 210                                 $start = $endEpoch - $avgElapsed;
 211                                 for ( $i = 0; $i < $call['ct']; $i++ ) {
 212                                         $callStart = $start + ( $avgElapsed * $i );
 213                                         $record['periods'][] = array(
 214                                                 'start' => $callStart,
 215                                                 'end' => $callStart + $avgElapsed,
 216                                                 'memory' => $avgMem,
 217                                                 'subcalls' => 0,
 218                                         );
 219                                 }
 220                         }
 221
 222                         $profile[] = $record;
 223                 }
 224                 return $profile;
 225         }
 226
 227         /**
 228          * Log the data to some store or even the page output.
 229          */
 230         public function logData() {
 231                 if ( $this->logType === 'text' ) {
 232                         $this->logText();
 233                 } elseif ( $this->logType === 'udpprofile' ) {
 234                         $this->logToUdpprofile();
 235                 } elseif ( $this->logType === 'critpath' ){
 236                         $this->logCriticalPath();
 237                 } else {
 238                         wfLogWarning(
 239                                 "Unknown ProfilerXhprof log type '{$this->logType}'"
 240                         );
 241                 }
 242         }
 243
 244         /**
 245          * Write a brief profile report to stdout.
 246          */
 247         protected function logText() {
 248                 if ( $this->templated ) {
 249                         $ct = $this->getContentType();
 250                         if ( $ct === 'text/html' && $this->visible ) {
 251                                 $prefix = '<pre>';
 252                                 $suffix = '</pre>';
 253                         } elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) {
 254                                 $prefix = "\n/*";
 255                                 $suffix = "*/\n";
 256                         } else {
 257                                 $prefix = "<!--";
 258                                 $suffix = "-->\n";
 259                         }
 260
 261                         print $this->getSummaryReport( $prefix, $suffix );
 262                 }
 263         }
 264
 265         /**
 266          * Send collected information to a udpprofile daemon.
 267          *
 268          * @see http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile
 269          * @see $wgUDPProfilerHost
 270          * @see $wgUDPProfilerPort
 271          * @see $wgUDPProfilerFormatString
 272          */
 273         protected function logToUdpprofile() {
 274                 global $wgUDPProfilerHost, $wgUDPProfilerPort;
 275                 global $wgUDPProfilerFormatString;
 276
 277                 if ( !function_exists( 'socket_create' ) ) {
 278                         return;
 279                 }
 280
 281                 $metrics = $this->xhprof->getInclusiveMetrics();
 282
 283                 $sock = socket_create( AF_INET, SOCK_DGRAM, SOL_UDP );
 284                 $buffer = '';
 285                 $bufferSize = 0;
 286                 foreach ( $metrics as $func => $data ) {
 287                         $line = sprintf( $wgUDPProfilerFormatString,
 288                                 $this->getProfileID(),
 289                                 $data['ct'],
 290                                 isset( $data['cpu'] ) ? $data['cpu']['total'] : 0,
 291                                 isset( $data['cpu'] ) ? $data['cpu']['variance'] : 0,
 292                                 $data['wt']['total'] / 1000,
 293                                 $data['wt']['variance'],
 294                                 $func,
 295                                 isset( $data['mu'] ) ? $data['mu']['total'] : 0
 296                         );
 297                         $lineLength = strlen( $line );
 298                         if ( $lineLength + $bufferSize > 1400 ) {
 299                                 // Line would exceed max packet size, send packet before
 300                                 // appending to buffer.
 301                                 socket_sendto( $sock, $buffer, $bufferSize, 0,
 302                                         $wgUDPProfilerHost, $wgUDPProfilerPort
 303                                 );
 304                                 $buffer = '';
 305                                 $bufferSize = 0;
 306                         }
 307                         $buffer .= $line;
 308                         $bufferSize += $lineLength;
 309                 }
 310                 // Send final buffer
 311                 socket_sendto( $sock, $buffer, $bufferSize, 0x100 /* EOF */,
 312                         $wgUDPProfilerHost, $wgUDPProfilerPort
 313                 );
 314         }
 315
 316         /**
 317          * Write a critical path report to stdout.
 318          */
 319         protected function logCriticalPath() {
 320                 if ( $this->templated ) {
 321                         $ct = $this->getContentType();
 322                         if ( $ct === 'text/html' && $this->visible ) {
 323                                 $prefix = '<pre>Critical path:';
 324                                 $suffix = '</pre>';
 325                         } elseif ( $ct === 'text/javascript' || $ct === 'text/css' ) {
 326                                 $prefix = "\n/* Critical path:";
 327                                 $suffix = "*/\n";
 328                         } else {
 329                                 $prefix = "<!-- Critical path:";
 330                                 $suffix = "-->\n";
 331                         }
 332
 333                         print $this->getCriticalPathReport( $prefix, $suffix );
 334                 }
 335         }
 336
 337         /**
 338          * Get the content type of the current request.
 339          * @return string
 340          */
 341         protected function getContentType() {
 342                 foreach ( headers_list() as $header ) {
 343                         if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {
 344                                 return $m[1];
 345                         }
 346                 }
 347                 return 'application/octet-stream';
 348         }
 349
 350         /**
 351          * Returns a profiling output to be stored in debug file
 352          *
 353          * @return string
 354          */
 355         public function getOutput() {
 356                 return $this->getFunctionReport();
 357         }
 358
 359         /**
 360          * Get a report of profiled functions sorted by inclusive wall clock time
 361          * in descending order.
 362          *
 363          * Each line of the report includes this data:
 364          * - Function name
 365          * - Number of times function was called
 366          * - Total wall clock time spent in function in microseconds
 367          * - Minimum wall clock time spent in function in microseconds
 368          * - Average wall clock time spent in function in microseconds
 369          * - Maximum wall clock time spent in function in microseconds
 370          * - Percentage of total wall clock time spent in function
 371          * - Total delta of memory usage from start to end of function in bytes
 372          *
 373          * @return string
 374          */
 375         protected function getFunctionReport() {
 376                 $data = $this->xhprof->getInclusiveMetrics();
 377                 uasort( $data, Xhprof::makeSortFunction( 'wt', 'total' ) );
 378
 379                 $width = 140;
 380                 $nameWidth = $width - 65;
 381                 $format = "%-{$nameWidth}s %6d %9d %9d %9d %9d %7.3f%% %9d";
 382                 $out = array();
 383                 $out[] = sprintf( "%-{$nameWidth}s %6s %9s %9s %9s %9s %7s %9s",
 384                         'Name', 'Calls', 'Total', 'Min', 'Each', 'Max', '%', 'Mem'
 385                 );
 386                 foreach ( $data as $func => $stats ) {
 387                         $out[] = sprintf( $format,
 388                                 $func,
 389                                 $stats['ct'],
 390                                 $stats['wt']['total'],
 391                                 $stats['wt']['min'],
 392                                 $stats['wt']['mean'],
 393                                 $stats['wt']['max'],
 394                                 $stats['wt']['percent'],
 395                                 isset( $stats['mu'] ) ? $stats['mu']['total'] : 0
 396                         );
 397                 }
 398                 return implode( "\n", $out );
 399         }
 400
 401         /**
 402          * Get a brief report of profiled functions sorted by inclusive wall clock
 403          * time in descending order.
 404          *
 405          * Each line of the report includes this data:
 406          * - Percentage of total wall clock time spent in function
 407          * - Total wall clock time spent in function in seconds
 408          * - Number of times function was called
 409          * - Function name
 410          *
 411          * @param string $header Header text to prepend to report
 412          * @param string $footer Footer text to append to report
 413          * @return string
 414          */
 415         protected function getSummaryReport( $header = '', $footer = '' ) {
 416                 $data = $this->xhprof->getInclusiveMetrics();
 417                 uasort( $data, Xhprof::makeSortFunction( 'wt', 'total' ) );
 418
 419                 $format = '%6.2f%% %3.6f %6d - %s';
 420                 $out = array( $header );
 421                 foreach ( $data as $func => $stats ) {
 422                         $out[] = sprintf( $format,
 423                                 $stats['wt']['percent'],
 424                                 $stats['wt']['total'] / 1e6,
 425                                 $stats['ct'],
 426                                 $func
 427                         );
 428                 }
 429                 $out[] = $footer;
 430                 return implode( "\n", $out );
 431         }
 432
 433         /**
 434          * Get a brief report of the most costly code path by wall clock time.
 435          *
 436          * Each line of the report includes this data:
 437          * - Total wall clock time spent in function in seconds
 438          * - Function name
 439          *
 440          * @param string $header Header text to prepend to report
 441          * @param string $footer Footer text to append to report
 442          * @return string
 443          */
 444         protected function getCriticalPathReport( $header = '', $footer = '' ) {
 445                 $data = $this->xhprof->getCriticalPath();
 446
 447                 $out = array( $header );
 448                 $out[] = sprintf( "%7s %9s %9s %6s %4s",
 449                         'Time%', 'Time', 'Mem', 'Calls', 'Name'
 450                 );
 451
 452                 $format = '%6.2f%% %9.6f %9d %6d %s%s';
 453                 $total = null;
 454                 $nest = 0;
 455                 foreach ( $data as $key => $stats ) {
 456                         list( $parent, $child ) = Xhprof::splitKey( $key );
 457                         if ( $total === null ) {
 458                                 $total = $stats;
 459                         }
 460                         $out[] = sprintf( $format,
 461                                 100 * $stats['wt'] / $total['wt'],
 462                                 $stats['wt'] / 1e6,
 463                                 isset( $stats['mu'] ) ? $stats['mu'] : 0,
 464                                 $stats['ct'],
 465                                 //$nest ? str_repeat( ' ', $nest - 1 ) . '┗ ' : '',
 466                                 $nest ? str_repeat( ' ', $nest - 1 ) . '└─' : '',
 467                                 $child
 468                         );
 469                         $nest++;
 470                 }
 471                 $out[] = $footer;
 472                 return implode( "\n", $out );
 473         }
 474 }