wiki.techinc.nl/includes/profiler/ProfilerXhprof.php

237 lines
6.9 KiB
PHP
Raw Normal View History

<?php
/**
* 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.
*
* @code
* $wgProfiler['class'] = ProfilerXhprof::class;
* $wgProfiler['flags'] = XHPROF_FLAGS_NO_BUILTINS;
* $wgProfiler['output'] = 'text';
* $wgProfiler['visible'] = true;
* @endcode
*
* @code
* $wgProfiler['class'] = ProfilerXhprof::class;
* $wgProfiler['flags'] = XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY | XHPROF_FLAGS_NO_BUILTINS;
* $wgProfiler['output'] = 'udp';
* @endcode
*
* 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.
* Shell-style patterns are also accepted.
*
* This also supports Tideways-XHProf PHP extension, which is mostly a drop-in
* replacement for Xhprof (replace XHPROF_FLAGS_* with XHPROF_TIDEWAYS_FLAGS_*),
* as well as the older (discontinued) Tideways extension (TIDEWAYS_FLAGS_*).
*
* @copyright © 2014 Wikimedia Foundation and contributors
* @ingroup Profiler
* @see Xhprof
* @see https://php.net/xhprof
* @see https://github.com/facebook/hhvm/blob/master/hphp/doc/profiling.md
* @see https://github.com/tideways/php-xhprof-extension
*/
class ProfilerXhprof extends Profiler {
/**
Decouple Xhprof profiling from profiling data processing The motivation for this patch came from trying to use xhprof to profile the unit tests. I was able to profile specific test suites, but if I tried to profile a complete PHPUnit run, I ended up with empty profiling data. My initial suspicion was that this was due to some Xhprof buffer getting exhausted. The actual reason ended up being much simpler: the XhprofTest suite indirectly called xhprof_enable() / xhprof_disable(), which stopped xhprof and cleared out the data, so that when I was calling xhprof_disable() at the end of the run, there was no profiling data to return, because xhprof was not running. For the most part the XhprofTest was already doing the right thing by trying to avoid having side-effects or relying on xhprof. Wherever possible, test fixture profiling data was used in lieu of actually running xhprof. But this was not totally successful because the Xhprof class coupled the collection of data to the processing of data. Xhprof::__construct() called xhprof_enable(), so there was no real way around that. I think that the right way to fix that is to decouple profiling from profiling data analysis. Thus I renamed 'Xhprof' to 'XhprofData', and modified the class so that it expects to be fed profiling data rather than going out and collecting it on its own. As a result, it is now possible to profile a full phpunit run with xhprof, and the work that went into writing fixtures for the Xhprof unit tests pays off: the class and the tests no longer have a hard dependency on the xhprof extension, and the tests do not have to be skipped when it is not installed. And the tests are really testing the system under test, rather than the xhprof extension. Finally, I added a new Xhprof class, which really is just an extremely thin wrapper around xhprof_enable() / xhprof_disable(). The only extra functionality it provides is the ability to check whether xhprof is running, via Xhprof::isEnabled(). Calling Xhprof::enable() when it is already enabled will cause an exception to be thrown. This should help us avoid running into situations where two components contend for control of the profiler without realizing it. A unit test tests this behavior. The only part of this change that is not covered by tests is the change to ProfilerXhprof. I tested it manually and it works. Change-Id: Ica96beded68f04083abaf48ef1ae8c726eb60fa6
2016-05-12 18:10:39 +00:00
* @var XhprofData|null $xhprofData
*/
Decouple Xhprof profiling from profiling data processing The motivation for this patch came from trying to use xhprof to profile the unit tests. I was able to profile specific test suites, but if I tried to profile a complete PHPUnit run, I ended up with empty profiling data. My initial suspicion was that this was due to some Xhprof buffer getting exhausted. The actual reason ended up being much simpler: the XhprofTest suite indirectly called xhprof_enable() / xhprof_disable(), which stopped xhprof and cleared out the data, so that when I was calling xhprof_disable() at the end of the run, there was no profiling data to return, because xhprof was not running. For the most part the XhprofTest was already doing the right thing by trying to avoid having side-effects or relying on xhprof. Wherever possible, test fixture profiling data was used in lieu of actually running xhprof. But this was not totally successful because the Xhprof class coupled the collection of data to the processing of data. Xhprof::__construct() called xhprof_enable(), so there was no real way around that. I think that the right way to fix that is to decouple profiling from profiling data analysis. Thus I renamed 'Xhprof' to 'XhprofData', and modified the class so that it expects to be fed profiling data rather than going out and collecting it on its own. As a result, it is now possible to profile a full phpunit run with xhprof, and the work that went into writing fixtures for the Xhprof unit tests pays off: the class and the tests no longer have a hard dependency on the xhprof extension, and the tests do not have to be skipped when it is not installed. And the tests are really testing the system under test, rather than the xhprof extension. Finally, I added a new Xhprof class, which really is just an extremely thin wrapper around xhprof_enable() / xhprof_disable(). The only extra functionality it provides is the ability to check whether xhprof is running, via Xhprof::isEnabled(). Calling Xhprof::enable() when it is already enabled will cause an exception to be thrown. This should help us avoid running into situations where two components contend for control of the profiler without realizing it. A unit test tests this behavior. The only part of this change that is not covered by tests is the change to ProfilerXhprof. I tested it manually and it works. Change-Id: Ica96beded68f04083abaf48ef1ae8c726eb60fa6
2016-05-12 18:10:39 +00:00
protected $xhprofData;
/**
* Profiler for explicit, arbitrary, frame labels
* @var SectionProfiler
*/
protected $sprofiler;
/**
* @param array $params
* @see Xhprof::__construct()
*/
public function __construct( array $params = [] ) {
parent::__construct( $params );
Decouple Xhprof profiling from profiling data processing The motivation for this patch came from trying to use xhprof to profile the unit tests. I was able to profile specific test suites, but if I tried to profile a complete PHPUnit run, I ended up with empty profiling data. My initial suspicion was that this was due to some Xhprof buffer getting exhausted. The actual reason ended up being much simpler: the XhprofTest suite indirectly called xhprof_enable() / xhprof_disable(), which stopped xhprof and cleared out the data, so that when I was calling xhprof_disable() at the end of the run, there was no profiling data to return, because xhprof was not running. For the most part the XhprofTest was already doing the right thing by trying to avoid having side-effects or relying on xhprof. Wherever possible, test fixture profiling data was used in lieu of actually running xhprof. But this was not totally successful because the Xhprof class coupled the collection of data to the processing of data. Xhprof::__construct() called xhprof_enable(), so there was no real way around that. I think that the right way to fix that is to decouple profiling from profiling data analysis. Thus I renamed 'Xhprof' to 'XhprofData', and modified the class so that it expects to be fed profiling data rather than going out and collecting it on its own. As a result, it is now possible to profile a full phpunit run with xhprof, and the work that went into writing fixtures for the Xhprof unit tests pays off: the class and the tests no longer have a hard dependency on the xhprof extension, and the tests do not have to be skipped when it is not installed. And the tests are really testing the system under test, rather than the xhprof extension. Finally, I added a new Xhprof class, which really is just an extremely thin wrapper around xhprof_enable() / xhprof_disable(). The only extra functionality it provides is the ability to check whether xhprof is running, via Xhprof::isEnabled(). Calling Xhprof::enable() when it is already enabled will cause an exception to be thrown. This should help us avoid running into situations where two components contend for control of the profiler without realizing it. A unit test tests this behavior. The only part of this change that is not covered by tests is the change to ProfilerXhprof. I tested it manually and it works. Change-Id: Ica96beded68f04083abaf48ef1ae8c726eb60fa6
2016-05-12 18:10:39 +00:00
$flags = $params['flags'] ?? 0;
Decouple Xhprof profiling from profiling data processing The motivation for this patch came from trying to use xhprof to profile the unit tests. I was able to profile specific test suites, but if I tried to profile a complete PHPUnit run, I ended up with empty profiling data. My initial suspicion was that this was due to some Xhprof buffer getting exhausted. The actual reason ended up being much simpler: the XhprofTest suite indirectly called xhprof_enable() / xhprof_disable(), which stopped xhprof and cleared out the data, so that when I was calling xhprof_disable() at the end of the run, there was no profiling data to return, because xhprof was not running. For the most part the XhprofTest was already doing the right thing by trying to avoid having side-effects or relying on xhprof. Wherever possible, test fixture profiling data was used in lieu of actually running xhprof. But this was not totally successful because the Xhprof class coupled the collection of data to the processing of data. Xhprof::__construct() called xhprof_enable(), so there was no real way around that. I think that the right way to fix that is to decouple profiling from profiling data analysis. Thus I renamed 'Xhprof' to 'XhprofData', and modified the class so that it expects to be fed profiling data rather than going out and collecting it on its own. As a result, it is now possible to profile a full phpunit run with xhprof, and the work that went into writing fixtures for the Xhprof unit tests pays off: the class and the tests no longer have a hard dependency on the xhprof extension, and the tests do not have to be skipped when it is not installed. And the tests are really testing the system under test, rather than the xhprof extension. Finally, I added a new Xhprof class, which really is just an extremely thin wrapper around xhprof_enable() / xhprof_disable(). The only extra functionality it provides is the ability to check whether xhprof is running, via Xhprof::isEnabled(). Calling Xhprof::enable() when it is already enabled will cause an exception to be thrown. This should help us avoid running into situations where two components contend for control of the profiler without realizing it. A unit test tests this behavior. The only part of this change that is not covered by tests is the change to ProfilerXhprof. I tested it manually and it works. Change-Id: Ica96beded68f04083abaf48ef1ae8c726eb60fa6
2016-05-12 18:10:39 +00:00
$options = isset( $params['exclude'] )
? [ 'ignored_functions' => $params['exclude'] ] : [];
Xhprof::enable( $flags, $options );
$this->sprofiler = new SectionProfiler();
}
Decouple Xhprof profiling from profiling data processing The motivation for this patch came from trying to use xhprof to profile the unit tests. I was able to profile specific test suites, but if I tried to profile a complete PHPUnit run, I ended up with empty profiling data. My initial suspicion was that this was due to some Xhprof buffer getting exhausted. The actual reason ended up being much simpler: the XhprofTest suite indirectly called xhprof_enable() / xhprof_disable(), which stopped xhprof and cleared out the data, so that when I was calling xhprof_disable() at the end of the run, there was no profiling data to return, because xhprof was not running. For the most part the XhprofTest was already doing the right thing by trying to avoid having side-effects or relying on xhprof. Wherever possible, test fixture profiling data was used in lieu of actually running xhprof. But this was not totally successful because the Xhprof class coupled the collection of data to the processing of data. Xhprof::__construct() called xhprof_enable(), so there was no real way around that. I think that the right way to fix that is to decouple profiling from profiling data analysis. Thus I renamed 'Xhprof' to 'XhprofData', and modified the class so that it expects to be fed profiling data rather than going out and collecting it on its own. As a result, it is now possible to profile a full phpunit run with xhprof, and the work that went into writing fixtures for the Xhprof unit tests pays off: the class and the tests no longer have a hard dependency on the xhprof extension, and the tests do not have to be skipped when it is not installed. And the tests are really testing the system under test, rather than the xhprof extension. Finally, I added a new Xhprof class, which really is just an extremely thin wrapper around xhprof_enable() / xhprof_disable(). The only extra functionality it provides is the ability to check whether xhprof is running, via Xhprof::isEnabled(). Calling Xhprof::enable() when it is already enabled will cause an exception to be thrown. This should help us avoid running into situations where two components contend for control of the profiler without realizing it. A unit test tests this behavior. The only part of this change that is not covered by tests is the change to ProfilerXhprof. I tested it manually and it works. Change-Id: Ica96beded68f04083abaf48ef1ae8c726eb60fa6
2016-05-12 18:10:39 +00:00
/**
* @return XhprofData
*/
public function getXhprofData() {
if ( !$this->xhprofData ) {
$this->xhprofData = new XhprofData( Xhprof::disable(), $this->params );
}
return $this->xhprofData;
}
public function scopedProfileIn( $section ) {
$key = 'section.' . ltrim( $section, '.' );
return $this->sprofiler->scopedProfileIn( $key );
}
/**
* No-op for xhprof profiling.
*/
public function close() {
}
/**
* Check if a function or section should be excluded from the output.
*
* @param string $name Function or section name.
* @return bool
*/
private function shouldExclude( $name ) {
if ( $name === '-total' ) {
return true;
}
if ( !empty( $this->params['include'] ) ) {
foreach ( $this->params['include'] as $pattern ) {
if ( fnmatch( $pattern, $name, FNM_NOESCAPE ) ) {
return false;
}
}
return true;
}
if ( !empty( $this->params['exclude'] ) ) {
foreach ( $this->params['exclude'] as $pattern ) {
if ( fnmatch( $pattern, $name, FNM_NOESCAPE ) ) {
return true;
}
}
}
return false;
}
public function getFunctionStats() {
Decouple Xhprof profiling from profiling data processing The motivation for this patch came from trying to use xhprof to profile the unit tests. I was able to profile specific test suites, but if I tried to profile a complete PHPUnit run, I ended up with empty profiling data. My initial suspicion was that this was due to some Xhprof buffer getting exhausted. The actual reason ended up being much simpler: the XhprofTest suite indirectly called xhprof_enable() / xhprof_disable(), which stopped xhprof and cleared out the data, so that when I was calling xhprof_disable() at the end of the run, there was no profiling data to return, because xhprof was not running. For the most part the XhprofTest was already doing the right thing by trying to avoid having side-effects or relying on xhprof. Wherever possible, test fixture profiling data was used in lieu of actually running xhprof. But this was not totally successful because the Xhprof class coupled the collection of data to the processing of data. Xhprof::__construct() called xhprof_enable(), so there was no real way around that. I think that the right way to fix that is to decouple profiling from profiling data analysis. Thus I renamed 'Xhprof' to 'XhprofData', and modified the class so that it expects to be fed profiling data rather than going out and collecting it on its own. As a result, it is now possible to profile a full phpunit run with xhprof, and the work that went into writing fixtures for the Xhprof unit tests pays off: the class and the tests no longer have a hard dependency on the xhprof extension, and the tests do not have to be skipped when it is not installed. And the tests are really testing the system under test, rather than the xhprof extension. Finally, I added a new Xhprof class, which really is just an extremely thin wrapper around xhprof_enable() / xhprof_disable(). The only extra functionality it provides is the ability to check whether xhprof is running, via Xhprof::isEnabled(). Calling Xhprof::enable() when it is already enabled will cause an exception to be thrown. This should help us avoid running into situations where two components contend for control of the profiler without realizing it. A unit test tests this behavior. The only part of this change that is not covered by tests is the change to ProfilerXhprof. I tested it manually and it works. Change-Id: Ica96beded68f04083abaf48ef1ae8c726eb60fa6
2016-05-12 18:10:39 +00:00
$metrics = $this->getXhprofData()->getCompleteMetrics();
$profile = [];
$main = null; // units in ms
foreach ( $metrics as $fname => $stats ) {
if ( $this->shouldExclude( $fname ) ) {
continue;
}
// Convert elapsed times from μs to ms to match interface
$entry = [
'name' => $fname,
'calls' => $stats['ct'],
'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_real' => $stats['wt']['min'] / 1000,
'max_real' => $stats['wt']['max'] / 1000
];
$profile[] = $entry;
if ( $fname === 'main()' ) {
$main = $entry;
}
}
// Merge in all of the custom profile sections
foreach ( $this->sprofiler->getFunctionStats() as $stats ) {
if ( $this->shouldExclude( $stats['name'] ) ) {
continue;
}
// @note: getFunctionStats() values already in ms
$stats['%real'] = $main['real'] ? $stats['real'] / $main['real'] * 100 : 0;
$stats['%cpu'] = $main['cpu'] ? $stats['cpu'] / $main['cpu'] * 100 : 0;
$stats['%memory'] = $main['memory'] ? $stats['memory'] / $main['memory'] * 100 : 0;
$profile[] = $stats; // assume no section names collide with $metrics
}
return $profile;
}
/**
* 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->getFunctionStats();
usort( $data, function ( $a, $b ) {
return $b['real'] <=> $a['real']; // descending
} );
$width = 140;
$nameWidth = $width - 65;
$format = "%-{$nameWidth}s %6d %9d %9d %9d %9d %7.3f%% %9d";
$out = [];
$out[] = sprintf( "%-{$nameWidth}s %6s %9s %9s %9s %9s %7s %9s",
'Name', 'Calls', 'Total', 'Min', 'Each', 'Max', '%', 'Mem'
);
foreach ( $data as $stats ) {
$out[] = sprintf( $format,
$stats['name'],
$stats['calls'],
$stats['real'] * 1000,
$stats['min_real'] * 1000,
$stats['real'] / $stats['calls'] * 1000,
$stats['max_real'] * 1000,
$stats['%real'],
$stats['memory']
);
}
return implode( "\n", $out );
}
/**
* Retrieve raw data from xhprof
* @return array
*/
public function getRawData() {
Decouple Xhprof profiling from profiling data processing The motivation for this patch came from trying to use xhprof to profile the unit tests. I was able to profile specific test suites, but if I tried to profile a complete PHPUnit run, I ended up with empty profiling data. My initial suspicion was that this was due to some Xhprof buffer getting exhausted. The actual reason ended up being much simpler: the XhprofTest suite indirectly called xhprof_enable() / xhprof_disable(), which stopped xhprof and cleared out the data, so that when I was calling xhprof_disable() at the end of the run, there was no profiling data to return, because xhprof was not running. For the most part the XhprofTest was already doing the right thing by trying to avoid having side-effects or relying on xhprof. Wherever possible, test fixture profiling data was used in lieu of actually running xhprof. But this was not totally successful because the Xhprof class coupled the collection of data to the processing of data. Xhprof::__construct() called xhprof_enable(), so there was no real way around that. I think that the right way to fix that is to decouple profiling from profiling data analysis. Thus I renamed 'Xhprof' to 'XhprofData', and modified the class so that it expects to be fed profiling data rather than going out and collecting it on its own. As a result, it is now possible to profile a full phpunit run with xhprof, and the work that went into writing fixtures for the Xhprof unit tests pays off: the class and the tests no longer have a hard dependency on the xhprof extension, and the tests do not have to be skipped when it is not installed. And the tests are really testing the system under test, rather than the xhprof extension. Finally, I added a new Xhprof class, which really is just an extremely thin wrapper around xhprof_enable() / xhprof_disable(). The only extra functionality it provides is the ability to check whether xhprof is running, via Xhprof::isEnabled(). Calling Xhprof::enable() when it is already enabled will cause an exception to be thrown. This should help us avoid running into situations where two components contend for control of the profiler without realizing it. A unit test tests this behavior. The only part of this change that is not covered by tests is the change to ProfilerXhprof. I tested it manually and it works. Change-Id: Ica96beded68f04083abaf48ef1ae8c726eb60fa6
2016-05-12 18:10:39 +00:00
return $this->getXhprofData()->getRawData();
}
}