Hi Andres, Tom,
Andres, it seems like the problem is independent of having large data manipulations mixed with schema changes. The below test case demonstrates it with just schema changes.
Tom, I've tested your patch, and it seems to have a positive impact for sure. I've documented a test case to reproduce this issue (below), and your avoid-search-in-catcache-invalidate.patch reduces the test case time from 63 seconds per run to 27 seconds per run. Here's an updated sample capture with the patch applied: https://gist.github.com/mfenniak/cef36699deb426efd8e433027553a37e
Here's the test case I've been using for the above measurements:
a) creating 10,000 tables in 200 schemas
DO $$
DECLARE
i INTEGER;
j INTEGER;
schema TEXT;
BEGIN
FOR i IN 1..200 LOOP
schema := 'test_' || i;
EXECUTE format('CREATE SCHEMA IF NOT EXISTS %I', schema);
FOR j IN 1..500 LOOP
EXECUTE format('CREATE TABLE IF NOT EXISTS %I.%I (f1 int, f2 int)', schema, 'test_' || j);
END LOOP;
END LOOP;
END;
$$;
b) start logical replication w/ pg_recvlogical, printing out timestamps of messages and timestamps of transactions:
pg_recvlogical --create-slot --start -f - --if-not-exists --plugin=test_decoding --slot=cputest --dbname=mathieu.fenniak --username=postgres --option=include-timestamp | gawk '{ print strftime("%Y-%m-%d %H:%M:%S"), $0; fflush(); }'
c) drop a few schemas in a transaction
begin;drop schema test_1 cascade;drop schema test_2 cascade;drop schema test_3 cascade;drop schema test_4 cascade;drop schema test_5 cascade;drop schema test_6 cascade;commit;
Six schema drops had a 63s second delay between the actual commit and pg_recvlogical outputting it w/ stock 9.5.4:
2017-05-10 08:35:12 BEGIN 956
2017-05-10 08:36:15 COMMIT 956 (at 2017-05-10 08:35:12.106773-06)
Six schema drops w/ Tom's patch (applied to 9.5.4) had a 27 second delay:
2017-05-10 08:48:08 BEGIN 942
2017-05-10 08:48:35 COMMIT 942 (at 2017-05-10 08:48:08.182015-06)
(other test details: wal_level=logical; max_wal_senders=5; wal_sender_timeout = 3600s; max_locks_per_transaction = 65536; max_replication_slots = 5)
On Fri, May 5, 2017 at 7:38 PM, Andres Freund <andres@xxxxxxxxxxx> wrote:
On 2017-05-05 21:32:27 -0400, Tom Lane wrote:
> Andres Freund <andres@xxxxxxxxxxx> writes:
> > On 2017-05-05 14:24:07 -0600, Mathieu Fenniak wrote:
> >> It appears that most of the time is spent in the
> >> RelfilenodeMapInvalidateCallback and CatalogCacheIdInvalidate cache Err, sorry. Completely mangled that sentence. Executing fewer
> >> invalidation callbacks, both of which appear to be invalidating caches
> >> based upon the cache value.
>
> > I think optimizing those has some value (and I see Tom is looking at
> > that aspect, but the bigger thing would probably be to do fewer lookups.
>
> I'm confused --- the lookup side of things is down in the noise in
> Mathieu's trace.
invalidations. We currently are likely re-executing the same set of
invalidations constantly in Mathieu's case.
Background: When decoding a transaction during logical decoding we're
currently re-executing *all* a transaction's own cache invalidations, if
it has any, at every new command-id observed in the WAL stream. That's
because currently invalidations are only sent at commit, so we don't
know from "when" they are. But I think there's some very low-hanging
fruits reducing the frequency at which those are executed.
In many cases where there's just a few schema changes in a transaction,
this doesn't hurt badly. But if you have a transaction that does a
bootload of schema changes *and* a has a lot of other changes, it gets
expensive.
Mathieu: The above also indicates a possible workaround, you can try
separating larger amounts of data manipulations from schema changes,
into separate transactions.
Greetings,
Andres Freund
