wp profile
Installation
This command requires at least v.0.23.0 but you should probably be running at least 1.1.0 anyways. You also need to define SAVEQUERIES as true in your wp-config.php file. Install via wp package install wp-cli/profile-command. If you run into errors you might need to temporarily up your PHP memory limit to 128 or 256 so that composer can install it.
About
Did you ever use Debug Bar for debugging along with all of the sub-plugins that it supports? Pretty awesome however you need to actually install that plugin into your site which causes a Heisenberg problem because your observations are actually affecting the results. Attacking from the CLI allows you to monitor without affecting the results (at least too much).
Usage
Step #1 – Show stages
Running this command:
wp profile stage
gives these results:
+------------+---------+------------+-------------+-------------+------------+--------------+-----------+------------+--------------+---------------+ | stage | time | query_time | query_count | cache_ratio | cache_hits | cache_misses | hook_time | hook_count | request_time | request_count | +------------+---------+------------+-------------+-------------+------------+--------------+-----------+------------+--------------+---------------+ | bootstrap | 0.8169s | 0.002s | 8 | 99.27% | 1083 | 8 | 0.3199s | 7352 | 0.1501s | 1 | | main_query | 0.0099s | 0.0002s | 1 | 100% | 51 | 0 | 0.0086s | 150 | 0s | 0 | | template | 0.2104s | 0.0111s | 34 | 99.83% | 1725 | 3 | 0.2003s | 8500 | 0s | 0 | +------------+---------+------------+-------------+-------------+------------+--------------+-----------+------------+--------------+---------------+ | total (3) | 1.0373s | 0.0132s | 43 | 99.7% | 2859 | 11 | 0.5288s | 16002 | 0.1501s | 1 | +------------+---------+------------+-------------+-------------+------------+--------------+-----------+------------+--------------+---------------+
We can see that the most amount of time is spent in the bootstrap stage so we’ll dig into that in the next step.
Step #2 – Examine specific stage
Running this command:
wp profile stage bootstrap
gives these results:
+--------------------------+----------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | hook | callback_count | time | query_time | query_count | cache_ratio | cache_hits | cache_misses | request_time | request_count | +--------------------------+----------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | muplugins_loaded:before | | 0.1086s | 0s | 0 | 100% | 3 | 0 | 0s | 0 | | muplugins_loaded | 2 | 0.0002s | 0s | 0 | 100% | 2 | 0 | 0s | 0 | | plugins_loaded:before | | 0.347s | 0.0005s | 2 | 99.16% | 354 | 3 | 0s | 0 | | plugins_loaded | 42 | 0.0389s | 0.0008s | 2 | 100% | 83 | 0 | 0s | 0 | | setup_theme:before | | 0.0007s | 0s | 0 | 100% | 4 | 0 | 0s | 0 | | setup_theme | 1 | 0.0001s | 0s | 0 | 100% | 1 | 0 | 0s | 0 | | after_setup_theme:before | | 0.0121s | 0s | 0 | 90.91% | 30 | 3 | 0s | 0 | | after_setup_theme | 12 | 0.0153s | 0s | 0 | 100% | 17 | 0 | 0s | 0 | | init:before | | 0s | 0s | 0 | | 0 | 0 | 0s | 0 | | init | 110 | 0.2853s | 0.0005s | 4 | 99.66% | 582 | 2 | 0.1864s | 1 | | wp_loaded:before | | 0.0001s | 0s | 0 | 100% | 4 | 0 | 0s | 0 | | wp_loaded | 16 | 0.0003s | 0s | 0 | 100% | 3 | 0 | 0s | 0 | | wp_loaded:after | | 0.0191s | 0s | 0 | | 0 | 0 | 0s | 0 | +--------------------------+----------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | total (13) | 183 | 0.8275s | 0.0017s | 8 | 99.07% | 1083 | 8 | 0.1864s | 1 | +--------------------------+----------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
We can now see two hooks that we want to dig into, plugins_loaded:before and init. Unfortunately there’s a known bug in PHP 7 so we can’t debug the first one yet. We can, however, dig into the second hook which we’ll do in the next step.
Step #3 – Examine specific hook
Running this command:
wp profile hook init
gives way too much! However, we can pass the --spotlight argument which will remove all zero-ish things from view. So instead we’ll run:
wp profile hook init --spotlight
which gives us:
+--------------------+----------------------------------------------------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | callback | location | time | query_time | query_count | cache_ratio | cache_hits | cache_misses | request_time | request_count | +--------------------+----------------------------------------------------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | pmpromc_init() | pmpro-mailchimp/pmpro-mailchimp.php:33 | 0.001s | 0.0001s | 1 | 100% | 4 | 0 | 0s | 0 | | Vc_Manager->init() | js_composer/js_composer.php:249 | 0.0416s | 0s | 0 | 100% | 4 | 0 | 0s | 0 | | wp_cron() | wp-includes/cron.php:348 | 0.2195s | 0s | 0 | 88.89% | 8 | 1 | 0.2186s | 1 | | BWP_MINIFY->init() | bwp-minify/includes/class-bwp-framework-improved.php:332 | 0.0007s | 0s | 0 | 88.89% | 8 | 1 | 0s | 0 | | pmpro_init() | paid-memberships-pro/includes/init.php:6 | 0.0028s | 0.0002s | 3 | 100% | 66 | 0 | 0s | 0 | +--------------------+----------------------------------------------------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | total (5) | | 0.2656s | 0.0003s | 4 | 95.56% | 90 | 2 | 0.2186s | 1 | +--------------------+----------------------------------------------------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
Well that helps! It appears that poor-man’s cron (the default) is enabled on this site so I think a lot of work is being done checking and settings that up. I should probably switch that over to system cron. I can also see where some of my other queries are ending up. Unfortunately I just found out about this a couple of hours after I used Debug Bar and grep for troubleshooting so most of my optimizations are in place.
But then I found five dollars.