Slow in production, fast in pgAdmin

Published 1 year ago

Ever came across with a mysterious performance issue of a database query, while executing the exact same query directly on the same database instance performs fast as it should? Are you using prepared statements with your ORM or query builder? Are you on Postgres? Chances are, you're not really running the exact same queries. And in this post I'm about to elaborate on the importance of using proper data types during any interaction with a database.

Preparation

Consider having the following silly demo table:

CREATE TABLE posts (
    id UUID,
    name CHARACTER VARYING,
    tag_ids UUID[]
);

INSERT INTO posts (id, name, tag_ids) VALUES (
    'c709c1d6-66e4-4670-be67-00e31376227d', 
    'First', 
    '{"f881c3bb-737f-4df6-a9c2-30afa459bfbf", "a4817385-8f4b-4a8c-b9c1-87907630b788", "4472bd25-4cc3-4a57-acdd-27dd1ea499f4"}'
);

Scenario

Now imagine, you have an application, which is trying to fetch all entries from posts that contain any of the supplied tag ids. Something like this:

SELECT id, name 
FROM posts 
WHERE tag_ids && CAST(ARRAY['f881c3bb-737f-4df6-a9c2-30afa459bfbf', '02edf96c-6522-4f60-b1f1-5aad4cb63228']::UUID[] AS UUID[]);

Please, refer to the corresponding documentation if you're unfamiliar with Postgres arrays and operators.

Usage of some ORMs could be less desirable than others, as in some cases they tend to be poorly designed or quite restrictive, or the very least inconvenient to use. That may force some developers to end up with a query similar to this in a prepared statement:

SELECT id, name FROM posts WHERE tag_ids && CAST(? AS UUID[]);

...and then, as a parameter you could pass '{"f881c3bb-737f-4df6-a9c2-30afa459bfbf", "02edf96c-6522-4f60-b1f1-5aad4cb63228"}' as a string on the application side. Simple Postgres array syntax; easy, right?

What goes wrong?

Now if you have a closer look at the query above, you'll notice we're actually casting a CHARACTER VARYING to a UUID[] on the database side.

The reason why this is important is, that during debugging, it is often overlooked that we're actually dealing with prepared statements. When starting such an investigation, after figuring out that the database query is the culprit for the performance impact, the first logical step would be to run the same query directly on the database with a tool like pgAdmin or DataGrip, or even using the psql console. But check this out:

-- Substitute the parameter like how the ORM would in our app
EXPLAIN ANALYZE SELECT id, name FROM posts WHERE tag_ids && CAST('{"f881c3bb-737f-4df6-a9c2-30afa459bfbf", "02edf96c-6522-4f60-b1f1-5aad4cb63228"}'AS UUID[]);

-- Substitute the parameter with an actual UUID[]
EXPLAIN ANALYZE SELECT id, name FROM posts WHERE tag_ids && CAST(ARRAY['f881c3bb-737f-4df6-a9c2-30afa459bfbf', '02edf96c-6522-4f60-b1f1-5aad4cb63228']::UUID[] AS UUID[]);

-- Both variants from above, but without CAST()
EXPLAIN ANALYZE SELECT id, name FROM posts WHERE tag_ids && '{"f881c3bb-737f-4df6-a9c2-30afa459bfbf", "02edf96c-6522-4f60-b1f1-5aad4cb63228"}';
EXPLAIN ANALYZE SELECT id, name FROM posts WHERE tag_ids && ARRAY['f881c3bb-737f-4df6-a9c2-30afa459bfbf', '02edf96c-6522-4f60-b1f1-5aad4cb63228']::UUID[];

All of those would conclude with an optimal performance report, e.g.:

Seq Scan on posts  (cost=0.00..19.38 rows=7 width=48) (actual time=0.007..0.008 rows=1 loops=1)
   Filter: (tag_ids && '{f881c3bb-737f-4df6-a9c2-30afa459bfbf,02edf96c-6522-4f60-b1f1-5aad4cb63228}'::uuid[])
Planning Time: 0.036 ms
Execution Time: 0.015 ms

Postgres can see that it's a UUID[], no matter what. This is why during your debug sessions you'll experience your query completing with a good performance. But to truly reproduce what your ORM is doing, try it this way:

PREPARE stmt1 (CHARACTER VARYING) AS
    SELECT id, name FROM posts WHERE tag_ids && CAST(? AS UUID[]);
EXPLAIN ANALYZE EXECUTE stmt1('{"f881c3bb-737f-4df6-a9c2-30afa459bfbf", "02edf96c-6522-4f60-b1f1-5aad4cb63228"}');

Remember, in our imaginary application, we're passing a string representation of a UUID array as a parameter to the prepared statement? Well, that's how it translates to Postgres, and it reveals the flaw right away:

Seq Scan on posts  (cost=0.00..23.12 rows=7 width=48) (actual time=0.009..0.009 rows=1 loops=1)
   Filter: (tag_ids && ('{""f881c3bb-737f-4df6-a9c2-30afa459bfbf"", ""02edf96c-6522-4f60-b1f1-5aad4cb63228""}'::cstring)::uuid[])
Planning Time: 0.068 ms
Execution Time: 0.016 ms

Previously, in every attempt to reproduce the initial issue, we consistently got an optimal cost of 0.00..19.38, but in this case it went up to 0.00..23.12. It is because now our query is hidden behind a prepared statement, and Postgres is expecting a CHARACTER VARYING instead of a UUID[], which in turn, forces it to choose a different optimization algorithm internally.

Solution

To rectify the problem, you have to make sure to pass the parameter in the matching data type to your prepared statement. When it's done correctly, it would go through as:

PREPARE stmt2 (UUID[]) AS
    SELECT id, name FROM posts WHERE tag_ids && CAST(? AS UUID[]);
EXPLAIN ANALYZE EXECUTE stmt2('{"f881c3bb-737f-4df6-a9c2-30afa459bfbf", "02edf96c-6522-4f60-b1f1-5aad4cb63228"}');

Seq Scan on posts  (cost=0.00..19.38 rows=7 width=48) (actual time=0.007..0.008 rows=1 loops=1)
   Filter: (tag_ids && '{f881c3bb-737f-4df6-a9c2-30afa459bfbf,02edf96c-6522-4f60-b1f1-5aad4cb63228}'::uuid[])
Planning Time: 0.050 ms
Execution Time: 0.015 ms

The cost is back to 0.00..19.38.

Key takeaways

Firstly and most importantly, no matter what sort of programming task it is, use the correct data types. Use casts only if it's absolutely necessary, and do everything you can to eliminate them. Using the proper types makes the code more readable, more convenient to work with, and as it turns out, it could offer better performance.

Secondly, when it comes to debugging, bear in mind that prepared statements do have an extra layer of obfuscation - so it's worth checking your queries with Postgres' prepared statement syntax as well.