logical decoding / rewrite map vs. maxAllocatedDescs
От | Tomas Vondra |
---|---|
Тема | logical decoding / rewrite map vs. maxAllocatedDescs |
Дата | |
Msg-id | 738a590a-2ce5-9394-2bef-7b1caad89b37@2ndquadrant.com обсуждение исходный текст |
Ответы |
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Re: logical decoding / rewrite map vs. maxAllocatedDescs |
Список | 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
Вложения
В списке pgsql-hackers по дате отправления: