evie

Posted on Mar 15, 2017

A Rubyist's Guide to Postgresql's Explain

#ruby #intermediate #rails #postgres

This post was originally published on RubyLetter.com

If you want to understand why your database queries maybe aren't as fast as they used to be, nothing beats a little feature of postgres called explain.

It's a simple idea. Just ask postgres to explain how it plans to perform a query and it'll tell you. You can even have it execute the query it and compare expected performance to actual.

Sound familiar?

You may have seen explain before. Ever since version 3.2, Rails will automatically run it on any queries that take longer than 500ms.

The only problem is that the output is fairly cryptic. Here's an example, which I stole from the rails development blog:

% User.where(:id => 1).joins(:posts).explain

EXPLAIN for: SELECT "users".* FROM "users" INNER JOIN "posts" ON "posts"."user_id" = "users"."id" WHERE "users"."id" = 1
                                  QUERY PLAN
------------------------------------------------------------------------------
 Nested Loop Left Join  (cost=0.00..37.24 rows=8 width=0)
   Join Filter: (posts.user_id = users.id)
   ->  Index Scan using users_pkey on users  (cost=0.00..8.27 rows=1 width=4)
         Index Cond: (id = 1)
   ->  Seq Scan on posts  (cost=0.00..28.88 rows=8 width=4)
         Filter: (posts.user_id = 1)
(6 rows)

What the heck does this mean?

In this article I'm going to walk you through how to interpret results like this, with a special focus on how it impacts web development in Ruby.

The syntax

If you're using Rails, you can append .explain to any Active Record query to do an explain:

> User.where(id: 1).explain
  User Load (10.0ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1  [["id", 1]]
=> EXPLAIN for: SELECT "users".* FROM "users" WHERE "users"."id" = $1 [["id", 1]]
                                QUERY PLAN
--------------------------------------------------------------------------
 Index Scan using users_pkey on users  (cost=0.29..8.30 rows=1 width=812)
   Index Cond: (id = 1)
(2 rows)

While the explain method is handy, it doesn't give you access to the more advanced options available to you directly in postgres.

To use explain directly in postgres, just run psql -d yourdb to open your postgres client and run something like this:

explain select * from users where id=1;
                                QUERY PLAN
--------------------------------------------------------------------------
 Index Scan using users_pkey on users  (cost=0.29..8.30 rows=1 width=812)
   Index Cond: (id = 1)
(2 rows)

This gives us information about how postgres plans on doing the query, including its best guesses as to how much work it will take.

To actually run the query and see how it compares to the estimates, you can do an explain analyze:

explain analyze select * from users where id=1;
                               QUERY PLAN
------------------------------------------------------------------------------------
 Index Scan using users_pkey on users  (cost=0.29..8.30 rows=1 width=812) (actual time=0.043..0.044 rows=1 loops=1)
   Index Cond: (id = 1)
 Total runtime: 0.117 ms

Interpreting the output

Postgres is smart. It will do its best to figure out the most efficient way way to execute your query. In other words, it makes a "query plan." The explain command simply prints it out.

Consider the following:

# explain select * from users order by created_at limit 10;
                               QUERY PLAN
-------------------------------------------------------------------------
 Limit  (cost=892.98..893.01 rows=10 width=812)
   ->  Sort  (cost=892.98..919.16 rows=104 width=812)
         Sort Key: created_at
         ->  Seq Scan on users  (cost=0.00..666.71 rows=104 width=812)
(4 rows)

This output is made of two parts:

The "node list" describing the sequence of actions to perform the query
Performance estimates, describing the cost to perform each item in the list.

The node list

Let's remove all of the performance estimates, so we only have our list of nodes:

 Limit
   ->  Sort (Sort Key: created_at)
         ->  Seq Scan on users

This is kind of like a "program" that postgres has written to execute the query. There are three actions: "limit", "sort" and "seq scan." The output of each child is piped into its parent.

If it was Ruby, it might look like this:

all_users.sort(:created_at).limit(10)

There are lots of different actions the postgresql can use in its query plan. You don't need to know what they all mean, but it's helpful to know a handful:

Index Scan: Postgres will fetch records using an index. This is kind of like finding items in a Ruby hash.
Seq Scan: Postgres will fetch records by looping over a record set.
Filter: Selects only those records from a record set which match a condition.
Sort: Sorts the recordset.
Aggregate: Used for things like count, max, min, etc.
Bitmap Heap Scan: Uses a bitmap to represent matching records. Operations like and-ing and or-ing can sometimes be done more easily to the bitmap than to the actual records.
...many more. :)

Performance estimates

Each node in the node list has a set of performance estimates. They look like this:

Limit  (cost=892.98..893.01 rows=10 width=812)

The numbers are:

Cost: How much effort it will take to perform the action. This number is unit-less, and only meant to be compared to other cost numbers.
Rows: The estimated number of rows that have to be looped-over to perform the action.
Width: The estimated size in bytes of each row

I find myself using "Rows" the most. It's really useful for seeing if the query scales. If it equals "1" then I know the query is performant. If it equals the number of records in the table, then the query probably isn't very performant with large datasets.

Actual performance values

If you use the explain analyze feature to actually run the query, then you'll be given two sets of numbers. The first contains estimates, like the ones above. The second contains the actual values:

# explain analyze select * from users order by created_at limit 10;
                                                       QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=892.98..893.01 rows=10 width=812) (actual time=22.443..22.446 rows=10 loops=1)
   ->  Sort  (cost=892.98..919.16 rows=10471 width=812) (actual time=22.441..22.443 rows=10 loops=1)
         Sort Key: created_at
         Sort Method: top-N heapsort  Memory: 31kB
         ->  Seq Scan on users  (cost=0.00..666.71 rows=10471 width=812) (actual time=0.203..15.221 rows=10472 loops=1)
 Total runtime: 22.519 ms
(6 rows)

The items are:

Actual time: The time in milliseconds that it will take to perform the action.
Rows: The actual number of rows to be processed.
Loops: Sometimes a given action happens more than once. If it does, loops will be > 1.

More verbose output

By default explain outputs a pretty condensed version of what it knows. You can, however, ask it to give you more detail. You can even tell it to output formats like JSON or YAML.

# EXPLAIN (ANALYZE, FORMAT YAML) select * from users order by created_at limit 10;
                QUERY PLAN
------------------------------------------
 - Plan:                                 +
     Node Type: "Limit"                  +
     Startup Cost: 892.98                +
     Total Cost: 893.01                  +
     Plan Rows: 10                       +
     Plan Width: 812                     +
     Actual Startup Time: 12.945         +
     Actual Total Time: 12.947           +
     Actual Rows: 10                     +
     Actual Loops: 1                     +
     Plans:                              +
       - Node Type: "Sort"               +
         Parent Relationship: "Outer"    +
         Startup Cost: 892.98            +
         Total Cost: 919.16              +
         Plan Rows: 10471                +
         Plan Width: 812                 +
         Actual Startup Time: 12.944     +
         Actual Total Time: 12.946       +
         Actual Rows: 10                 +
         Actual Loops: 1                 +
         Sort Key:                       +
           - "created_at"                +
         Sort Method: "top-N heapsort"   +
         Sort Space Used: 31             +
         Sort Space Type: "Memory"       +
         Plans:                          +
           - Node Type: "Seq Scan"       +
             Parent Relationship: "Outer"+
             Relation Name: "users"      +
             Alias: "users"              +
             Startup Cost: 0.00          +
             Total Cost: 666.71          +
             Plan Rows: 10471            +
             Plan Width: 812             +
             Actual Startup Time: 0.008  +
             Actual Total Time: 5.823    +
             Actual Rows: 10472          +
             Actual Loops: 1             +
   Triggers:                             +
   Total Runtime: 13.001
(1 row)

You can get even more verbose output by using EXPLAIN (ANALYZE, VERBOSE, FORMAT YAML) select ...

Visualization tools

Explain generates a lot of output. When analyzing more complex queries, it can become difficult to parse.

There are several free tools designed to help you. They parse the output of explain and generate nice diagrams for you. They can even flag potential performance issues for your review. Here's one I like.

Examples

Let's put it all together and do a few quick examples. Did you know that there are several common Rails idioms that produce poorly-scaling database queries?

The counting conundrum

It's really common to see code like this in Rails views:

Total Faults <%= Fault.count %>

That results in SQL that looks something like this:

select count(*) from faults;

Let's plug into explain and see what happens.

# explain select count(*) from faults;
                            QUERY PLAN
-------------------------------------------------------------------
 Aggregate  (cost=1840.31..1840.32 rows=1 width=0)
   ->  Seq Scan on faults  (cost=0.00..1784.65 rows=22265 width=0)
(2 rows)

Woah! Our simple count query is looping over 22,265 rows — the entire table! In postgres, counts always loop over the entire record set.

The sorting scandal

It's really common to see lists of items, sorted by some field. For example:

Fault.order("created_at desc").limit(10)

You're just retrieving 10 records, right? But to get them, you have to sort the entire table. As you can see below, the Sort node has to process 22,265 rows.

# explain select * from faults order by created_at limit 10;
                                 QUERY PLAN
----------------------------------------------------------------------------
 Limit  (cost=2265.79..2265.81 rows=10 width=1855)
   ->  Sort  (cost=2265.79..2321.45 rows=22265 width=1855)
         Sort Key: created_at
         ->  Seq Scan on faults  (cost=0.00..1784.65 rows=22265 width=1855)

By adding an index we can replace the Sort node with a much faster Index Scan.

# CREATE INDEX index_faults_on_created_at ON faults USING btree (created_at);
CREATE INDEX

# explain select * from faults order by created_at limit 10;
                                               QUERY PLAN
---------------------------------------------------------------------------------------------------------
 Limit  (cost=0.29..2.66 rows=10 width=1855)
   ->  Index Scan using index_faults_on_created_at on faults  (cost=0.29..5288.04 rows=22265 width=1855)
(2 rows)

Conclusion

I hope this article has been helpful and will encourage you to play around with the explain command. It's really fundamental to understanding how your application will scale as you bring in more and more data.