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.
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.
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
23 * Profiler wrapper for XHProf extension.
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.
29 * To mimic ProfilerSimpleText results:
31 * $wgProfiler['class'] = 'ProfilerXhprof';
32 * $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
33 * $wgProfiler['log'] = 'text';
34 * $wgProfiler['visible'] = true;
37 * To mimic ProfilerSimpleUDP results:
39 * $wgProfiler['class'] = 'ProfilerXhprof';
40 * $wgProfiler['flags'] = XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY | XHPROF_FLAGS_NO_BUILTINS;
41 * $wgProfiler['log'] = 'udpprofile';
44 * Similar to ProfilerSimpleTrace results, report the most expensive path
45 * through the application:
47 * $wgProfiler['class'] = 'ProfilerXhprof';
48 * $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
49 * $wgProfiler['log'] = 'critpath';
50 * $wgProfiler['visible'] = true;
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.
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.
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).
74 * @author Bryan Davis <bd808@wikimedia.org>
75 * @copyright © 2014 Bryan Davis and Wikimedia Foundation.
78 * @see https://php.net/xhprof
79 * @see https://github.com/facebook/hhvm/blob/master/hphp/doc/profiling.md
81 class ProfilerXhprof
extends Profiler
{
89 * Type of report to send when logData() is called.
90 * @var string $logType
95 * Should profile report sent to in page content be visible?
101 * Minimum wall time precentage for a fucntion to be reported to the debug
102 * toolbar via getRawData().
103 * @var float $toolbarCutoff
105 protected $toolbarCutoff;
108 * @param array $params
109 * @see Xhprof::__construct()
111 public function __construct( array $params = array() ) {
112 $params = array_merge(
116 'toolbarCutoff' => 0.1,
120 parent
::__construct( $params );
121 $this->logType
= $params['log'];
122 $this->visible
= $params['visible'];
123 $this->xhprof
= new Xhprof( $params );
126 public function isStub() {
131 * No-op for xhprof profiling.
133 * Use the 'include' configuration key instead if you need to constrain
134 * the functions that are profiled.
136 * @param string $functionname
138 public function profileIn( $functionname ) {
139 global $wgDebugFunctionEntry;
140 if ( $wgDebugFunctionEntry ) {
141 $this->debug( "Entering {$functionname}" );
146 * No-op for xhprof profiling.
148 * Use the 'include' configuration key instead if you need to constrain
149 * the functions that are profiled.
151 * @param string $functionname
153 public function profileOut( $functionname ) {
154 global $wgDebugFunctionEntry;
155 if ( $wgDebugFunctionEntry ) {
156 $this->debug( "Exiting {$functionname}" );
161 * No-op for xhprof profiling.
163 public function close() {
167 * Get data for the debugging toolbar.
170 * @see https://www.mediawiki.org/wiki/Debugging_toolbar
172 public function getRawData() {
173 $metrics = $this->xhprof
->getCompleteMetrics();
174 $endEpoch = $this->getTime();
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.
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(
194 function( $carry, $item ) {
195 return $carry +
$item['ct'];
199 'periods' => array(),
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,
222 $profile[] = $record;
228 * Log the data to some store or even the page output.
230 public function logData() {
231 if ( $this->logType
=== 'text' ) {
233 } elseif ( $this->logType
=== 'udpprofile' ) {
234 $this->logToUdpprofile();
235 } elseif ( $this->logType
=== 'critpath' ){
236 $this->logCriticalPath();
239 "Unknown ProfilerXhprof log type '{$this->logType}'"
245 * Write a brief profile report to stdout.
247 protected function logText() {
248 if ( $this->templated
) {
249 $ct = $this->getContentType();
250 if ( $ct === 'text/html' && $this->visible
) {
253 } elseif ( $ct === 'text/javascript' ||
$ct === 'text/css' ) {
261 print $this->getSummaryReport( $prefix, $suffix );
266 * Send collected information to a udpprofile daemon.
268 * @see http://git.wikimedia.org/tree/operations%2Fsoftware.git/master/udpprofile
269 * @see $wgUDPProfilerHost
270 * @see $wgUDPProfilerPort
271 * @see $wgUDPProfilerFormatString
273 protected function logToUdpprofile() {
274 global $wgUDPProfilerHost, $wgUDPProfilerPort;
275 global $wgUDPProfilerFormatString;
277 if ( !function_exists( 'socket_create' ) ) {
281 $metrics = $this->xhprof
->getInclusiveMetrics();
283 $sock = socket_create( AF_INET
, SOCK_DGRAM
, SOL_UDP
);
286 foreach ( $metrics as $func => $data ) {
287 $line = sprintf( $wgUDPProfilerFormatString,
288 $this->getProfileID(),
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'],
295 isset( $data['mu'] ) ?
$data['mu']['total'] : 0
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
308 $bufferSize +
= $lineLength;
311 socket_sendto( $sock, $buffer, $bufferSize, 0x100 /* EOF */,
312 $wgUDPProfilerHost, $wgUDPProfilerPort
317 * Write a critical path report to stdout.
319 protected function logCriticalPath() {
320 if ( $this->templated
) {
321 $ct = $this->getContentType();
322 if ( $ct === 'text/html' && $this->visible
) {
323 $prefix = '<pre>Critical path:';
325 } elseif ( $ct === 'text/javascript' ||
$ct === 'text/css' ) {
326 $prefix = "\n/* Critical path:";
329 $prefix = "<!-- Critical path:";
333 print $this->getCriticalPathReport( $prefix, $suffix );
338 * Get the content type of the current request.
341 protected function getContentType() {
342 foreach ( headers_list() as $header ) {
343 if ( preg_match( '#^content-type: (\w+/\w+);?#i', $header, $m ) ) {
347 return 'application/octet-stream';
351 * Returns a profiling output to be stored in debug file
355 public function getOutput() {
356 return $this->getFunctionReport();
360 * Get a report of profiled functions sorted by inclusive wall clock time
361 * in descending order.
363 * Each line of the report includes this data:
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
375 protected function getFunctionReport() {
376 $data = $this->xhprof
->getInclusiveMetrics();
377 uasort( $data, Xhprof
::makeSortFunction( 'wt', 'total' ) );
380 $nameWidth = $width - 65;
381 $format = "%-{$nameWidth}s %6d %9d %9d %9d %9d %7.3f%% %9d";
383 $out[] = sprintf( "%-{$nameWidth}s %6s %9s %9s %9s %9s %7s %9s",
384 'Name', 'Calls', 'Total', 'Min', 'Each', 'Max', '%', 'Mem'
386 foreach ( $data as $func => $stats ) {
387 $out[] = sprintf( $format,
390 $stats['wt']['total'],
392 $stats['wt']['mean'],
394 $stats['wt']['percent'],
395 isset( $stats['mu'] ) ?
$stats['mu']['total'] : 0
398 return implode( "\n", $out );
402 * Get a brief report of profiled functions sorted by inclusive wall clock
403 * time in descending order.
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
411 * @param string $header Header text to prepend to report
412 * @param string $footer Footer text to append to report
415 protected function getSummaryReport( $header = '', $footer = '' ) {
416 $data = $this->xhprof
->getInclusiveMetrics();
417 uasort( $data, Xhprof
::makeSortFunction( 'wt', 'total' ) );
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
,
430 return implode( "\n", $out );
434 * Get a brief report of the most costly code path by wall clock time.
436 * Each line of the report includes this data:
437 * - Total wall clock time spent in function in seconds
440 * @param string $header Header text to prepend to report
441 * @param string $footer Footer text to append to report
444 protected function getCriticalPathReport( $header = '', $footer = '' ) {
445 $data = $this->xhprof
->getCriticalPath();
447 $out = array( $header );
448 $out[] = sprintf( "%7s %9s %9s %6s %4s",
449 'Time%', 'Time', 'Mem', 'Calls', 'Name'
452 $format = '%6.2f%% %9.6f %9d %6d %s%s';
455 foreach ( $data as $key => $stats ) {
456 list( $parent, $child ) = Xhprof
::splitKey( $key );
457 if ( $total === null ) {
460 $out[] = sprintf( $format,
461 100 * $stats['wt'] / $total['wt'],
463 isset( $stats['mu'] ) ?
$stats['mu'] : 0,
465 //$nest ? str_repeat( ' ', $nest - 1 ) . '┗ ' : '',
466 $nest ?
str_repeat( ' ', $nest - 1 ) . '└─' : '',
472 return implode( "\n", $out );