logical decoding / rewrite map vs. maxAllocatedDescs

Hi,

While investigating an issue with rewrite maps in logical decoding, I
found it's pretty darn trivial to hit this:

ERROR: 53000: exceeded maxAllocatedDescs (492) while trying to open
file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b"

This happens because we seem to open the mapping files and keep them
open until the next checkpoint, at which point we fsync + close.

I suppose there are reasons why it's done this way, and admittedly the
test that happens to trigger this is a bit extreme (essentially running
pgbench concurrently with 'vacuum full pg_class' in a loop). I'm not
sure it's extreme enough to deem it not an issue, because people using
many temporary tables often deal with bloat by doing frequent vacuum
full on catalogs.

Furthermore, the situation is made worse by opening the same file
repeatedly, under different file descriptor.

I've added elog(LOG) to OpenTransientFile and CloseTransientFile - see
the attached file.log, which is filtered to a single process. The 'cnt'
field is showing numAllocatedDescs. There are 500 calls to
OpenTransientFile, but only 8 calls to CloseTransientFile (all of them
for pg_filenode.map).

But each of the mapping files is opened 9x, so we run out of file
descriptors 10x faster. Moreover, I'm pretty sure simply increasing the
file descriptor limit is not a solution - we'll simply end up opening
the files over and over until hitting it again.

But wait, there's more - what happens after hitting the limit? We
restart the decoding process, and end up getting this:

ERROR: 53000: exceeded maxAllocatedDescs (492) while trying to open
file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b"
LOCATION: OpenTransientFile, fd.c:2161
LOG: 00000: starting logical decoding for slot "s"
DETAIL: streaming transactions committing after 1/6097DD48, reading
WAL from 1/60275848
LOCATION: CreateDecodingContext, logical.c:414
LOG: 00000: logical decoding found consistent point at 1/60275848
DETAIL: Logical decoding will begin using saved snapshot.
LOCATION: SnapBuildRestore, snapbuild.c:1872
ERROR: XX000: subtransaction logged without previous top-level txn
record
LOCATION: ReorderBufferAssignChild, reorderbuffer.c:790
LOG: 00000: starting logical decoding for slot "s"
DETAIL: streaming transactions committing after 1/60988088, reading
WAL from 1/60275848
LOCATION: CreateDecodingContext, logical.c:414
LOG: 00000: logical decoding found consistent point at 1/60275848
DETAIL: Logical decoding will begin using saved snapshot.
LOCATION: SnapBuildRestore, snapbuild.c:1872
ERROR: XX000: subtransaction logged without previous top-level txn
record
LOCATION: ReorderBufferAssignChild, reorderbuffer.c:790

I'd say this implies the "can't open file" is handled in a way that
corrupts the mapping files, making it impossible to restart the
decoding. AFAICS the only option at this point is to drop the
subscription and start over.

I think the right solution here is (a) making sure we don't needlessly
open the same mapping file over and over, (b) closing the files sooner,
instead of waiting for the next checkpoint. I guess a small local cache
of file descriptors would do both things.

Not sure about the error handling. Even if we get rid of the file
descriptor limit issue, I guess there are other ways why this we can
fail here, so we probably need to improve that too.

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services