This is one of the ways I diagnose performance issues within WordPress, specifically “hey this site is slow, what can we do to speed it up?” Whereas a callgrind file gives you a look into the whole callstack of your script, the point of this is to profile actions and filters in WordPress.
It does require that you make some changes to core files. This is not meant to be something that you use in production, nor is it meant to be something you run all the time. This is for “spring cleaning” your site, and/or tracking down general slowness.
The code between “// @custom start” and “// @custom end” is what you will be adding. I am not including line numbers because they change frequently with the version of WordPress.
index.php
Put this at the top of index.php, before any other code.
class Pmc_Debug
{
protected static $_threshold_to_hide = 0.1;
public static function get_threshold_to_hide() {
return static::$_threshold_to_hide;
}
public static function set_threshold_to_hide( $time ) {
static::$_threshold_to_hide = (float) $time;
}
public static function record_action( $name ) {
$backtrace = debug_backtrace(false);
if ( ! isset($backtrace[2]['args']) ) {
return;
}
foreach ( $backtrace[2]['args'] as &$arg ) {
$arg = ( is_string($arg) ) ? stripslashes($arg) : $arg;
}
$GLOBALS['pmc_action_timer'][microtime()][] = array(
'name' => $name,
'backtrace' => var_export($backtrace[2], true),
);
}
public static function print_recorded_actions() {
?>
<hr />
<div style="padding: 10px; background-color: white; color: black; white-space: pre; text-align: left;">
<pre>
<?php
$timetotals = array();
$break = '<hr />';
$eol = '<br />';
$detail_list = $eol . $eol . $break . $eol . $eol;
$detail_list .= 'Detail action list.' . $eol;
if ( static::get_threshold_to_hide() > 0.0 ) {
$detail_list .= 'Hiding items faster than ' . static::get_threshold_to_hide() . ' seconds.' . $eol;
}
$detail_list .= $eol . $break . $eol;
reset($GLOBALS['pmc_action_timer']);
$previous_item = array('timestamp' => array('sec' => 0.0, 'usec' => 0.0), 'items' => array());
do {
if ( ! isset( $timestamp ) ) {
$timestamp = microtime();
}
if ( ! isset( $items ) ) {
$items = array();
}
list($usec, $sec) = explode(" ", $timestamp);
$sec = (float) $sec;
$usec = (float) $usec;
$timestamp_float = $sec + $usec;
if ( $timestamp && ! isset($start_time) ) {
$start_time = $timestamp_float;
} else {
$end_time = $timestamp_float;
}
if ( empty($previous_items['items']) ) {
$diff = 0.0;
$previous_items['items'][] = array('name' => 'nothing', 'backtrace' => '');
} else {
$diff = $timestamp_float - ( $previous_items['timestamp']['sec'] + $previous_items['timestamp']['usec'] );
}
if ( $diff > static::get_threshold_to_hide() ) {
$previous = array();
if ( ! empty($previous_items['items']) ) {
foreach ( $previous_items['items'] as $previous_item ) {
$previous[] = $previous_item['name'];
}
}
foreach ( $items as $item ) {
$detail_list .= $eol . round($diff, 3) . ' seconds between starting ' . implode(', ', $previous) . ' and starting ' . $item['name'] . $eol;
if ( ! empty($previous_items['items']) ) {
foreach ( $previous_items['items'] as $previous_item ) {
$detail_list .= $previous_item['backtrace'] . $eol;
}
}
$detail_list .= $item['backtrace'] . $eol;
}
}
foreach ( $items as $key => $item ) {
$timetotals[$item['name']][] = $diff;
}
$previous_items['timestamp']['sec'] = $sec;
$previous_items['timestamp']['usec'] = $usec;
$previous_items['items'] = $items;
} while ( list($timestamp, $items) = each($GLOBALS['pmc_action_timer']) );
$detail_list .= $eol . $break . $eol;
$summary_list = $eol . $eol . $break . $eol . $eol;
$summary_list .= 'Action overview: aggregate totals.' . $eol;
if ( static::get_threshold_to_hide() > 0.0 ) {
$summary_list .= 'Hiding items faster than ' . static::get_threshold_to_hide() . ' seconds.' . $eol;
}
$summary_list .= $eol . $break . $eol;
do {
$total_time = 0.0;
if ( isset($times) ) {
foreach ( $times as $time ) {
$total_time += $time;
}
}
if ( $total_time > static::get_threshold_to_hide() ) {
$summary_list .= $tag . ' took approximately ' . round($total_time, 3) . ' seconds' . $eol;
}
} while ( list($tag, $times) = each($timetotals) );
$summary_list .= $eol . $break . $eol;
if ( $end_time < $start_time ) {
$end_time = $start_time;
}
echo 'Request took ' . ( $end_time - $start_time ) . ' seconds from start to finish.' . $eol;
echo $summary_list;
echo $detail_list;
?>
</pre>
</div>
<?php
}
}
Pmc_Debug::record_action('bootup');
wp-includes/plugin.php
In this file, look for the functions below and add the lines between “@custom start” and “@custom end”. Basically, they go at the top of all the functions where filters are applied and actions are called.
function do_action($tag, $arg = '') {
global $wp_filter, $wp_actions, $merged_filters, $wp_current_filter;
// @custom start
Pmc_Debug::record_action($tag);
// @custom end
function do_action_ref_array($tag, $args) {
global $wp_filter, $wp_actions, $merged_filters, $wp_current_filter;
// @custom start
Pmc_Debug::record_action($tag);
// @custom end
function apply_filters($tag, $value) {
global $wp_filter, $merged_filters, $wp_current_filter;
// @custom start
Pmc_Debug::record_action($tag);
// @custom end
function apply_filters_ref_array($tag, $args) {
global $wp_filter, $merged_filters, $wp_current_filter;
// @custom start
Pmc_Debug::record_action($tag);
// @custom end
wp-content/themes/my-theme/footer.php
Here is the code that outputs the results. This goes anywhere after the wp_footer() function, but it’s easiest just to put it before the closing </html> tag.
Pmc_Debug::record_action('done');
Pmc_Debug::print_recorded_actions();
33.946465
-118.369885
