This is how we use wp profile, a premium wp-cli command. This command is lifesaver.
Usage
Commands
wp profile
Output
+-----------+---------+-----------+-----------+-----------+-----------+-----------+-----------+-----------+-----------+-------------+ | stage | time | query_tim | query_cou | cache_rat | cache_hit | cache_mis | hook_time | hook_coun | request_t | request_cou | | | | e | nt | io | s | ses | | t | ime | nt | +-----------+---------+-----------+-----------+-----------+-----------+-----------+-----------+-----------+-----------+-------------+ | bootstrap | 5.3334s | 0.5977s | 6643 | 35.25% | 7227 | 13275 | 3.8516s | 31334 | 0s | 0 | | main_quer | 0.0159s | 0.0005s | 4 | 95.56% | 43 | 2 | 0.0111s | 157 | 0s | 0 | | y | | | | | | | | | | | | template | 1.7506s | 0.0275s | 221 | 88.82% | 1533 | 193 | 0.7102s | 19882 | 0s | 0 | +-----------+---------+-----------+-----------+-----------+-----------+-----------+-----------+-----------+-----------+-------------+ | total | 7.0999s | 0.6257s | 6868 | 73.21% | 8803 | 13470 | 4.5729s | 51373 | 0s | 0 | +-----------+---------+-----------+-----------+-----------+-----------+-----------+-----------+-----------+-----------+-------------+
As you can see bootstrap stage is taking most time!
So run wp profile --stage=bootstrap next
Output
+-------------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | hook | time | query_time | query_count | cache_ratio | cache_hits | cache_misses | request_time | request_count | +-------------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | | 0.0794s | 0.0016s | 1 | 25% | 1 | 3 | 0s | 0 | | muplugins_loaded | 0.0003s | 0s | 0 | 50% | 1 | 1 | 0s | 0 | | | 1.0627s | 0.0016s | 22 | 72.83% | 185 | 69 | 0s | 0 | | plugins_loaded | 0.0845s | 0.0031s | 15 | 94.49% | 120 | 7 | 0s | 0 | | | 0.0005s | 0s | 0 | 100% | 4 | 0 | 0s | 0 | | setup_theme | 0s | 0s | 0 | | 0 | 0 | 0s | 0 | | | 0.0277s | 0s | 0 | 100% | 58 | 0 | 0s | 0 | | after_setup_theme | 5.3204s | 0.5621s | 6592 | 33.42% | 6617 | 13180 | 0s | 0 | | | 0.0001s | 0s | 0 | | 0 | 0 | 0s | 0 | | init | 0.3526s | 0.0124s | 10 | 95.51% | 234 | 11 | 0s | 0 | | | 0.001s | 0.0001s | 1 | 60% | 3 | 2 | 0s | 0 | | wp_loaded | 0.0028s | 0.0001s | 2 | 66.67% | 4 | 2 | 0s | 0 | | | 0.0253s | 0s | 0 | | 0 | 0 | 0s | 0 | +-------------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+ | total | 6.9573s | 0.5811s | 6643 | 69.79% | 7227 | 13275 | 0s | 0 | +-------------------+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
You can see after_setup_theme takes almost 5 seconds!
So let’s run wp profile --hook=after_setup_theme next
Output
+-------------------+---------+------------+-------------+-------------+------------+--------------+--------------+--------------------+ | callback | time | query_time | query_count | cache_ratio | cache_hits | cache_misses | request_time | request_count | +-------------------+---------+------------+-------------+-------------+------------+--------------+--------------+--------------------+ | WooCommerce->setu | 0.0008s | 0s | 0 | 100% | 6 | 0 | 0s | 0 | | p_environment() | | | | | | | | | | MC4WP_Integration | 0.0028s | 0s | 0 | | 0 | 0 | 0s | 0 | | _Manager->initial | | | | | | | | | | ize() | | | | | | | | | | rtp_wc_add_states | 0s | 0s | 0 | | 0 | 0 | 0s | 0 | | _filter() | | | | | | | | | | rtp_referral_link | 0.0001s | 0s | 0 | | 0 | 0 | 0s | 0 | | _rewrite_rules() | | | | | | | | | | rtp_session_start | 0s | 0s | 0 | | 0 | 0 | 0s | 0 | | () | | | | | | | | | | rtpanel_setup() | 4.6487s | 0.5885s | 6591 | 33.4% | 6609 | 13179 | 0s | 0 | | WooCommerce->incl | 0.0021s | 0s | 0 | | 0 | 0 | 0s | 0 | | ude_template_func | | | | | | | | | | tions() | | | | | | | | | | wc_template_debug | 0.0004s | 0.0001s | 1 | 66.67% | 2 | 1 | 0s | 0 | | _mode() | | | | | | | | | | WPSEO_Sitemaps->r | 0s | 0s | 0 | | 0 | 0 | 0s | 0 | | educe_query_load( | | | | | | | | | | ) | | | | | | | | | +-------------------+---------+------------+-------------+-------------+------------+--------------+--------------+--------------------+ | total | 4.6548s | 0.5886s | 6592 | 66.69% | 6617 | 13180 | 0s | 0 | +-------------------+---------+------------+-------------+-------------+------------+--------------+--------------+--------------------+
Looks like rtpanel_setup function is the culprit here!
This function is from our own rtPanel theme. We checked function body and found a for-loop at a wrong place!
Can’t imagine how much time it would have taken to debug this without WP-CLI profile command.