First DELETE query made by a connection against a partitioned table is very slow

[jasonl]

We've been running into an issue with pg_pathman. Versions in use:

pg_pathman: 1.4.1
Postgresql: 9.6.3

The fundamental issue is that for the first DELETE query against partitioned tables run on a connection, the planning process is extraordinarily slow, often taking several seconds, yet is much faster on subsequent executions for the same Postgres connection.

So when we first interact with a Postgres connection, and run EXPLAIN against the child table, everything happens quite quickly:

postgres=# \c production_db
You are now connected to database "production_db" as user "postgres".
production_db=# EXPLAIN DELETE FROM "schema_name"."redacted_table_2605" WHERE "schema_name"."redacted_table_2605"."customer_id" = 31104246 AND "schema_name"."redacted_table_2605"."account_id" = 1931;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
   ->  Index Scan using redacted_table_2605_pkey on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
         Index Cond: ((account_id = 1931) AND (customer_id = 31104246))
(3 rows)

Time: 12.970 ms
production_db=# EXPLAIN DELETE FROM "schema_name"."redacted_table_2605" WHERE "schema_name"."redacted_table_2605"."customer_id" = 31104246 AND "schema_name"."redacted_table_2605"."account_id" = 1931;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
   ->  Index Scan using redacted_table_2605_pkey on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
         Index Cond: ((account_id = 1931) AND (customer_id = 31104246))
(3 rows)

Time: 4.848 ms
production_db=# EXPLAIN DELETE FROM "schema_name"."redacted_table_2605" WHERE "schema_name"."redacted_table_2605"."customer_id" = 31104246 AND "schema_name"."redacted_table_2605"."account_id" = 1931;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
   ->  Index Scan using redacted_table_2605_pkey on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
         Index Cond: ((account_id = 1931) AND (customer_id = 31104246))
(3 rows)

Time: 0.745 ms
production_db=# EXPLAIN DELETE FROM "schema_name"."redacted_table_2605" WHERE "schema_name"."redacted_table_2605"."customer_id" = 31104246 AND "schema_name"."redacted_table_2605"."account_id" = 1931;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
   ->  Index Scan using redacted_table_2605_pkey on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
         Index Cond: ((account_id = 1931) AND (customer_id = 31104246))
(3 rows)

Time: 0.958 ms

However, when do the EXPLAIN for the query against the parent table, the first explain (and actual queries too) takes several seconds. This is the same psql session as above, using the exactly same connection, I've just split it to put this explanation in:

production_db=# EXPLAIN DELETE FROM "schema_name"."redacted_table" WHERE "schema_name"."redacted_table"."customer_id" = 31104246 AND "schema_name"."redacted_table"."account_id" = 1931;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
   ->  Index Scan using redacted_table_2605_pkey on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
         Index Cond: ((account_id = 1931) AND (customer_id = 31104246))
(3 rows)

Time: 2097.566 ms
production_db=# EXPLAIN DELETE FROM "schema_name"."redacted_table" WHERE "schema_name"."redacted_table"."customer_id" = 31104246 AND "schema_name"."redacted_table"."account_id" = 1931;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
   ->  Index Scan using redacted_table_2605_pkey on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
         Index Cond: ((account_id = 1931) AND (customer_id = 31104246))
(3 rows)

Time: 1.095 ms
production_db=# EXPLAIN DELETE FROM "schema_name"."redacted_table" WHERE "schema_name"."redacted_table"."customer_id" = 31104246 AND "schema_name"."redacted_table"."account_id" = 1931;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
   ->  Index Scan using redacted_table_2605_pkey on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
         Index Cond: ((account_id = 1931) AND (customer_id = 31104246))
(3 rows)

Time: 0.993 ms
production_db=# EXPLAIN DELETE FROM "schema_name"."redacted_table" WHERE "schema_name"."redacted_table"."customer_id" = 31104246 AND "schema_name"."redacted_table"."account_id" = 1931;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
   ->  Index Scan using redacted_table_2605_pkey on redacted_table_2605  (cost=0.29..4.59 rows=6 width=6)
         Index Cond: ((account_id = 1931) AND (customer_id = 31104246))
(3 rows)

Time: 0.928 ms

The table we're querying has the following check constraint for pg_pathman:

"pathman_redacted_table_2605_check" CHECK (account_id >= 1931 AND account_id < 1932)

Notice the timings: In both cases, where we run DELETE queries against the parent table, and directly against the child table, the Postgres query planner produces the correct query plan. But the first time it does so when pg_pathman is involved, it takes several seconds.

We've also noticed where these DELETE conditions are triggered, Postgres memory use spikes and it starts accruing tens of thousands of RowExclusiveAccess locks. This only happens with DELETE statements, and does not affect INSERT or UPDATE statements so far as we can tell.

[funbringer]

Hi @jasonl,

How many partitions do you have? There's nothing extraordinary, pg_pathman has to build internal cache on 1st access to table. Execution time should depend on total amount of partitions, though.

Generally, we suggest using connection pools to minimize impact of "1st time caching".

[jasonl]

We have 1943 tables. Is that an excessive amount that would require several seconds for the caches to be built?

[funbringer]

We have 1943 tables. Is that an excessive amount that would require several seconds for the caches to be built?

Not really, could you show us your partitioning scheme (partitioning expression, table definition, something that could help)?

[funbringer]

Here's my small bench:

postgresql.conf:

max_locks_per_transaction = 512
shared_buffers = 1GB
fsync = off

/* create a table & fill it with some data */
create table test(val int not null);
select create_range_partitions('test', 'val', 1, 100, 10000);
insert into test select generate_series(1, 10000000) % 1000001;

# stop warm DB
~/pg_10/bin/pg_ctl -D ~/pg_10/DB stop

# flush all caches
sync && echo 3 > /proc/sys/vm/drop_caches

# start cold DB
~/pg_10/bin/pg_ctl -D ~/pg_10/DB start

explain analyze delete from test where val = 1;
                                               QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on test_1  (cost=0.00..17.50 rows=10 width=6) (actual time=5.888..5.888 rows=0 loops=1)
   ->  Seq Scan on test_1  (cost=0.00..17.50 rows=10 width=6) (actual time=5.887..5.887 rows=0 loops=1)
         Filter: (val = 1)
         Rows Removed by Filter: 990
 Planning time: 665.157 ms
 Execution time: 60.405 ms
(4 rows)

/* everything has been cached properly (10001 partitions & bounds) */
table pathman_cache_stats ;
         context          |  size   |  used  | entries
--------------------------+---------+--------+---------
 maintenance              |       0 |      0 |       0
 partition dispatch cache |  449392 | 448048 |       1
 partition parents cache  |  516096 | 336992 |   10001
 partition bounds cache   | 1040384 | 735096 |   10001
(6 rows)

As you can see, my laptop seems to cope with 10k partitions.

[jasonl]

I've investigated a bit more - and it seems the several seconds of cache loading time was also to do with database load, and not just pg_pathman. We'll look into "pre-warming" our connections in the connection pool.

Does pg_pathman cache the partition data on a per-database level, or is it per-table?

[funbringer]

Does pg_pathman cache the partition data on a per-database level, or is it per-table?

It's a per-session cache that's bound to postgres' relcache (which is also per-session). The cache is mainly used for partition dispatch. I think we should create an article in our Wiki providing some basics of our caching mechanisms.

Each entry of dispatch cache represents one partitioned table.

[jasonl]

What happens when a new child table is created? Does that invalidate the partition dispatch cache?

[funbringer]

What happens when a new child table is created? Does that invalidate the partition dispatch cache?

pg_pathman performs partial invalidation: dispatch cache entry is marked invalid and its contents are freed, but known partition bounds can still be reused. After that, this entry remains invalid until some query accesses the partition table (yes, our caches are lazy). The refresh procedure requires that all partitions are locked (we use AccessShareLock).

[jasonl]

So, we've looked into this a bit more. Our actual problem was that we were seeing massive memory spikes and tens of thousands of RowExclusiveLocks from a part of our application where we had 20 threads all updating partitioned tables.

The reason these RowExclusiveLocks were being taken - we think - and not the AccessShareLock you say, is that the first statement being executed by the worker threads that touched certain partitioned tables was a DELETE statement. The result of this was that we would get all 20 threads taking out RowExclusiveLock on all partitioned tables, which ended up being over 100K locks in total, which caused Postgres memory use to spike, and then then OOM-killer would kill a backend, corrupting shared memory, and all backends would have to restart.

We've pushed a fix to production which has all the threads run a useless select query on all the partitioned tables before any delete statements, which should ensure that a DELETE statement is almost never executed on a connection with an invalidated partition cache. The result of this is that we now don't see the 100K+ spikes in RowExclusiveLocks, but a much smaller spike of around 5K AccessShareLocks when we deliberately trigger a partition cache invalidation by adding or deleting a partitioned table, which is the same spike we see when our connection pool originally builds its pool (and it is set to run the same noop SELECT statements to ensure all the connections there have a pre-warmed partition cache)

Anyway, thanks for all your help.

[funbringer]

Anyway, thanks for all your help.

I'm glad that you were able to improve the situation, but could you elaborate more on the 100K locks problem? I don't quite understand this part:

The result of this was that we would get all 20 threads taking out RowExclusiveLock on all partitioned tables, which ended up being over 100K locks in total

We always use AccessShareLock, be it DELETE, UPDATE, SELECT or anything else.

[jasonl]

We have 4 partitioned tables, each with around 1900 partitions. These partitions are per-customer for us, so when we add a new customer, a new partition gets added to each of these tables. What I think is happening is that when a new partition is added, all 20 connections have their cache invalidated, and when the invalidated cache is rebuilt in a DELETE statement, something - perhaps in Postgres itself, rather then pg_pathman - takes a RowExclusiveLock on every child table.

We have metrics on Postgres showing total locks, split up by lock type, with a sample taken every 5 seconds. And in these metrics, we were seeing spikes above 100K RowExclusiveLocks. Since we've changed our application software to ensure that a connection which may have an invalid partition cache never runs a DELETE statement first, the problem has gone away - and we only see spikes of around 5K or so AccessShareLocks.

[funbringer]

Thank you for the clarification!

something - perhaps in Postgres itself, rather then pg_pathman - takes a RowExclusiveLock on every child table.

This doesn't sound right, I'll investigate this further.

[jamatthews]

@funbringer We've managed to narrow down the memory usage spikes to deleting from a range partitioned table where no partition exists to contain the key. The query plan appears to be a sequential scan of the parent table but it takes a suspiciously long time for querying an empty table and memory is consumed but seemingly not freed.

Reproducing the issue for us is as simple as:

create table test(val int not null);
select create_range_partitions('test', 'val', 1, 100, 10000);
insert into test select generate_series(1, 10000000) % 1000001;
delete from test where val = 0;

The amount of memory consumed is far higher than what we have shared_buffers set to, so it's definitely not shared memory. Usage doesn't go down until we close the session.

* Mem usage for PID 4043
-- Rss: 1965828 kB
-- Pss: 1.79396e+06 kB
Shared Clean 5380 kB
Shared Dirty 207168 kB
Private 1753280 kB

[funbringer]

Reproducing the issue for us is as simple as:

I'm sorry, but why do you consider this a real use case? You don't create 10k partitions every once in a while, do you?

Consider this: we've just created a 10k partitions, that's a good amount, and it might be that after millions of allocations we ended up having a meaningful living pointer (with a different lifecycle) to the process heap that prevents libc from using brk() or sbrk(). I'm not saying that "2 gigs of mem per backend" is ok, but the problem seems to be irrelevant to the original topic. We could discuss it later, though.

By the way, you might want to take a look at pathman_cache_stats view, and also at the memstat extension.