Profile

Advertisement

WP CLI Profile package allow use to identify the performance of our WordPress website.

Installation Installation

wp package install wp-cli/profile-command

Top ↑

Syntax Syntax

wp profile stage [<stage>] [--all] [--spotlight] [--url=<url>] [--fields=<fields>] [--format=<format>] [--order=<order>] [--orderby=<orderby>]

Where,

  • bootstrap: is where WordPress is setting itself up, loading plugins and the main theme, and firing the init hook.
  • main_query: is how WordPress transforms the request  into the primary WP_Query.
  • template: is where WordPress determines which theme template to render based on the main query, and renders it.

Top ↑

Usage Usage

Simple usage:

$ wp profile stage --url=https://maheshwaghmare.com/
+------------+---------+-------------+------------+
| stage      | time    | cache_ratio | hook_count |
+------------+---------+-------------+------------+
| bootstrap  | 1.0081s | 97.73%      | 23076      |
| template   | 0.6028s | 96.27%      | 6516       |
| main_query | 0.1033s | 81.7%       | 180        |
+------------+---------+-------------+------------+
| total (3)  | 4.7142s | 91.9%       | 29772      |
+------------+---------+-------------+------------+

Here, We can see which stage takes much time when requesting the https://maheshwaghmare.com/ (home page) of our WordPress website.

Profile by Stages Profile by Stages

As we see by default we get the profile of all stages. But, We can debug the profile by providing the specific stage.

E.g.

wp profile stage <stage-name>

We can pass additional parameters as: time, query_time, query_count, cache_ratio, cache_hits, cache_misses, hook_time, hook_count, request_time, request_count

Bootstrap Stage Bootstrap Stage

$ wp profile stage bootstrap --fields=hook,time,cache_ratio --spotlight --orderby=time --order=DESC
+--------------------------+---------+-------------+
| hook                     | time    | cache_ratio |
+--------------------------+---------+-------------+
| init                     | 3.1252s | 95.38%      |
| muplugins_loaded:before  | 0.815s  | 25%         |
| plugins_loaded:before    | 0.612s  | 85.42%      |
| plugins_loaded           | 0.189s  | 88.46%      |
| after_setup_theme:before | 0.08s   | 100%        |
| wp_loaded:after          | 0.034s  |             |
| after_setup_theme        | 0.011s  | 84.62%      |
| muplugins_loaded         | 0s      | 50%         |
+--------------------------+---------+-------------+
| total (8)                | 4.8663s | 75.55%      |
+--------------------------+---------+-------------+

Top ↑

Template Stage Template Stage

$ wp profile stage template --fields=hook,time,cache_ratio --spotlight --orderby=time --order=DESC
+-------------------+--------+-------------+
| hook              | time   | cache_ratio |
+-------------------+--------+-------------+
| wp_head           | 0.632s | 96.68%      |
| wp_footer         | 0.163s | 97.92%      |
| template_redirect | 0.034s | 97.67%      |
+-------------------+--------+-------------+
| total (3)         | 0.829s | 97.42%      |
+-------------------+--------+-------------+

Top ↑

Main Query Stage Main Query Stage

$ wp profile stage main_query --fields=hook,time,cache_ratio --spotlight --orderby=time --order=DESC
+----------------------+--------+-------------+
| hook                 | time   | cache_ratio |
+----------------------+--------+-------------+
| wp                   | 0.077s | 91.53%      |
| parse_request:before | 0.033s | 90.91%      |
+----------------------+--------+-------------+
| total (2)            | 0.11s  | 91.22%      |
+----------------------+--------+-------------+

Top ↑

Profile by Hooks Profile by Hooks

We can debug the performance by hooks.

E.g.

wp profile hook <hook-name>

We can pass additional parameters as: callback_count, time, query_time, query_count, cache_ratio, cache_hits, cache_misses, request_time, request_count

Top ↑

All Hooks All Hooks

We can debug all hook which is executed while visiting the specific page.

Top ↑

Group by Time Group by Time

$ wp profile hook --fields=hook,callback_count,time --orderby=time
+-------------------------------------------------------------------------------+---------+
| callback                                                                      | time    |
+-------------------------------------------------------------------------------+---------+
| esc_html                                                                     | 1              | 0.001s   |
...
| wp_head                                                                      | 30             | 0.742s   |
| astra_masthead_content                                                       | 4              | 0.8751s  |
| astra_masthead                                                               | 1              | 0.8771s  |
| astra_header                                                                 | 3              | 0.8891s  |
| astra_footer                                                                 | 1              | 0.9611s  |
| init                                                                         | 106            | 4.4243s  |
| wp                                                                           | 37             | 6.9494s  |
+------------------------------------------------------------------------------+----------------+----------+
| total (1802)                                                                 | 1107           | 18.4431s |
+------------------------------------------------------------------------------+----------------+----------+

Top ↑

Profile by URL Profile by URL

$ wp profile hook --fields=hook,callback_count,time --orderby=time --url=http://localhost/dev/portfolio

Top ↑

Group by Callback Count Group by Callback Count

$ wp profile hook --fields=hook,callback_count,time --orderby=callback_count
+-------------------------------------------------------------------------------+---------+
| callback                                                                      | time    |
+-------------------------------------------------------------------------------+---------+
| function(){}                                                                  | 0s      |
| register_block_core_block()                                                   | 0.001s  |
...
| wp_head                                                                      | 30             | 0.742s   |
| astra_masthead_content                                                       | 4              | 0.8751s  |
| astra_masthead                                                               | 1              | 0.8771s  |
| astra_header                                                                 | 3              | 0.8891s  |
| astra_footer                                                                 | 1              | 0.9611s  |
| init                                                                         | 106            | 4.4243s  |
| wp                                                                           | 37             | 6.9494s  |
+------------------------------------------------------------------------------+----------------+----------+
| total (1802)                                                                 | 1107           | 18.4431s |
+------------------------------------------------------------------------------+----------------+----------+

Top ↑

Single Hook Single Hook

We can debug specific hook. Let’s debug the init hook group by time and callback count.

Top ↑

Group by Time Group by Time

Lets debug the init hook group by time.

$ wp profile hook init --fields=callback,time --orderby=time
+-------------------------------------------------------------------------------+---------+
| callback                                                                      | time    |
+-------------------------------------------------------------------------------+---------+
| rest_api_init()                                                               | 0.001s  |
...
| ActionScheduler_DBLogger->init()                                              | 0.001s  |
| wp_cron()                                                                     | 1.0701s |
+-------------------------------------------------------------------------------+---------+
| total (106)                                                                   | 2.8532s |
+-------------------------------------------------------------------------------+---------+

Top ↑

Group by callback count Group by callback count

Lets debug the init hook group by callback count.

$ wp profile hook init --fields=callback,time --orderby=callback_count
+-------------------------------------------------------------------------------+---------+
| callback                                                                      | time    |
+-------------------------------------------------------------------------------+---------+
| function(){}                                                                  | 0s      |
| register_block_core_block()                                                   | 0.001s  |
...
| register_block_core_categories()                                              | 0s      |
| register_block_core_calendar()                                                | 0s      |
+-------------------------------------------------------------------------------+---------+
| total (106)                                                                   | 1.8471s |
+-------------------------------------------------------------------------------+---------+

Top ↑

Specific Page Specific Page

$ wp profile hook init --fields=callback,time --orderby=time --url=http://localhost/dev/portfolio
+-------------------------------------------------------------------------------+---------+
| callback                                                                      | time    |
+-------------------------------------------------------------------------------+---------+
| register_block_core_archives()                                                | 0.001s  |
| rest_api_init()                                                               | 0.001s  |
...
| wp_widgets_init()                                                             | 0.157s  |
| wp_cron()                                                                     | 1.1221s |
+-------------------------------------------------------------------------------+---------+
| total (106)                                                                   | 3.3182s |
+-------------------------------------------------------------------------------+---------+

Top ↑

Spotlight Spotlight

? wp profile hook --fields=hook,time,cache_ratio --spotlight --orderby=time --order=DESC
+-----------------------------------+---------+-------------+
| hook                              | time    | cache_ratio |
+-----------------------------------+---------+-------------+
| rest_api_init                     | 1.1056s | 96.76%      |
...
| elementor/fonts/additional_fonts  | 0.0076s | 90%         |
| muplugins_loaded                  | 0.0005s | 50%         |
+-----------------------------------+---------+-------------+
| total (25)                        | 4.0329s | 94.82%      |
+-----------------------------------+---------+-------------+

Debug rest_api_init hook

? wp profile hook rest_api_init --fields=callback,time,cache_ratio --spotlight --orderby=time --order=DESC
+-----------------------------------------+---------+-------------+
| callback                                | time    | cache_ratio |
+-----------------------------------------+---------+-------------+
| WC_API->register_rest_routes()          | 0.6487s | 95.44%      |
| create_initial_rest_routes()            | 0.1098s | 100%        |
| Envato_Elements\REST->register_routes() | 0.0245s |             |
+-----------------------------------------+---------+-------------+
| total (3)                               | 0.7829s | 97.72%      |
+-----------------------------------------+---------+-------------+

Example 2

? wp profile hook init --fields=callback,time,cache_ratio --spotlight --orderby=time --order=DESC  
+--------------------------------------------+---------+-------------+                             
| callback                                   | time    | cache_ratio |                             
+--------------------------------------------+---------+-------------+                             
| wp_cron()                                  | 1.103s  | 90.48%      |                             
| Elementor\Plugin->init()                   | 0.5867s | 95.38%      |                             
...
| WooCommerce->add_image_sizes()             | 0.0029s | 85.71%      |                             
+--------------------------------------------+---------+-------------+                             
| total (13)                                 | 1.9125s | 83.66%      |                             
+--------------------------------------------+---------+-------------+

Top ↑

Profile by Function Profile by Function

We can also profile the functions.

Top ↑

Normal Function Normal Function

Suppose we have below function:

function my_test_loop() {
	for ($i=0; $i < 5000; $i++) {
		// Loop for 5000 time.
	}
}

Profile function my_test_loop() as below:

? wp profile eval "my_test_loop();"
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
| time    | query_time | query_count | cache_ratio | cache_hits | cache_misses | request_time | request_count |
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
| 0.0005s | 0s         | 0           |             | 0          | 0            | 0s           | 0             |
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+

Top ↑

Profile wp_remote_get Profile wp_remote_get

? wp profile eval "wp_remote_get( 'https://maheshwaghmare.com/wp-json/wp/v2/posts/' );"
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
| time    | query_time | query_count | cache_ratio | cache_hits | cache_misses | request_time | request_count |
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
| 1.4288s | 0s         | 0           | 100%        | 2          | 0            | 1.4281s      | 1             |
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+

Top ↑

Profile by File Profile by File

We can debug the performance by file.

? wp profile eval-file my-plugin-file.php
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
| time    | query_time | query_count | cache_ratio | cache_hits | cache_misses | request_time | request_count |
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+
| 0.1114s | 0s         | 0           | 100%        | 4          | 0            | 0s           | 0             |
+---------+------------+-------------+-------------+------------+--------------+--------------+---------------+

Leave a Reply