Debugging WordPress: Find Slow Filters and Actions

English: WordPress Logo

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.

“But wait”, you say, “Just add the profiling to the ‘all’ filter and you don’t have to do all this.”  That’s probably fine for most cases.  This method measures actions and filters that execute before plugins are loaded.  Additionally, there’s always the chance of a priority conflict even if you put priority 0, because if there are multiple items at the same priority level they just get appended to the list, so your profiling hook may execute after another action/filter.

So without further ado:

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();
About these ads

4 thoughts on “Debugging WordPress: Find Slow Filters and Actions

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s