Derrick.Blarg

Tag: time-measurement

  • Silly Ideas: Cache WordPress Excerpts

    Silly Ideas: Cache WordPress Excerpts

    I recently worked on profiling a customer site for performance problems, and one of the issues that I had seen was that calls to get_the_excerpt() were running HORRIBLY slow due to filters.

    I ended up writing a really hacky workaround to cache excerpts to help reduce the burden they had on the page generation time, but we ended up not using this solution. Instead we found another filter in a plugin that removed the painfully slow stuff happening in the excerpt.

    So below is one potential way to cache your excerpt, but be warned it’s only barely tested:

    /**
 * Checks the excerpt cache for a post and returns the cached excerpt if available.
 * If the post is password protected, the original post excerpt is returned.
 *
 * @param string  $post_excerpt The original post excerpt.
 * @param WP_Post $post         The post object.
 *
 * @return string The post excerpt, either from the cache or the original.
 */
function blarg_check_excerpt_cache( string $post_excerpt, WP_Post $post ): string {
	// We do not want to cache password protected posts.
	if ( post_password_required( $post ) ) {
		return $post_excerpt;
	}

	$cache_key   = $post->ID;
	$cache_group = 'blarg_cached_post_excerpt';
	$cache_data  = wp_cache_get( $cache_key, $cache_group );

	if ( false !== $cache_data ) {
		remove_all_filters( 'get_the_excerpt' );
		add_filter( 'get_the_excerpt', 'blarg_check_excerpt_cache', PHP_INT_MIN, 2 );
		$post_excerpt = $cache_data;
	} else {
		add_filter( 'get_the_excerpt', 'blarg_cache_the_excerpt', PHP_INT_MAX, 2 );
	}

	// At this point, do not modify anything and return.
	return $post_excerpt;
}
add_filter( 'get_the_excerpt', 'blarg_check_excerpt_cache', PHP_INT_MIN, 2 );

/**
 * Caches the post excerpt in the WordPress object cache.
 *
 * @param string  $post_excerpt The post excerpt to cache.
 * @param WP_Post $post         The post object.
 *
 * @return string The cached post excerpt.
 */
function blarg_cache_the_excerpt( string $post_excerpt, WP_Post $post ): string {
	$cache_key   = $post->ID;
	$cache_group = 'blarg_cached_post_excerpt';
	wp_cache_set( $cache_key, $post_excerpt, $cache_group );

	return $post_excerpt;
}

/**
 * Deletes the cached excerpt for a given post.
 *
 * @param int|WP_Post $post The post ID or WP_Post object.
 *
 * @return void
 */
function blarg_delete_the_excerpt_cache( int|WP_Post $post ): void {
	if ( $post instanceof WP_Post ) {
		$post_id = $post->ID;
	} else {
		$post_id = $post;
	}

	$cache_key   = $post_id;
	$cache_group = 'blarg_cached_post_excerpt';
	wp_cache_delete( $cache_key, $cache_group );
}
add_action( 'clean_post_cache', 'blarg_delete_the_excerpt_cache', 10, 1 );
Code language: PHP (php)

    This should automatically clear out the cache any time the post is updated, but if the excerpt gets updated in any other way you may need to purge the cache in other ways.

    Good luck with this monstrosity!

  • Bash Script: Calculate before/after 2: Calculate Harder

    Bash Script: Calculate before/after 2: Calculate Harder

    As an update, or an evolution of my earlier script that did some simple math for me, I’ve made one that will full-on test a URL while I’m making changes to see what the impact performance is of my updates.

    $ abtesturl.sh --url=https://example.com/ --count=10
Press any key to run initial tests...
Initial average TTFB: 3.538 seconds
Press any key to re-run tests...

Running second test...
Second average TTFB: 1.975 seconds
Before TTFB: 3.538 seconds
After TTFB: 1.975 seconds
Change in TTFB: -1.563 seconds
Percentage Change: -44.00%Code language: JavaScript (javascript)

    It makes it much simpler to gather data to write reports or figure out of a change is worth the effort.

    Well, that’s about it so here’s the script:

    #!/bin/bash

function show_usage() {
	echo "Usage: $0 --url=<URL> [--count=<number of requests>]"
	echo "  --url        Specifies the URL to test."
	echo "  --count      Optional. Specifies the number of requests to send. Default is 6."
	echo
	echo "Example: $0 --url=https://example.com/ --count=5"
	exit
}

function average_ttfb() {
	local URL=""
	local COUNT=6 # Default COUNT to 6 if not supplied
	local CURL_OPTS="-s"

	# Parse arguments
	for arg in "$@"; do
		case $arg in
			--url=*)
			URL="${arg#*=}"
			shift # Remove argument from processing
			;;
		--count=*)
			COUNT="${arg#*=}"
			shift # Remove argument from processing
			;;
		*)
			# Unknown option
			;;
		esac
	done

	if [[ -z "$URL" ]]; then
		exit 1
	fi

	local total_time=0
	local count_success=0

	for ((i=1; i<=COUNT; i++))
	do
		# Perform the curl command, extracting the time to first byte
		ttfb=$(curl $CURL_OPTS -o /dev/null -w "%{time_starttransfer}\n" $URL)
		
		# Check if the curl command was successful
		if [ $? -eq 0 ]; then
			total_time=$(echo "$total_time + $ttfb" | bc)
			((count_success++))
		else
			echo "Request $i failed." >&2
		fi
	done

	if [ $count_success -eq 0 ]; then
		echo "All requests failed." >&2
		return 1
	fi

	# Calculate the average TTFB
	average_time=$(echo "scale=3; $total_time / $count_success" | bc)
	echo $average_time # This line now simply outputs the average time
}

function ab_test_ttfb() {
	# Run initial test
	read -p "Press any key to run initial tests..." -n 1 -r
	initial_ttfb=$(set -e; average_ttfb "$@"; set +e)
	echo "Initial average TTFB: $initial_ttfb seconds"
	
	# Wait for user input to proceed
	read -p "Press any key to re-run tests..." -n 1 -r
	echo # Move to a new line

	# Run second test
	echo "Running second test..."
	second_ttfb=$(average_ttfb "$@")
	echo "Second average TTFB: $second_ttfb seconds"

	# Calculate and output the difference and percentage change
	difference=$(echo "$second_ttfb - $initial_ttfb" | bc)
	percent_change=$(echo "scale=2; ($difference / $initial_ttfb) * 100" | bc)

	echo "Before TTFB: $initial_ttfb seconds"
	echo "After TTFB: $second_ttfb seconds"
	echo "Change in TTFB: $difference seconds"
	echo "Percentage Change: $percent_change%"
}

# Check if help is requested or no arguments are provided
if [[ " $* " == *" --help "* ]] || [[ "$#" -eq 0 ]]; then
	show_usage
fi

# Check if --url is in the arguments
url_present=false
for arg in "$@"; do
	if [[ $arg == --url=* ]]; then
		url_present=true
		break
	fi
done

if [ "$url_present" = false ]; then
	echo "Error: --url argument is required."
	show_usage
fi

ab_test_ttfb "$@"Code language: Bash (bash)

    Don’t break anything!

  • Command Timing in ZSH

    Command Timing in ZSH

    I’ve had a few snippets in my .zshrc file for a while now that will output how long a command takes to process.

    First off, I’d like to say that I did not come up with this idea, and I didn’t really write the code. I’ve snipped it from somewhere and modified it over time, so I am very sorry to the original author for not being able to give full credit. I didn’t save where I got it from–so if anyone comes across this in the future and might know where the idea came from, drop it in the comments.

    Now, on to the fun:

    The original script only went down to the second, but I wanted more granularity than that, so I went down to the millisecond.

    You’ll likely need to install gdate (brew install gdate) for this to work properly.

    The code (added to ~/.zshrc):

    function preexec() {
	timer=$(($(gdate +%s%0N)/1000000))
}

function precmd() {
	if [ "$timer" ]; then
		now=$(($(gdate +%s%0N)/1000000))
		elapsed=$now-$timer

		reset_color=$'\e[00m'
		RPROMPT="%F{cyan} $(converts "$elapsed") %{$reset_color%}"
		export RPROMPT
		unset timer
	fi
}

converts() {
	local t=$1

	local d=$((t/1000/60/60/24))
	local h=$((t/1000/60/60%24))
	local m=$((t/100/60%60))
	local s=$((t/1000%60))
	local ms=$((t%1000))

	if [[ $d -gt 0 ]]; then
			echo -n " ${d}d"
	fi
	if [[ $h -gt 0 ]]; then
			echo -n " ${h}h"
	fi
	if [[ $m -gt 0 ]]; then
			echo -n " ${m}m"
	fi
	if [[ $s -gt 0 ]]; then
		echo -n " ${s}s"
	fi
	if [[ $ms -gt 0 ]]; then
		echo -n " ${ms}ms"
	fi
	echo
}Code language: PHP (php)
  • Debugging WordPress Hooks: Speed

    Debugging WordPress Hooks: Speed

    If you google debugging WordPress hooks you’ll find a lot of information.

    About 1,180,000 results

    Let’s add another one.

    WordPress hooks are powerful, but also complex under the hood. There’s plenty of topics I could talk about here, but right now I’m only going to talk about speed. How long does it take for a hook to fire and return?

    Some cool work in this area has already been done thanks to Debug Bar Slow Actions and Query Monitor, but outside of something like Xdebug or New Relic, you’ll have a hard time figuring out how long each individual hook callback takes without modifying either WordPress core or each hook call.

    … or maybe not …

    While doing some client debugging for my job at WordPress VIP (did I mention we’re hiring?) I came across the need to do this exact thing. I’ve just finished the code that will make this happen, and I’m releasing it into the wild for everyone to benefit.

    What’s the problem we’re trying to solve? Well, this client has a sporadic issue where posts saving in the admin time out and sometimes fail. We’ve ruled out some potential issues, and are looking at a save_post hook going haywire.

    Now I can capture every single save_post action, what the callback was, and how long it took. Here’s an example for this exact post:

    START: 10:save_post, (Callback: `delete_get_calendar_cache`)
STOP: 10:save_post, Taken 132.084μs (Callback: `delete_get_calendar_cache`)
START: 10:save_post, (Callback: `sharing_meta_box_save`)
STOP: 10:save_post, Taken 15.974μs (Callback: `sharing_meta_box_save`)
START: 10:save_post, (Callback: `Jetpack_Likes_Settings::meta_box_save`)
STOP: 10:save_post, Taken 19.073μs (Callback: `Jetpack_Likes_Settings::meta_box_save`)
START: 10:save_post, (Callback: `SyntaxHighlighter::mark_as_encoded`)
STOP: 10:save_post, Taken 19.073μs (Callback: `SyntaxHighlighter::mark_as_encoded`)
START: 10:save_post, (Callback: `AMP_Post_Meta_Box::save_amp_status`)
STOP: 10:save_post, Taken 16.928μs (Callback: `AMP_Post_Meta_Box::save_amp_status`)
START: 20:save_post, (Callback: `Publicize::save_meta`)
STOP: 20:save_post, Taken 428.915μs (Callback: `Publicize::save_meta`)
START: 9000:save_post, (Callback: `Debug_Bar_Slow_Actions::time_stop`)
STOP: 9000:save_post, Taken 11.921μs (Callback: `Debug_Bar_Slow_Actions::time_stop`)
START: 1:save_post, (Callback: `The_SEO_Framework\Load::_update_post_meta`)
STOP: 1:save_post, Taken 6.016ms (Callback: `The_SEO_Framework\Load::_update_post_meta`)
START: 1:save_post, (Callback: `The_SEO_Framework\Load::_save_inpost_primary_term`)
STOP: 1:save_post, Taken 1.535ms (Callback: `The_SEO_Framework\Load::_save_inpost_primary_term`)
START: 10:save_post, (Callback: `delete_get_calendar_cache`)
STOP: 10:save_post, Taken 179.052μs (Callback: `delete_get_calendar_cache`)
START: 10:save_post, (Callback: `sharing_meta_box_save`)
STOP: 10:save_post, Taken 247.002μs (Callback: `sharing_meta_box_save`)
START: 10:save_post, (Callback: `Jetpack_Likes_Settings::meta_box_save`)
STOP: 10:save_post, Taken 25.988μs (Callback: `Jetpack_Likes_Settings::meta_box_save`)
START: 10:save_post, (Callback: `The_SEO_Framework\Load::delete_excluded_ids_cache`)
STOP: 10:save_post, Taken 185.966μs (Callback: `The_SEO_Framework\Load::delete_excluded_ids_cache`)
START: 10:save_post, (Callback: `SyntaxHighlighter::mark_as_encoded`)
STOP: 10:save_post, Taken 15.020μs (Callback: `SyntaxHighlighter::mark_as_encoded`)
START: 10:save_post, (Callback: `AMP_Post_Meta_Box::save_amp_status`)
STOP: 10:save_post, Taken 12.875μs (Callback: `AMP_Post_Meta_Box::save_amp_status`)
START: 20:save_post, (Callback: `Publicize::save_meta`)
STOP: 20:save_post, Taken 377.893μs (Callback: `Publicize::save_meta`)
START: 9000:save_post, (Callback: `Debug_Bar_Slow_Actions::time_stop`)
STOP: 9000:save_post, Taken 14.067μs (Callback: `Debug_Bar_Slow_Actions::time_stop`)Code language: CSS (css)

    So how does it work?

    1. We add an all action that will fire for every other action.
    2. In the all callback, we make sure we’re looking for the correct hook.
    3. We then build an array to store some data, use the $wp_filter global to fill out information such as the priority and the callback, and store the start time.
    4. Next we have to add a new action to run for our hook right before the callback we want to time. We use the fact that, even though add_action() is supposed to use an int for the priority, it will also accept a string. We add new hooks, and re-prioritze all of the existing hooks with floats that are stringified.
    5. This allows us to capture the start time and end time of each individual callback, instead of the priority group as a whole.

    Of course, this does add a tiny bit of overhead, and could cause some problems if any other plugins use stringified hook priorities, or other odd issues–so be careful 🙂

    Finally, here’s the code:

    class VIP_Hook_Timeline {
	public $hook;
	public $callbacks     = [];
	public $callback_mod  = 0.0001;
	public $callback_mods = [];

	public function __construct( $hook ) {
		$this->hook = $hook;
		add_action( 'all', array( $this, 'start' ) );
	}

	public function start() {
		// We only want to get a timeline for one hook.
		if ( $this->hook !== current_filter() ) {
			return;
		}

		global $wp_filter;

		// Iterate over each priority level and set up array.
		foreach( $wp_filter[ $this->hook ] as $priority => $callback ) {
			// Make the mod counter if not exists.
			if ( ! isset( $this->callback_mods[ $priority ] ) ) {
				$this->callback_mods[ $priority ] = $priority - $this->callback_mod;
			}

			// Make the array if not exists.
			if ( ! is_array( $this->callbacks[ $priority ] ) ) {
				$this->callbacks[ $priority ] = [];
			}

			// Iterate over each callback and set up array.
			foreach( array_keys( $callback ) as $callback_func ) {
				if ( ! is_array( $this->callbacks[ $priority ][ $callback_func ] ) ) {
					$this->callbacks[ $priority ][ $callback_func ] = [ 'start' => 0, 'stop' => 0 ];
				}
			}
		}

		foreach( $this->callbacks as $priority => $callback ) {
			foreach ( array_keys( $callback ) as $callback_func ) {

				// Get data befmore we move things around.
				$human_callback = $this->get_human_callback( $wp_filter[ $this->hook ][ $priority ][$callback_func] );

				// Modify the priorities.
				$pre_callback_priority = $this->callback_mods[ $priority ];
				$this->callback_mods[ $priority ] = $this->callback_mods[ $priority ] + $this->callback_mod;

				$new_callback_priority = $this->callback_mods[ $priority ];
				$this->callback_mods[ $priority ] = $this->callback_mods[ $priority ] + $this->callback_mod;

				$post_callback_priority = $this->callback_mods[ $priority ];
				$this->callback_mods[ $priority ] = $this->callback_mods[ $priority ] + $this->callback_mod;

				// Move the callback to our "new" priority.
				if ( $new_callback_priority != $priority ) {
					$wp_filter[ $this->hook ]->callbacks[ strval( $new_callback_priority ) ][ $callback_func ] = $wp_filter[ $this->hook ]->callbacks[ $priority ][ $callback_func ];
					unset( $wp_filter[ $this->hook ]->callbacks[ $priority ][ $callback_func ] );
					if ( empty( $wp_filter[ $this->hook ]->callbacks[ $priority ] ) ) {
						unset( $wp_filter[ $this->hook ]->callbacks[ $priority ] );
					}
				}

				// Add a new action right before the one we want to debug to capture start time.
				add_action( $this->hook, function( $value = null ) use ( $callback_func, $priority, $human_callback ) {
					$this->callbacks[ $priority ][ $callback_func ]['start'] = microtime( true );

					// Uncomment this if you just want to dump data to the PHP error log, otherwise add your own logic.
					//$message = 'START: %d:%s, (Callback: `%s`)';
					// phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_error_log
					//error_log( sprintf( $message,
					//	$priority,
					//	$this->hook,
					//	$human_callback,
					//) );

					// Just in case it's a filter, return.
					return $value;
				}, strval( $pre_callback_priority ) );

				// Add a new action right after the one we want to debug to capture end time.
				add_action( $this->hook, function( $value = null ) use ( $callback_func, $priority, $human_callback ) {
					$this->callbacks[ $priority ][ $callback_func ]['stop'] = microtime( true );

					// Uncomment this if you just want to dump data to the PHP error log, otherwise add your own logic.
					//$message = 'STOP: %d:%s, Taken %s (Callback: `%s`)';
					// phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_error_log
					//error_log( sprintf( $message,
					//	$priority,
					//	$this->hook,
					//	$this->get_human_diff( $priority, $callback_func ),
					//	$human_callback,
					//) );

					// Just in case it's a filter, return.
					return $value;
				}, strval( $post_callback_priority ) );
				
			}
		}
	}

	public function get_human_callback( $callback ) {
		$human_callback = '[UNKNOWN HOOK]';
		if ( is_array( $callback['function'] ) && count( $callback['function'] ) == 2 ) {
			list( $object_or_class, $method ) = $callback['function'];
			if ( is_object( $object_or_class ) ) {
				$object_or_class = get_class( $object_or_class );
			}
			$human_callback =  sprintf( '%s::%s', $object_or_class, $method );
		} elseif ( is_object( $callback['function'] ) ) {
			// Probably an anonymous function.
			$human_callback =  get_class( $callback['function'] );
		} else {
			$human_callback =  $callback['function'];
		}
		return $human_callback;
	}

	public function get_start( $priority, $callback_func ) {
		return (float) $this->callbacks[ $priority ][ $callback_func ]['start'];
	}

	public function get_stop( $priority, $callback_func ) {
		return (float) $this->callbacks[ $priority ][ $callback_func ]['stop'];
	}

	public function get_diff( $priority, $callback_func ) {
		return (float) ( $this->get_stop( $priority, $callback_func ) - $this->get_start( $priority, $callback_func ) );
	}

	public function get_human_diff( $priority, $callback_func ) {
		$seconds = $this->get_diff( $priority, $callback_func );

		// Seconds.
		if ( $seconds >= 1 || $seconds == 0 ) {
			return number_format( $seconds, 3 ) . 's';
		}

		// Milliseconds.
		if ( $seconds >= .001 ) {
			return number_format( $seconds * 1000, 3 ) . 'ms';
		}

		// Microseconds.
		if ( $seconds >= .000001 ) {
			return number_format( $seconds * 1000000, 3 ) . 'μs';
		}

		// Nanoseconds.
		if ( $seconds >= .000000001 ) {
			// WOW THAT'S FAST!
			return number_format( $seconds * 1000000000, 3 ) . 'ns';
		}

		return $seconds . 's?';
	}
}
new VIP_Hook_Timeline( 'save_post' );Code language: PHP (php)

Close

Ad-Blocker Not Detected 🛑

Consider installing a browser extension that blocks ads and other malicious scripts in your browser to protect your privacy and security, conserve your expensive data plan, and cut your online carbon footprint. Learn more.