requests slow down by 100 times

One of the clients of our PostgreSQL server monitoring system had a problem with severely slow queries when running the database in Docker. In this article we will talk about the possible consequences of using PostgreSQL in Docker with the default configuration.

A client came forward with a problem – the interface was slow when displaying logs. The analysis showed that the reason is the long execution of the request (we give it in abbreviated form):

SELECT
	rc.pack
,	rc.recno
,	rc.ts
,	rc.type
,	rc.duration
,	coalesce(rc.unparsed, '') unparsed
,	rc.dt::text
,	get_rawdata_str(rc.dt, rc.pack, rc.recno) "text"
,	( SELECT ... ) query
,	regexp_replace(( SELECT ... )::text, '^\[(.*)\]$', '\1') context
,	( SELECT ... ) parameters
,	( SELECT ... ) exectime
,	( SELECT ... ) plan
,	( SELECT ... ) "lock"
,	err.error
,	err.errargs
,	err.msg
FROM
	record rc
LEFT JOIN
	LATERAL( SELECT ...	) err
		ON TRUE
WHERE
	(rc.pack, rc.dt) = ($1::uuid, $2::date)
ORDER BY
	recno;

Loading the query plan to explain.tensor.ru :

We see that all the time was spent on the root node”Nested Loop Left Join“.

This happened as a result of calling functions on the columns of the root JOIN, but there or get_rawdata_str or regexp_replace . In this case, both functions are not displayed in the plan, and all their time and resources are reflected in the root node:

Since the database is test and there is not much data, then regexp_replace cannot consume many resources.

Checking the PL/pgSQL function get_rawdata_str – it generates its plan, but it is not displayed when called EXPLAIN ANALYZE . It is possible to obtain a query plan from such a function only using the module auto_explain when the parameter is enabled:

SET auto_explain.log_nested_statements = on;

In this case, the log will contain entries like CONTEXT with the plan of the called function:

CONTEXT:  SQL function "get_rawdata_str" statement 1

We enable this parameter and load the query plan from the function body:

query plan from get_rawdata_str function

We see that the request itself takes 309 ms, but the JIT takes another 1.7 seconds:

But why is JIT enabled on the client, but not on our servers?

In general, JIT appeared in version 11, Here there was discussion about its inclusion.

In version 11 it remained disabled by default, and in all versions starting from 12, JIT is enabled.

In addition to the config options, using JIT requires that several conditions be met:

PG assembly must be done with option –with-llvm in official packages this is true, but in the case of building from sources, you can check the presence of the option with the command:

pg_config --configure | grep with-llvm

presence of a JIT provider, by default it is llvmjit which is installed from the package postgresql-llvmjit.

When the server is rotated instructions only packages are installed postgresql-server as well as dependent postgresql And postgresql-libs and the JIT provider is not installed by default.

We also do not install a provider on our server, so we have JIT turned off.

By the way, you can check the functionality of JIT like this:

SELECT pg_jit_available();

The client reported that the database was deployed in Docker, since it was a test installation with a small amount of data.

It looks like the PostgreSQL docker image has JIT enabled and works out of the box. We check:

docker pull postgres
docker run --name postgres -e POSTGRES_PASSWORD=password -d postgres
docker exec -it postgres find / -name "*jit*"

/usr/lib/postgresql/16/lib/llvmjit_types.bc
/usr/lib/postgresql/16/lib/llvmjit.so
/usr/lib/postgresql/16/lib/bitcode/postgres/jit
/usr/lib/postgresql/16/lib/bitcode/postgres/jit/jit.bc
/usr/share/postgresql-common/server/test-with-jit.conf

docker exec -it postgres psql -U postgres -Atc 'SELECT pg_jit_available();'
t

That’s right – a JIT provider has been added to the image, which means that if the request cost threshold is exceeded, some of the operations will be optimized.

The decision to apply JIT optimizations is made based on the total cost of the request. If the value is exceeded jit_above_cost (default 100,000) JIT optimization of expressions in WHERE, aggregates, target lists and projections is performed, as well as transformation of tuples when loading them from disk into memory. In this case, the parameters in the query plan in the JIT section will be included Expressions And Deforming:

JIT:
  Options: Inlining false, Optimization false, Expressions true, Deforming true

If the cost of the request exceeds jit_inline_above_cost (default 500,000) or jit_optimize_above_cost (also 500,000 by default) then the bodies of small functions and statements will be inlined in the code and expensive optimizations may be applied. In the plan this will be displayed in the parameters Inlining And Optimization:

JIT:
  Options: Inlining true, Optimization true, Expressions true, Deforming true

In our request in the body of the function get_rawdata_str several LEFT JOINs on tables with a large number of rows, as a result, the cost of the query was very large and the scheduler connected JIT for optimization.

We ask the client to disable JIT:

ALTER SYSTEM SET jit=off;
SELECT pg_reload_conf();

And the query execution time dropped to 30 ms:

Problem solved. But to prevent this from happening again, we recommend running PostgreSQL in Docker with JIT disabled by default.

To do this, add the option to disable JIT to the launch command:

docker run --name postgres -e POSTGRES_PASSWORD=postgres -d postgres -c jit=off

Or create your own config and run PostgreSQL with it:

docker run -i --rm postgres cat /usr/share/postgresql/postgresql.conf.sample > my-postgres.conf
echo "jit=off" >> my-postgres.conf
docker run -d --name postgres -v "$PWD/my-postgres.conf":/etc/postgresql/postgresql.conf -e POSTGRES_PASSWORD=password postgres -c 'config_file=/etc/postgresql/postgresql.conf'