How to do WordPress plugin performance analysis

In the video below, I show an example of performance analysis of a WordPress plugin. Performance optimisation is firstly performance analysis – you need to find out where your performance bottlenecks are before you touch any code.

Performance bottlenecks in WordPress are most commonly found in the database, so a tool like Query Monitor can help a great deal and is the right first port of call. If you want to do performance analysis and optimisation properly however, break out the big-boy tools.

Percona Toolkit

To gather all the SQL queries into a league table, I set up the slow query log for Percona Server / MySQL 8 to record every SQL query. See my guide on enabling the slow query log and identifying slow queries with Percona for how to do that.

I am using a value of long_query_time = 0 to catch every query, not just the slow ones.

Xdebug Profiler

To analyse the PHP bottlenecks, use the Xdebug profiler. Don’t bother with lightweight in-page profilers like the old P3 Performance Profiler – the results from them are garbage.

To set up the Xdebug profiler, follow my guide on profiling WordPress PHP code. I am using the profiler to grab everything because this is a cron-based plugin, but you can use the trigger option from that guide if you only need to profile a single page.

An almost complete picture of performance

With the two tools above you’ll get all the SQL bottlenecks and all the PHP bottlenecks. There are other things that can affect performance which I am not covering here. To enumerate a few I am not considering:

• Network and bandwidth
• OS config, memory congestion and thrashing
• Server config, disk speed and CPU speed
• Competing resources – other activity on the server, load and so on

In this example I am running my performance analysis on a development server where I know the specs. I also keep a duplicate reference server running the original code with an identical setup, so I can run side-by-side performance comparisons after optimisation.

Analysing Performance

First of all, download the Xdebug profiler trace for whatever you’re tracing and open it with QCacheGrind. I use the Callee Map tab, like in this screenshot:

The items I’ve marked on the screen:

1. This is the ordered list of expensive items, most expensive at the top automatically. The first column, Incl, shows total time for this function including its children. The second column shows just the time used by this function, excluding its children. Then you have the number of calls, the function name and where it comes from.
2. This is the callee map. You can see the big chunk of 33% is the wpdb query call, then the next three items take up about 25% of the total execution time of this first function (do_action). The next three are PMXI_Chunk, PMXI_Admin and apply_filters. Each of these boxes can be drilled into to view performance details about that specific item.
3. The third part along the bottom shows more info – you can alter this to show charts of callers and callees.

So we have three target areas to look at really – the SQL queries, PMXI_Chunk and PMXI_Admin. PMXI is WP All Import, so this trace is of a bulk product import.

Here’s a screenshot of the pt-query-digest results:

What you’re looking at above is:

1. The rank of the query along with the total percentage of time this type of query has consumed. The queries at the top are your biggest targets – optimise them for the most impact.
2. The right hand column shows a basic summary of the query.
3. The rest of the report covers details about each query type. To show you that, here’s the text for the top four queries (I’ve cut out some bumf):

# Query 1: 20.36 QPS, 0.05x concurrency, ID 0xFD1893280DD503F4 at byte 12710724
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 9 3930
# Exec time 20 10s 1ms 76ms 3ms 4ms 2ms 2ms
# Lock time 7 455ms 36us 1ms 115us 224us 71us 98us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Rows affecte 33 3.84k 1 1 1 1 0 1
# Bytes sent 0 53.73k 14 14 14 14 0 14
# Query size 7 498.77k 91 776 129.96 258.32 126.56 97.36
# Tables
# SHOW TABLE STATUS FROM `awdstackdb` LIKE 'wp_postmeta'G
# SHOW CREATE TABLE `awdstackdb`.`wp_postmeta`G
INSERT INTO `wp_postmeta` (`post_id`, `meta_key`, `meta_value`) VALUES (2399, '_product_version', '2.6.4')G

# Query 2: 20.32 QPS, 0.05x concurrency, ID 0x42B194D1A514097D at byte 10645618
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 10 3942
# Exec time 18 9s 485us 92ms 2ms 4ms 3ms 2ms
# Lock time 4 253ms 31us 897us 64us 144us 52us 44us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 1 3.85k 1 1 1 1 0 1
# Rows affecte 33 3.85k 1 1 1 1 0 1
# Bytes sent 0 42.35k 11 11 11 11 0 11
# Query size 2 188.63k 49 49 49 49 0 49
# Tables
# SHOW TABLE STATUS FROM `awdstackdb` LIKE 'wp_postmeta'G
# SHOW CREATE TABLE `awdstackdb`.`wp_postmeta`G
DELETE FROM wp_postmeta WHERE meta_id IN( 48049 )G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select * from wp_postmeta WHERE meta_id IN( 48049 )G

# Query 3: 42.82 QPS, 0.03x concurrency, ID 0x56ED2B5B5549F23D at byte 73914
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 21 8308
# Exec time 10 5s 177us 10ms 610us 2ms 576us 424us
# Lock time 14 937ms 41us 2ms 112us 348us 121us 66us
# Rows sent 2 3.85k 0 1 0.47 0.99 0.50 0
# Rows examine 38 119.08k 0 29 14.68 27.38 8.14 14.52
# Rows affecte 0 0 0 0 0 0 0 0
# Bytes sent 2 809.26k 95 105 99.74 102.22 4.75 92.72
# Query size 10 667.26k 74 97 82.24 88.31 4.92 80.10
# Tables
# SHOW TABLE STATUS FROM `awdstackdb` LIKE 'wp_postmeta'G
# SHOW CREATE TABLE `awdstackdb`.`wp_postmeta`G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT meta_id FROM wp_postmeta WHERE meta_key = '_product_url' AND post_id = 2224G

# Query 4: 7.52 QPS, 0.02x concurrency, ID 0x90EFB67D60488121 at byte 5430080
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 1452
# Exec time 8 4s 527us 57ms 3ms 5ms 2ms 3ms
# Lock time 2 172ms 42us 879us 118us 214us 70us 103us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 1.42k 1 1 1 1 0 1
# Rows affecte 12 1.42k 1 1 1 1 0 1
# Bytes sent 0 73.73k 52 52 52 52 0 52
# Query size 1 103.78k 72 74 73.19 72.65 1 72.65
# Tables
# SHOW TABLE STATUS FROM `awdstackdb` LIKE 'wp_term_taxonomy'G
# SHOW CREATE TABLE `awdstackdb`.`wp_term_taxonomy`G
UPDATE wp_term_taxonomy SET count = count + 1 WHERE term_taxonomy_id = 836G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select count = count + 1 from wp_term_taxonomy where term_taxonomy_id = 836G

The most immediately useful parts here are the query examples, so I copy and paste them into mysql and stick the word EXPLAIN at the front, e.g.

explain select * from wp_postmeta WHERE meta_id IN( 48049 );

In this case, when I run this query against the database it’s using an index, so there’s not much I can do to optimise here using SQL techniques. What I can figure out from the code, however, is that the three top queries are actually trying to do an UPDATE, and in the vast majority of cases the update is not required.

In other words, the developer of this code, instead of running an UPDATE statement, has run a DELETE followed by an INSERT. This was presumably because a DELETE followed by an INSERT needs one less code path: if the data doesn’t already exist the delete does nothing and the insert runs as normal, and if the data does already exist it is deleted before being inserted.

To double check this, I look in the mysql-slow.log file. What I find is many multiple SELECT and then DELETE statements. It makes sense for there to be individual INSERT statements, but not individual DELETE statements, since the DELETE is deleting all the postmeta. Again, it would be better to do what’s called an UPSERT (update or insert).

So I’ve found my next major performance bottleneck to fix. Searching the mysql-slow.log file for the first DELETE against wp_postmeta, I found there are 24 DELETE statements per post. That can be turned into a single statement, which gives roughly a 20x speed boost for this section. This is exactly the class of problem tracking slow SQL back to its origin is about, and where a SQL-first importer avoids the query churn in the first place.

Summary

Use the Xdebug profiler to analyse performance bottlenecks, then drill into the relevant code – SQL, PHP, or both. Use the slow query log and the pt-query-digest tool to help you analyse the SQL queries. When the fix turns out to be a missing index or a query that needs rewriting, that is exactly what Scalability Pro automates.

Here’s a video which can help you picture this a little better. Let me know if there’s anything you’d like covered in more depth in my next videos.

Further reading

Related products

Scalability ProSpeed up your whole site – big catalogues, big databases, no re-architectureSuper Speedy ImportsEasy to use. Built for speed.