Dealing With Slow SQL Queries? Let the “EXPLAIN” Statement Handle It | by Max | Jun, 2022

Understand EXPLAIN query plans (part 1 of 2)

Photo by Markus Winkler on Unsplash

Have you ever had a slow-running SQL query but you weren’t sure where to even start looking for optimizations? If only there was some way to pinpoint exactly which parts of your query were causing the whole thing to run slow, so that you can focus your efforts there, rather than making tweaks all over the place.

That’s exactly what the EXPLAIN statement allows us to do. The EXPLAIN statement will give you the query plan produced by your database’s query planner, and also gives you estimates of what the most costly parts of your query are.However, deciphering what each part of the query plan is telling us can be a bit tricky at first .

In this article, we’ll walk through how we can understand what the query plan is telling us and how we can use that information to improve the performance of our queries.

This article is part 1 of a set of 2 articles and is focused on understanding the query planner output using the EXPLAIN statement.

We’ll be using Postgres as our database here, so just be aware that there may be some minor differences, especially in the Postgres-related features, if you’re using a different RDBMS. If you’re using a data you may actually have a separate set of tools to analyze your query performance, since RDBMS and Data Warehouses go about storing and retrieving data in different ways.

To start things off, let’s create a basic table that we can use throughout to write queries against and analyze performance.

CREATE TABLE user_event_log (
id SERIAL PRIMARY KEY,
event_id INTEGER,
event_metadata JSONB,
user_id INTEGER,
created_at TIMESTAMP DEFAULT NOW(),
updated_at TIMESTAMP DEFAULT NOW()
);

Although we won’t create them, we’ll assume that event_id and user_id are foreign key references to a separate event and user table.

Next, let’s insert some data.

INSERT INTO user_event_log(event_id, event_metadata, user_id) VALUES
(1, ‘{“field”: “some value”}’, 1),
(2, ‘{“field”: “some value”}’, 1);

Although we only have two rows at the moment, there’s actually already a lot of interesting information that we can get from here, so let’s start using our EXPLAIN query.

EXPLAIN SELECT *
FROM user_event_log
WHERE user_id = 1;

And this is our output:

Seq Scan on user_event_log (cost=0.00..21.50 rows=5 width=60)
Filter: (user_id = 1)

Alright, so what does this mean? Let’s take it bit-by-bit, starting at the top with the actual EXPLAIN keyword.

The EXPLAIN keyword will give us the query plan, ie the approach the query planner determines as optimal, which will be taken to perform this query if it’s executed. In addition, we will also get some estimated cost metrics.

In more complex plans, which we’ll see later, we can get multiple nodes as output, but it this query we just get a single node.

The first thing we see is the Seq Scan keyword, in other words, we have a full table scan. This means that our query is going to go through every record in this table when performing this query. Yikes!

Now this obviously isn’t a problem when we only have two rows, but imagine having a table with 10 million rows, and you now run this query multiple times per second. That means tons of data will be read from disk into memory, and only the relevant bits are kept.

That’s also where the Filter: (user_id = 1)statement comes in.

The full picture of what’s happening here is that our query is traversing through our whole data, reading the data from disk, and any records it finds that fits this condition will be kept to be returned with the query, the rest are discarded.

We’ll look at how we can fix this in a second. Some of you probably already know that the solution here is indices, but let’s take it step-by-step and look at the rest of the output in the parenthesis.

We also see this: cost=0.00...21.50. What does this mean?

This is Postgres’ estimate as to the cost of this part of the query. The cost is in arbitrary units and doesn’t mean much by itself, but it can be pretty useful to compare relative costs between different parts of a query. In our case we don’t have multiple parts yet, but this can be useful later.

The 0.00 is the estimated start-up cost. The start-up cost is a measure of how long it will take until this part of the query produces its first row. In this case it’s 0, but we’ll see later on that this doesn’t always start at 0.

The 21.50 is the total cost of this part of the query, from when it starts to when it finishes.

Important to note about both cost components is that they are cumulative, meaning that the costs of higher nodes include the costs of lower components.

Finally, Postgres estimates that it will return 5 rows, and that the size in bytes (what it calls the width) is 60 bytes per row. The row estimate is obviously wrong, but that’s fine, and we’ll get into the row estimates a bit later and when you should be worried.

So now that we’ve seen our query plan, let’s optimize things a bit. When you see a full table scan you usually want to think about optimizing it by creating an index on the column.

CREATE INDEX event_log_user_id_idx ON user_event_log(user_id);

Our query plan now looks like this:

Seq Scan on user_event_log (cost=0.00..1.02 rows=1 width=60)
Filter: (user_id = 1)

You’re probably wondering now, wait, isn’t that basically the same plan we had previously?

Yes, and we’ve actually reached an interesting edge-case here.

Postgres now has to decide between using the index and using the full table scan, and it decided that the full table scan is actually the more efficient operation in this case. Usually, when you end up returning at least around 10% of the data in your table, the full table scan becomes more efficient over the index scan.

This is because using an index requires several IO operations — looking up the indices, and then looking up the relevant records determined from the indices. Whereas a full table scan is just reading in the records directly.

If we add in some more more data into our database using a simple python script

And then try our EXPLAIN query again this is what our query plan looks like:

Index Scan using event_log_user_id_idx on user_event_log (cost=0.28..8.37 rows=5 width=117)
Index Cond: (user_id = 1)

We can see we switched from a full table scan and a filter instead to an index scan and an index condition.

Now before we move on and quickly talk about this node, some of you may have noticed that we now have a total of 219 users. Shouldn’t something like 10 users be enough to get us to our approx. 10% threshold? Well, yes, but also no. The reason here is that we’re dealing with a very small table, and we’re actually also influenced by our buffers at this scale. We’ll get back to buffers in part 2 though to not diverge too much here.

Coming back to our new output — we see we have an Index Scan on the index event_log_user_id_idx that we created above, and we can see that our index is scanned using the condition in the filter (user_id = 1). This means that we go through our index, and from it find the rows we need to read from disk by looking up the relevant records we need from the index.

If we change our filter condition for extra users, we’ll see that Index Scan remains, but our index condition gets updated. This is because we can use the same index for all of these filter conditions.

EXPLAIN SELECT *
FROM user_event_log
WHERE user_id in (1, 12, 87)

Which Gives:

Index Scan using event_log_user_id_idx on user_event_log (cost=0.28..17.09 rows=15 width=117)
Index Cond: (user_id = ANY (‘{1,12,87}’::integer[]))”

However, changing our filter condition to also include, eg, the event_id, we add in an extra filter operation, since we don’t have an index on (user_id, event_id).

EXPLAIN SELECT *
FROM user_event_log
WHERE user_id = 1 and event_id = 2

Giving:

Index Scan using event_log_user_id_idx on user_event_log (cost=0.28..8.38 rows=1 width=117)
Index Cond: (user_id = 1)
Filter: (event_id = 2)

What’s happening here is that we load all the relevant records for user_id = 1 based on our index lookup, and then filter those rows with the filter condition event_id = 2.

If we had an index on both event_id and user_id, we would revert to just a single index lookup.

CREATE INDEX event_log_user_id_event_id_idx ON user_event_log(user_id, event_id);

Resulting in:

Index Scan using event_log_user_id_event_id_idx on user_event_log (cost=0.28..8.30 rows=1 width=117)
Index Cond: ((user_id = 1) AND (event_id = 2))

Be aware though that this isn’t always the best step to take. In general, you should try to keep the number of indices you have on your tables low. This is because every time your data changes all your indices need to be updated. If your data changes frequently this adds a lot of overhead to your database because it needs to maintain all your indices. So make sure you only have indices that you’re actually using.

It’s also important to remember to take into context the situation you’re working in. The query plans provide information on how the query is planned to be executed, but it’s then up to you to decide if there are potentially any problems with this or if the plan is actually okay.

For example, you may have our very simple select query from above in your application:

SELECT *
FROM user_event_log
WHERE user_id = 1 and event_id = 2

And you notice that the performance is degrading as load is increasing. You run the EXPLAIN plan, and find that you actually only have an index on user_id but not on user_id and event_id. Naively adding the (user_id, event_id) index could actually cause extra performance problems, since maybe the actual issue is that you also have an index on the metadata column, and the increased load is causing your database to have to do a lot of background work maintaining this index. Adding an extra index isn’t always magically going to solve your problems, sometimes it may actually just make the situation worse.

In fact, I remember a time when we were batch importing the results of an analytical ETL job into our Postgres DB where we experienced exactly these issues. Although the batch upsert itself was done in about 15 minutes, our database’s CPU load was above 80% for another whole hour as the index updating and auto-vacuum processes got triggered. In this case, moving from upserts to inserts only with a delayed delation job for stale data, and removing a lot of our un-used indices resolved the issue for us.

So remember, always consider the full context you’re working in.

Now that we’ve taken the time to understand and decipher what each element in a node’s results tells us, let’s take a look at some more complex queries.

To help us out, we’re going to create a second table here, which contains the mapping of each event_id to their respective name.

CREATE TABLE IF NOT EXISTS event (
id SERIAL PRIMARY KEY,
name TEXT
);

And insert some data

INSERT INTO event(id, name) VALUES
(1, ‘login’), (2, ‘like’), (3, ‘comment’), (4, ‘follow’), (5, ‘subscribe’);

And let’s now perform a join on our user_event_log table, and filter out all events except for like events.

EXPLAIN SELECT uel.*
FROM user_event_log uel
LEFT JOIN event e on e.id = uel.event_id
WHERE e.name = ‘like’;

Giving:

Hash Join (cost=25.95..79.75 rows=5 width=117)
Hash Cond: (uel.event_id = e.id)
-> Seq Scan on user_event_log uel (cost=0.00..50.92 rows=1092 width=117)
-> Hash (cost=25.88..25.88 rows=6 width=4)
-> Seq Scan on event e (cost=0.00..25.88 rows=6 width=4)
Filter: (name = ‘like’::text)

The first thing that pops out here is that we now have several nodes, and we also have nested (or child + parent) components.

The way we read these query plans is from inwards to outwards. So the steps that happen first would be the sequence scan on the event table and applying the filter.

The next layer is interesting, because we have two nodes on the same level. What happens here first is we start with the lower node (also called inner child), and we load the results of the sequence scan on the event table with the filter into an in-memory hash table.

Then, for every row of the upper node (also called outer child), we look for a matching row in our hash table using the join condition.

SQL is obviously composed of more than SELECT, WHERE, and JOIN statements, but the principles that we’ve learned here can also be applied to the other types of statements you’ll be using.

In this article, we’ve seen how to use the EXPLAIN statement to get and understand the query plan, which tells us how the database plans to approach executing this query as well as how expensive it believes each step to be.

From the query plan, we’re already able to get some insightful information, such as what node our database believes will be the most work as well as where it’s planning to make use of indices.

However, it can also be very useful to also know the actual results of our query, and to be able to compare the query planner’s cost estimates to the actual numbers. This is what the EXPLAIN ANALYZE statement allows us to do which you can read about in part 2 of this article here.

Want to Connect?This article is also available in video format on YouTube here.

Leave a Comment