Improving the XHProf Extension
Note: This post is outdated. Please find more information about our current improvements to the XHProf extension on its Github page.
We rely on the XHProf PHP extension to collect profiling data for your applications. XHProf was developed by Facebook during the times when they still used PHP. Since its release it remains largely unmaintained except the occasional bugfix to allow compilation with recent PHP versions. In the last month, the extension moved from the official Facebook repository to another organization and should be considered unmaintained by Facebook.
To allow a stable integration of XHProf with the Tideways in the future, we have started to maintain our own fork of the project. At the moment the fork includes bugfixes and several improvements.
We haven’t started an “offical” repository for the fork yet, instead you will find the code in several branches of our fork.
Our mid-term goal is to release all these changes under an open-source license as a new extension.
Compiling with PHP 5.5.8+
Starting with PHP 5.5.8 XHProf would segfault because of a change in how the Zend Engine represents a function execution. There was an unmerged Pull Request on the XHProf repository which we merged into our fork.
Function Whitelist
Our first new feature is a whitelist of functions to profile as an opposite to ignore_functions that was already implemented using a new option called functions.
With a whitelist of interesting functions such as PDOStatement::execute, curl_exec and file_get_contents you can already find the most critical performance bottlenecks that are I/O related without collecting data for all the other function calls. This improves the performance of XHProf massively allowing to collect data for non-PHP layers on every request.
We have already turned this into a feature in the Tideways where you can see the performance of those layers over time:
Layers
You can activate this functionality by invoking XHProf with the following options:
xhprof_enable(0, array('functions' => array('PDOStatement::execute', 'PDO::commit', 'curl_exec'))); Argument Summary
One drawback of the current XHProf is its one-level hierarchy of tracing data, especially with respect to SQL queries or expensive HTTP/Filesystem calls.
The information that PDOStatement::execute was called 100 times and took 2 seconds is interesting but not nearly as interesting as the information which of the 100 queries was actually slow.
By default XHProf only collects the information about parent and child functions. For this simple script
<?php
xhprof_enable();
for ($i = 0; $i < 3; $i++) {
strlen(str_repeat("x", $i));
}
echo json_encode(xhprof_disable()); the output would look like the JSON structure below:
{
"main()": {
"ct": 1,
"wt": 116
},
"main()==>str_repeat": {
"ct": 3,
"wt": 22
},
"main()==>strlen": {
"ct": 3,
"wt": 1
},
"main()==>xhprof_disable": {
"ct": 1,
"wt": 0
}
} If you wanted to know which of the three calls of strlen was slow, no luck.
Our hosting partner Syseleven worked on solving this question before and came up with a partial improvement of the XHProf extension that allowed defining a whitelist of functions whose arguments should be included in the profiling. Changing the script:
<?php
xhprof_enable(0, array('argument_functions' => 'strlen'));
for ($i = 0; $i < 3; $i++) { strlen(str_repeat("x", $i)); }
echo json_encode(xhprof_disable()); Would yield:
{
"main()": {
"ct": 1,
"wt": 130
},
"main()==>str_repeat": {
"ct": 3,
"wt": 18
},
"main()==>strlen#": {
"ct": 1,
"wt": 1
},
"main()==>strlen#x": {
"ct": 1,
"wt": 0
},
"main()==>strlen#xx": {
"ct": 1,
"wt": 0
},
"main()==>xhprof_disable": {
"ct": 1,
"wt": 0
}
} This works for simple functions only, not for those that rely on data from previous function calls. That means curl_exec, PDOStatement::execute and almost any filesystem related call such as fgets would not show the arguments you are interested in. In addition SQL queries, filenames and URLs can be very long, but we are limiting the size of keys to 255 chars to avoid massive memory consumption of the profiling data structure.
That is why we have improved the Syseleven patch to handle the following special cases:
fopenshows the opened file or url as well as the resource id. Query Strings are omitted.fgets,fputs,fcloseand many related functions show the passed resource id, allowing correlation withfopencalls.curl_execshows the requested url except the query string.PDOStatement::executeshows the executed SQL query as a summary, which contains of the primary SQL keyword (select, update, delete, insert, other) and the affected main/first table found in the SQL statement.- Every PDO, ext/mysql and ext/mysqli query that executes a query shows a summary of the query.
Let’s look at a simple example to understand how those special cases are handled:
<?php
$args = array('fopen', 'fgets', 'curl_exec', 'PDOStatement::execute'); xhprof_enable(0, array('argument_functions' => $args));
$pdo = new PDO('sqlite:memory:'); $pdo->exec('CREATE TABLE foo (id INT)'); $stmt = $pdo->prepare('SELECT * FROM foo'); $stmt->execute();
$fh = fopen(__FILE__, 'r'); while ($line = fgets($fh)) { }
$ch = curl_init('http://qafoo.com'); curl_setopt($ch, CURLOPT_RETURNTRANSFER, true); curl_exec($ch);
echo json_encode(xhprof_disable()); And its related XHProf Output formatted as JSON:
{
"main()": {
"ct": 1,
"wt": 5730
},
"main()==>PDO::__construct": {
"ct": 1,
"wt": 277
},
"main()==>PDO::exec": {
"ct": 1,
"wt": 379
},
"main()==>PDO::prepare": {
"ct": 1,
"wt": 39
},
"main()==>PDOStatement::execute#select foo": {
"ct": 1, "wt": 44 },
"main()==>curl_exec#http://qafoo.com#7": {
"ct": 1,
"wt": 4457
},
"main()==>curl_init": {
"ct": 1,
"wt": 73
},
"main()==>curl_setopt": {
"ct": 1,
"wt": 15
},
"main()==>fgets#5": {
"ct": 21,
"wt": 28
},
"main()==>fopen#/tmp/args.php#4": {
"ct": 1,
"wt": 28
},
"main()==>xhprof_disable": {
"ct": 1,
"wt": 1
}
} Argument summaries are still experimental and we are currently cleaning up the code before releasing another binary and integrating its output into the Tideways UI.
If you want to experiment with it, the code is currently residing in the sql_summary branch on Github.
Compiling it requires one additional manual step, copying the file ext/curl/php_curl.h from the php-src into the include folder, because it isn’t exposed to other extensions by default.
We have plans for further improvements:
- Support for profiling template engines such as Smarty and Twig
- Grouping PDO and mysqli calls by Transaction-IDs to allow profiling commit operations and their related queries.
- ext/MongoDB Support
We are also open for suggestions to add other extensions or functions, maybe even framework/application related support if it makes sense.
Asynchronous Calls
PHP has limited support for asynchronous I/O, some extensions however provide such functionality for example curl_multi_exec, mysqli_async_query and stream_select.
When profiling code with multiple execution paths running at the same time, XHProf would currently ignore all the asynchronouspaths and only report the wall time for the PHP request itself.
We are currently planing to add a feature that will track the asynchronous paths as well. With this functionality you can see the duration of async queries and requests through the Tideways UI and get numbers on how efficiently you use async operations.
Conclusion
XHProf is very much alive and we are enjoying to work on all the improvements. We want to contribute all these changes back to the community as OpenSource patches so you can benefit even without using our Profiler offering.
