DEV Community

evie
evie

Posted on

A Rubyist's Guide to Postgresql's Explain

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)
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

This output is made of two parts:

  1. The "node list" describing the sequence of actions to perform the query
  2. 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
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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.

Visual Query Plan

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 %>
Enter fullscreen mode Exit fullscreen mode

That results in SQL that looks something like this:

select count(*) from faults;
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode

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.

Top comments (2)

Collapse
 
mlabarca profile image
Mauricio Labarca

Terrific ! Was there an option to automatically explain big queries in development environment?

Collapse
 
szaszolak profile image
Mikołaj Wawrzyniak

Grate job! Smooth and simple.