logical decoding / rewrite map vs. maxAllocatedDescs - Mailing list pgsql-hackers

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