End Point

News

Welcome to End Point's blog

Ongoing observations by End Point people.

Why is my function slow?

I often hear people ask "Why is my function so slow? The query runs fast when I do it from the command line!" The answer lies in the fact that a function's query plans are cached by Postgres, and the plan derived by the function is not always the same as shown by an EXPLAIN from the command line. To illustrate the difference, I downloaded the pagila test database. To show the problem, we'll need a table with a lot of rows, so I used the largest table, rental, which has the following structure:

pagila# \d rental
                       Table "public.rental"
    Column    |   Type     |             Modifiers
--------------+-----------------------------+--------------------------------
 rental_id    | integer    | not null default nextval('rental_rental_id_seq')
 rental_date  | timestamp  | not null
 inventory_id | integer    | not null
 customer_id  | smallint   | not null
 return_date  | timestamp  |
 staff_id     | smallint   | not null
 last_update  | timestamp  | not null default now()
Indexes:
    "rental_pkey" PRIMARY KEY (rental_id)
    "idx_unq_rental" UNIQUE (rental_date, inventory_id, customer_id)
    "idx_fk_inventory_id" (inventory_id)

It only had 16044 rows, however, not quite enough to demonstrate the difference we need. So let's add a few more rows. The unique index means any new rows will have to vary in one of the three columns: rental_date, inventory_id, or customer_id. The easiest to change is the rental date. By changing just that one item and adding the table back into itself, we can quickly and exponentially increase the size of the table like so:

INSERT INTO rental(rental_date, inventory_id, customer_id, staff_id)
  SELECT rental_date + '1 minute'::interval, inventory_id, customer_id, staff_id
  FROM rental;

I then ran the same query again, but with '2 minutes', '4 minutes', '8 minutes', and finally '16 minutes'. At this point, the table had 513,408 rows, which is enough for this example. I also ran an ANALYZE on the table in question (this should always be the first step when trying to figure out why things are going slower than expected). The next step is to write a simple function that accesses the table by counting how many rentals have occurred since a certain date:

DROP FUNCTION IF EXISTS count_rentals_since_date(date);

CREATE FUNCTION count_rentals_since_date(date)
RETURNS BIGINT
LANGUAGE plpgsql
AS $body$
  DECLARE
    tcount INTEGER;
  BEGIN
    SELECT INTO tcount
      COUNT(*) FROM rental WHERE rental_date > $1;
  RETURN tcount;
  END;
$body$;

Simple enough, right? Let's test out a few dates and see how long each one takes:

pagila# \timing

pagila# select count_rentals_since_date('2005-08-01');
 count_rentals_since_date
--------------------------
                   187901
Time: 242.923 ms

pagila# select count_rentals_since_date('2005-09-01');
 count_rentals_since_date
--------------------------
                     5824
Time: 224.718 ms

Note: all of the queries in this article were run multiple times first to reduce any caching effects. Those times appear to be about the same, but I know from the distribution of the data that the first query will not hit the index, but the second one should. Thus, when we try and emulate what the function is doing on the command line, the first effort often looks like this:

pagila# explain analyze select count(*) from rental where rental_date > '2005-08-01';
                     QUERY PLAN
--------------------------------------------------------------------------------
 Aggregate (actual time=579.543..579.544)
   Seq Scan on rental (actual time=4.462..403.122 rows=187901)
     Filter: (rental_date > '2005-08-01 00:00:00')
 Total runtime: 579.603 ms

pagila# explain analyze select count(*) from rental where rental_date > '2005-09-01';

                     QUERY PLAN
--------------------------------------------------------------------------------
 Aggregate  (actual time=35.133..35.133)
   Bitmap Heap Scan on rental (actual time=1.852..30.451)
     Recheck Cond: (rental_date > '2005-09-01 00:00:00')
     -> Bitmap Index Scan on idx_unq_rental (actual time=1.582..1.582 rows=5824)
         Index Cond: (rental_date > '2005-09-01 00:00:00')
 Total runtime: 35.204 ms

Wow, that's a huge difference! The second query is hitting the index and using some bitmap magic to pull back the rows in a blistering time of 35 milliseconds. However, the same date, using the function, takes 224 ms - over six times as slow! What's going on? Obviously, the function is *not* using the index, regardless of which date is passed in. This is because the function cannot know ahead of time what the dates are going to be, but caches a single query plan. In this case, it is caching the 'wrong' plan.

The correct way to see queries as a function sees them is to use prepared statements. This caches the query plan into memory and simply passes a value to the already prepared plan, just like a function does. The process looks like this:

pagila# PREPARE foobar(DATE) AS SELECT count(*) FROM rental WHERE rental_date > $1;
PREPARE

pagila# EXPLAIN ANALYZE EXECUTE foobar('2005-08-01');
                QUERY PLAN
--------------------------------------------------------------
 Aggregate  (actual time=535.708..535.709 rows=1)
   ->  Seq Scan on rental (actual time=4.638..364.351 rows=187901)
         Filter: (rental_date > $1)
 Total runtime: 535.781 ms

pagila# EXPLAIN ANALYZE EXECUTE foobar('2005-09-01');
                QUERY PLAN
--------------------------------------------------------------
 Aggregate  (actual time=280.374..280.375 rows=1)
   ->  Seq Scan on rental  (actual time=5.936..274.911 rows=5824)
         Filter: (rental_date > $1)
 Total runtime: 280.448 ms

These numbers match the function, so we can now see the reason the function is running as slow as it does: it is sticking to the "Seq Scan" plan. What we want to do is to have it use the index when the given date argument is such that the index would be faster. Functions cannot have more than one cached plan, so what we need to do is dynamically construct the SQL statement every time the function is called. This costs us a small bit of overhead versus having a cached query plan, but in this particular case (and you'll find in nearly all cases), the overhead lost is more than compensated for by the faster final plan. Making a dynamic query in plpgsql is a little more involved than the previous function, but it becomes old hat after you've written a few. Here's the same function, but with a dynamically generated SQL statement inside of it:

DROP FUNCTION IF EXISTS count_rentals_since_date_dynamic(date);

CREATE FUNCTION count_rentals_since_date_dynamic(date)
RETURNS BIGINT
LANGUAGE plpgsql
AS $body$
  DECLARE
    myst TEXT;
    myrec RECORD;
  BEGIN
    myst = 'SELECT count(*) FROM rental WHERE rental_date > ' || quote_literal($1);
    FOR myrec IN EXECUTE myst LOOP
      RETURN myrec.count;
    END LOOP;
  END;
$body$;

Note that we use the quote_literal function to take care of any quoting we may need. Also notice that we need to enter into a loop to run the query and then parse the output, but we can simply return right away, as we only care about the output from the first (and only) returned row. Let's see how this new function performs compared to the old one:

pagila# \timing

pagila# select count_rentals_since_date_dynamic('2005-08-01');
 count_rentals_since_date_dynamic
----------------------------------
                           187901
Time: 255.022 ms

pagila# select count_rentals_since_date('2005-08-01');
 count_rentals_since_date
--------------------------
                   187901
Time: 249.724 ms

pagila# select count_rentals_since_date('2005-09-01');
 count_rentals_since_date
--------------------------
                     5824
Time: 228.224 ms

pagila# select count_rentals_since_date_dynamic('2005-09-01');
 count_rentals_since_date_dynamic
----------------------------------
                             5824
Time: 6.618 ms

That's more like it! Problem solved. The function is running much faster now, as it can hit the index. The take-home lessons here are:

  1. Always make sure the tables you are using have been analyzed.
  2. Emulate the queries inside a function by using PREPARE + EXPLAIN EXECUTE, not EXPLAIN.
  3. Use dynamic SQL inside a function to prevent unwanted query plan caching.

11 comments:

Pavel Stěhule said...

your function from sample will be radically simplified in 8.4:

CREATE FUNCTION count_rentals_since_date_dynamic(date)
RETURNS BIGINT
LANGUAGE plpgsql
AS $body$
BEGIN
RETURN QUERY EXECUTE 'SELECT count(*) FROM rental WHERE rental_date > $1' USING $1;
END;
$body$;

regards
Pavel Stehule

Josh said...

It would be interesting (and lots of programming) to let a prepared statement cache a set of query plans, perhaps as many as one per filter step in the query, and choose between them at execution time based on the selectivity of each filter.

Daniel Lyons said...

It's probably faster (in addition to being more portable and safer) to use SQL instead of PL/pgSQL, since you're not really doing anything but running an SQL query with it. In other words, something like:

CREATE FUNCTION count_rentals_since_date_dynamic(date)
RETURNS BIGINT
AS $body$
SELECT count(*) FROM rental WHERE rental_date > $1;
$body$ LANGUAGE sql;

Greg Sabino Mullane said...

Pavel: Cool, 8.4 is going to be a nice release indeed. Thanks for the blog updates on what to look forward to!

Josh: Sounds tricky, I don't know if that would really gain much over just making a complete plan then and there.

Daniel: Yes, but this was just a simplified example, and most real-world functions with this problem (that I've come across) are plpgsql. I even thought about putting a SQL version of the function in the article, but decided to keep the article shorter and focused.

Joshua Tolley said...

The multiple cached plans technique would definitely be tricky :) I'm expecting most of the parsing overhead would happen only once per query (rather than, say, once per cached plan), and that it would gracefully avoid catastrophic failures such as you demonstrate while adding little to execution time for a prepared query. But I can't back up that expectation, yet :)

Chris said...

Hi, I'm a developer... not a DBA. We don't have a DBA, so I was tasked with figuring out what was going with some triggers in our Postgres 8.1 database. This article is the only thing I could find that helped. In fact, I started using strings/executions instead of just plain statements all over and cut execution time by over 90%.

Anyway, it seems like caching of a bad plan for functions is a huge failure... and I'm a little shocked I didn't find any other references to it out there. Maybe I'm looking in the wrong place. Can anyone refer me to some documentation or something that points this postgres foible out? Or suggests this awesome solution as a best-practice?

Of course, the proof is in the pudding.. and the query is way better. But, still it'd be nice to read more about this.

I appreciate any input.

Greg Sabino Mullane said...

Chris:

I don't think you'll find too much info out there. It's just a limitation of Postgres - it has to make a best one-time guess. For a lot of functions, this works out.

The official docs mention it as an almost aside, buried deep in here:

http://www.postgresql.org/docs/current/static/plpgsql-implementation.html#PLPGSQL-PLAN-CACHING

There is probably many posts on the Postgres mailing lists that have pointed out this trick as well.

Robert said...

Thank you very much. That solved my problem!

Anonymous said...

It sounds like a workaround that everybody uses and having to build a query dynamically just for this reason sounds silly. It makes the code not easy to read and adds complexity. I don't get why still was not implemented a better way to let the parser know that a new plan should be created for the query? Oracle has HINTS, there is no such thing here?

Greg Sabino Mullane said...

Anon: There is some work lately on solving this problem, but without hints: more of an automatic reparsing as necessary. Hints are a hot topic but generally frowned upon in the Postgres world as being more trouble than they are worth.

Greg Sabino Mullane said...

Anonymous, this is mostly fixed as of version 9.2. Please read http://blog.endpoint.com/2014/04/custom-plans-prepared-statements-in.html