Re: Logical decoding CPU-bound w/ large number of tables

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(at)anarazel(dot)de> wrote:

> On 2017-05-05 21:32:27 -0400, Tom Lane wrote:
> > Andres Freund <andres(at)anarazel(dot)de> 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
> > >> 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.
>
> Err, sorry. Completely mangled that sentence. Executing fewer
> 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
>