Performance issues with CAST function

Question

Observing this performance issue that can't be explained with EXPLAIN in a PostgreSQL 9.6 database.

There is currently a table public.users, which has a cast on it to output a record to JSONb. (e.g. SELECT u::jsonb FROM users u;).

The database has grown in complexity and schemas, which a new schema (think module) has been added that adds a few things to the user accounts (via joins in the schema table).

To make the cast to JSONb consistant across the app, the public.users cast was refashioned to use a cast in a new schema called catalogue. This way casting public.users will get additional properties from the catalogue schema in a transparent way to the user. This was done so that the API Server doesn't need to know to use this/that schema, and I can leave my (reused) User API Controller the same.

The new [refashioned] cast returns the cast from catalogue.users, so basically the public's cast function on users call a [SQL] function with the simple SQL command..

CREATE OR REPLACE FUNCTION catalogue.cast_user_jsonb_override(public.user)  RETURNS JSONb STABLE LANGUAGE sql
AS $$ 
 SELECT u::jsonb FROM catalogue.users u WHERE username = $1.username 
$$;

This way the casting public.user to JSONb will utilise the above cast without the user knowing.

However, for some reason calling the cast for public.users is slow, while calling the cast for catalogue.users is fast.

Calling...

EXPLAIN ANALYSE VERBOSE SELECT u::jsonb FROM catalogue.users u;
....
Planning time: 0.046 ms
Execution time: 40.086 ms

while calling...

EXPLAIN ANALYSE VERBOSE SELECT u::jsonb FROM catalogue.users u;
....
Planning time: 0.094 ms
Execution time: 1384.414 ms

or directly...

EXPLAIN ANALYSE VERBOSE SELECT catalogue.cast_users_jsonb_override(u) FROM public.users u;
....
Planning time: 0.101 ms
Execution time: 1325.343 ms

If anything, the catalogue cast should be the slower one as is performs joins and the likes.

The [override] cast function is STABLE to help with performance, but it doesn't seem to do much.

Any ideas as to why calling a function that executes a basic SELECT is slow, while calling the SQL itself is fast? . I haven't tested it in any other postgresql version, and there isn't any priority to do an upgrade to v10 to test as there is currently a deadline on the release.

Answer 1

Put auto_explain into shared_preload_libraries in postgresql.conf and restart PostgreSQL.

Set

auto_explain.log_min_duration = 0
auto_explain.log_nested_statements = on
auto_explain.log_analyze = on
auto_explain.log_buffers = on

in postgresql.conf (and reload).

Then run the slow query again.

This will log all SQL statements and their execution plan in the PostgreSQL log. Examine the plan for the statement run in your function. That should give you a clue.

The most likely explanation would be a missing index on catalogue.users(username).