public inbox for [email protected]help / color / mirror / Atom feed
[PATCH 3/4] Generation: keeper block 8+ messages / 3 participants [nested] [flat]
* [PATCH 3/4] Generation: keeper block @ 2021-07-31 00:54 Tomas Vondra <[email protected]> 0 siblings, 0 replies; 8+ messages in thread From: Tomas Vondra @ 2021-07-31 00:54 UTC (permalink / raw) --- src/backend/utils/mmgr/generation.c | 61 +++++++++++++++++++++++++---- 1 file changed, 54 insertions(+), 7 deletions(-) diff --git a/src/backend/utils/mmgr/generation.c b/src/backend/utils/mmgr/generation.c index 771a2525ca..6c90416e27 100644 --- a/src/backend/utils/mmgr/generation.c +++ b/src/backend/utils/mmgr/generation.c @@ -65,6 +65,7 @@ typedef struct GenerationContext Size nextBlockSize; /* next block size to allocate */ GenerationBlock *block; /* current (most recently allocated) block */ + GenerationBlock *keeper; /* keeper block */ dlist_head blocks; /* list of blocks */ } GenerationContext; @@ -254,6 +255,7 @@ GenerationContextCreate(MemoryContext parent, set->maxBlockSize = maxBlockSize; set->nextBlockSize = initBlockSize; set->block = NULL; + set->keeper = NULL; dlist_init(&set->blocks); /* Finally, do the type-independent part of context creation */ @@ -302,6 +304,7 @@ GenerationReset(MemoryContext context) } set->block = NULL; + set->keeper = NULL; /* Reset block size allocation sequence, too */ set->nextBlockSize = set->initBlockSize; @@ -344,7 +347,7 @@ GenerationAlloc(MemoryContext context, Size size) Size chunk_size = MAXALIGN(size); Size blockSize; - blockSize = (set->block) ? set->block->blksize : set->nextBlockSize; + blockSize = set->initBlockSize; /* is it an over-sized chunk? if yes, allocate special block */ if (chunk_size > (blockSize / 8)) @@ -400,6 +403,26 @@ GenerationAlloc(MemoryContext context, Size size) */ block = set->block; + /* + * If we can't use the current block, and we have a keeper block with + * enough free space in it, use it as the block. + * + * XXX We don't want to do this when there's not enough free space + * (although the keeper block should be empty, so not sure if checking + * the space in the keeper block is necessary). + */ + if (((block == NULL) || + (block->endptr - block->freeptr) < Generation_CHUNKHDRSZ + chunk_size) && + (set->keeper != NULL) && + (set->keeper->endptr - set->keeper->freeptr) < Generation_CHUNKHDRSZ + chunk_size) + { + block = set->keeper; + set->keeper = NULL; + + /* keeper block was not counted as allocated, so add it back */ + context->mem_allocated += block->blksize; + } + if ((block == NULL) || (block->endptr - block->freeptr) < Generation_CHUNKHDRSZ + chunk_size) { @@ -524,16 +547,34 @@ GenerationFree(MemoryContext context, void *pointer) if (block->nfree < block->nchunks) return; + /* Also make sure the block is not marked as the current block. */ + if (set->block == block) + set->block = NULL; + + /* Keep the block for reuse, if we don't have one already. */ + if (!set->keeper && block->blksize <= set->maxBlockSize) + { + /* reset the pointers before we use it as keeper block */ + block->freeptr = ((char *) block) + Generation_BLOCKHDRSZ; + block->endptr = ((char *) block) + block->blksize; + + block->nfree = 0; + block->nchunks = 0; + + set->keeper = block; + + /* keeper block is not counted as allocated */ + context->mem_allocated -= block->blksize; + + return; + } + /* * The block is empty, so let's get rid of it. First remove it from the * list of blocks, then return it to malloc(). */ dlist_delete(&block->node); - /* Also make sure the block is not marked as the current block. */ - if (set->block == block) - set->block = NULL; - context->mem_allocated -= block->blksize; free(block); } @@ -770,13 +811,19 @@ GenerationCheck(MemoryContext context) nchunks; char *ptr; - total_allocated += block->blksize; + /* + * The keeper block in the list of blocks, but we don't consider it + * as allocated in memory accounting. So don't include it in the sum. + */ + if (block != gen->keeper) + total_allocated += block->blksize; /* * nfree > nchunks is surely wrong, and we don't expect to see * equality either, because such a block should have gotten freed. */ - if (block->nfree >= block->nchunks) + if ((block->nfree > block->nchunks) && + ((block != gen->keeper) && (block->nfree == block->nchunks))) elog(WARNING, "problem in Generation %s: number of free chunks %d in block %p exceeds %d allocated", name, block->nfree, block, block->nchunks); -- 2.31.1 --------------D082F723AC01DF154D86FBFF Content-Type: text/x-patch; charset=UTF-8; name="0004-Generation-allocChunkLimit.patch" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="0004-Generation-allocChunkLimit.patch" ^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman @ 2022-04-07 17:52 Andres Freund <[email protected]> 0 siblings, 1 reply; 8+ messages in thread From: Andres Freund @ 2022-04-07 17:52 UTC (permalink / raw) To: Tom Lane <[email protected]>; +Cc: Michael Paquier <[email protected]>; [email protected] Hi, On 2022-04-07 13:40:30 -0400, Tom Lane wrote: > Michael Paquier <[email protected]> writes: > > Add TAP test for archive_cleanup_command and recovery_end_command > > grassquit just showed a non-reproducible failure in this test [1]: I was just staring at that as well. > # Postmaster PID for node "standby" is 291160 > ok 1 - check content from archives > not ok 2 - archive_cleanup_command executed on checkpoint > > # Failed test 'archive_cleanup_command executed on checkpoint' > # at t/002_archiving.pl line 74. > > This test is sending a CHECKPOINT command to the standby and > expecting it to run the archive_cleanup_command, but it looks > like the standby did not actually run any checkpoint: > > 2022-04-07 16:11:33.060 UTC [291806][not initialized][:0] LOG: connection received: host=[local] > 2022-04-07 16:11:33.078 UTC [291806][client backend][2/15:0] LOG: connection authorized: user=bf database=postgres application_name=002_archiving.pl > 2022-04-07 16:11:33.084 UTC [291806][client backend][2/16:0] LOG: statement: CHECKPOINT > 2022-04-07 16:11:33.092 UTC [291806][client backend][:0] LOG: disconnection: session time: 0:00:00.032 user=bf database=postgres host=[local] > > I am suspicious that the reason is that ProcessUtility does not > ask for a forced checkpoint when in recovery: > > RequestCheckpoint(CHECKPOINT_IMMEDIATE | CHECKPOINT_WAIT | > (RecoveryInProgress() ? 0 : CHECKPOINT_FORCE)); > > The trouble with this theory is that this test has been there for > nearly six months and this is the first such failure (I scraped the > buildfarm logs to be sure). Seems like failures should be a lot > more common than that. > I wondered if the recent pg_stats changes could have affected this, but I > don't really see how. I don't really see either. It's a bit more conceivable that the recovery prefetching changes could affect the timing sufficiently? It's also possible that it requires an animal of a certain speed to happen - we didn't have an -fsanitize=address animal until recently. I guess we'll have to wait and see what the frequency of the problem is? Greetings, Andres Freund ^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman @ 2022-04-07 17:57 Tom Lane <[email protected]> parent: Andres Freund <[email protected]> 0 siblings, 1 reply; 8+ messages in thread From: Tom Lane @ 2022-04-07 17:57 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: Michael Paquier <[email protected]>; [email protected] Andres Freund <[email protected]> writes: > On 2022-04-07 13:40:30 -0400, Tom Lane wrote: >> This test is sending a CHECKPOINT command to the standby and >> expecting it to run the archive_cleanup_command, but it looks >> like the standby did not actually run any checkpoint: >> ... >> I wondered if the recent pg_stats changes could have affected this, but I >> don't really see how. > I don't really see either. It's a bit more conceivable that the recovery > prefetching changes could affect the timing sufficiently? Oh, that's at least a little plausible. > I guess we'll have to wait and see what the frequency of the problem is? Yeah, with only one instance it could just be cosmic rays or something. However, assuming it is real, I guess I wonder why we don't say CHECKPOINT_FORCE in standby mode too. regards, tom lane ^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman @ 2022-04-07 18:12 Andres Freund <[email protected]> parent: Tom Lane <[email protected]> 0 siblings, 2 replies; 8+ messages in thread From: Andres Freund @ 2022-04-07 18:12 UTC (permalink / raw) To: Tom Lane <[email protected]>; +Cc: Michael Paquier <[email protected]>; [email protected] Hi, On 2022-04-07 13:57:45 -0400, Tom Lane wrote: > Yeah, with only one instance it could just be cosmic rays or something. > However, assuming it is real, I guess I wonder why we don't say > CHECKPOINT_FORCE in standby mode too. I guess it might partially be that restartpoints require a checkpoint to have happened on the primary. If we used FORCE, we'd have to wait till the next checkpoint on the primary, which'd be a problem if it's e.g. a manually issued CHECKPOINT; before shutting the standby down. Greetings, Andres Freund ^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman @ 2022-04-08 16:36 Tom Lane <[email protected]> parent: Andres Freund <[email protected]> 1 sibling, 0 replies; 8+ messages in thread From: Tom Lane @ 2022-04-08 16:36 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: Michael Paquier <[email protected]>; [email protected] Andres Freund <[email protected]> writes: > On 2022-04-07 13:57:45 -0400, Tom Lane wrote: >> Yeah, with only one instance it could just be cosmic rays or something. Not cosmic rays: skink has shown the same symptom three times running. Looks like maybe the archive_cleanup_command itself is doing something it shouldn't? regards, tom lane ^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman @ 2022-04-08 21:55 Tom Lane <[email protected]> parent: Andres Freund <[email protected]> 1 sibling, 2 replies; 8+ messages in thread From: Tom Lane @ 2022-04-08 21:55 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: Michael Paquier <[email protected]>; Thomas Munro <[email protected]>; [email protected] Andres Freund <[email protected]> writes: > On 2022-04-07 13:57:45 -0400, Tom Lane wrote: >> Yeah, with only one instance it could just be cosmic rays or something. >> However, assuming it is real, I guess I wonder why we don't say >> CHECKPOINT_FORCE in standby mode too. > I guess it might partially be that restartpoints require a checkpoint to have > happened on the primary. If we used FORCE, we'd have to wait till the next > checkpoint on the primary, which'd be a problem if it's e.g. a manually issued > CHECKPOINT; before shutting the standby down. After seeing skink's results, I tried running that test under valgrind here, and it fails just like that every time. skink's history allows us to bound the failure introduction between 79b716cfb7 and d7ab2a9a3c, which I think makes it just about certain that it was 5dc0418fab (Prefetch data referenced by the WAL, take II), though I've not bisected to be 100% sure. Adding some debug printouts to ExecuteRecoveryCommand convinces me that indeed the archive_cleanup_command is NOT getting called by the problematic CHECKPOINT command. I surmise based on Andres' comment above that the standby isn't making a restartpoint for lack of an available primary checkpoint, which looks to me like it could be a pre-existing bug in the test case: it's sure not doing anything to guarantee that the primary's checkpoint record has reached the standby. I tried adjusting the patch so it does guarantee that (as attached), and in two out of two tries it got past the archive_cleanup_command failure but then hung up waiting for standby2 to promote. On the whole, I'm not sure that the WAL prefetch logic is noticeably more stable than when we booted it out last year :-(. However, I also wonder why it is that this test case wasn't occasionally failing already. regards, tom lane Attachments: [text/x-diff] 002_archiving-hack.patch (890B, ../../[email protected]/2-002_archiving-hack.patch) download | inline diff: diff --git a/src/test/recovery/t/002_archiving.pl b/src/test/recovery/t/002_archiving.pl index c8f5ffbaf0..1032d8a388 100644 --- a/src/test/recovery/t/002_archiving.pl +++ b/src/test/recovery/t/002_archiving.pl @@ -44,13 +44,14 @@ $node_standby->start; # Create some content on primary $node_primary->safe_psql('postgres', "CREATE TABLE tab_int AS SELECT generate_series(1,1000) AS a"); -my $current_lsn = - $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();"); # Note the presence of this checkpoint for the archive_cleanup_command # check done below, before switching to a new segment. $node_primary->safe_psql('postgres', "CHECKPOINT"); +my $current_lsn = + $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();"); + # Force archiving of WAL file to make it present on primary $node_primary->safe_psql('postgres', "SELECT pg_switch_wal()"); ^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman @ 2022-04-08 23:56 Andres Freund <[email protected]> parent: Tom Lane <[email protected]> 1 sibling, 0 replies; 8+ messages in thread From: Andres Freund @ 2022-04-08 23:56 UTC (permalink / raw) To: Tom Lane <[email protected]>; +Cc: Michael Paquier <[email protected]>; Thomas Munro <[email protected]>; [email protected] Hi, On 2022-04-08 17:55:51 -0400, Tom Lane wrote: > After seeing skink's results, I tried running that test under valgrind > here, and it fails just like that every time. skink's history allows > us to bound the failure introduction between 79b716cfb7 and > d7ab2a9a3c, which I think makes it just about certain that it was > 5dc0418fab (Prefetch data referenced by the WAL, take II), though I've > not bisected to be 100% sure. I've tested it, it's 5dc0418fab that makes the difference. I reduced the cycle time by making initdb not go through valgrind, but have normal postgres instances go through it. > On the whole, I'm not sure that the WAL prefetch logic is noticeably > more stable than when we booted it out last year :-(. IDK. Last year's issues seems to have largely been caused by a flaky machine. And a bug, if it's that, in some archiving corner case that's not normally reached during tests... Greetings, Andres Freund ^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman @ 2022-04-09 00:59 Andres Freund <[email protected]> parent: Tom Lane <[email protected]> 1 sibling, 0 replies; 8+ messages in thread From: Andres Freund @ 2022-04-09 00:59 UTC (permalink / raw) To: Tom Lane <[email protected]>; +Cc: Michael Paquier <[email protected]>; Thomas Munro <[email protected]>; [email protected] Hi, On 2022-04-08 17:55:51 -0400, Tom Lane wrote: > I tried adjusting the patch so it does guarantee that (as attached), > and in two out of two tries it got past the archive_cleanup_command > failure but then hung up waiting for standby2 to promote. Adding $node_standby->safe_psql('postgres', "SELECT pg_switch_wal()"); just after $node_standby2->start; makes the tests pass here. What is that second test really testing? # Check the presence of temporary files specifically generated during # archive recovery. To ensure the presence of the temporary history # file, switch to a timeline large enough to allow a standby to recover # a history file from an archive. As this requires at least two timeline # switches, promote the existing standby first. Then create a second # standby based on the promoted one. Finally, the second standby is # promoted. Note "Then create a second standby based on the promoted one." - but that's not actually what's happening: $node_standby2->init_from_backup($node_primary, $backup_name, has_restoring => 1); It's created from the original primary, not the first standby, as the description says... Both nodes get promoted independently, in a run without valgrind: standby: 2022-04-08 17:23:42.966 PDT [2463835][startup][1/0:0][] LOG: INSERT @ 0/4000058: - XLOG/END_OF_RECOVERY: tli 2; prev tli 1; time 2022-04-08 17:23:42.96686-07 2022-04-08 17:23:42.966 PDT [2463835][startup][1/0:0][] LOG: xlog flush request 0/4000058; write 0/4000000; flush 0/4000000 standby2: 2022-04-08 17:23:43.307 PDT [2463999][startup][1/0:0][] LOG: INSERT @ 0/4000058: - XLOG/END_OF_RECOVERY: tli 3; prev tli 1; time 2022-04-08 17:23:43.307443-> 2022-04-08 17:23:43.307 PDT [2463999][startup][1/0:0][] LOG: xlog flush request 0/4000058; write 0/4000000; flush 0/4000000 except that standby2 can't choose tli 2 because it finds it used. Sure looks like something is funky with that test. But I think there's also something funky in the prefetching logic. I think it may attempt restoring during prefetching somehow, even though there's code that appears to try to prevent that? on standby2 I can see replay progress like the following: 2022-04-08 17:02:12.310 PDT [2441453][startup][1/0:0][] LOG: REDO @ 0/3024488; LSN 0/30244C8: prev 0/3024448; xid 725; len 3; blkref #0: rel 1663/5/16384, blk 4 - Heap/INSERT: off 60 flags 0x00 2022-04-08 17:02:12.311 PDT [2441453][startup][1/0:0][] DEBUG: record known xact 725 latestObservedXid 725 2022-04-08 17:02:12.311 PDT [2441453][startup][1/0:0][] CONTEXT: WAL redo at 0/3024488 for Heap/INSERT: off 60 flags 0x00; blkref #0: rel 1663/5/16384, blk 4 2022-04-08 17:02:12.312 PDT [2441453][startup][1/0:0][] DEBUG: executing restore command "cp "/home/andres/build/postgres/dev-assert/vpath/src/test/recovery/tmp_check/t_002_archiving_primary_data/archives/000000010000000000000004" "pg_wal/RECOVERYXLOG"" 2022-04-08 17:02:13.855 PDT [2441453][startup][1/0:0][] DEBUG: could not restore file "000000010000000000000004" from archive: child process exited with exit code 1 2022-04-08 17:02:13.855 PDT [2441453][startup][1/0:0][] DEBUG: could not open file "pg_wal/000000010000000000000004": No such file or directory 2022-04-08 17:02:13.856 PDT [2441453][startup][1/0:0][] LOG: REDO @ 0/30244C8; LSN 0/3024508: prev 0/3024488; xid 725; len 3; blkref #0: rel 1663/5/16384, blk 4 - Heap/INSERT: off 61 flags 0x00 2022-04-08 17:02:13.856 PDT [2441453][startup][1/0:0][] DEBUG: record known xact 725 latestObservedXid 725 2022-04-08 17:02:13.856 PDT [2441453][startup][1/0:0][] CONTEXT: WAL redo at 0/30244C8 for Heap/INSERT: off 61 flags 0x00; blkref #0: rel 1663/5/16384, blk 4 2022-04-08 17:02:13.857 PDT [2441453][startup][1/0:0][] DEBUG: executing restore command "cp "/home/andres/build/postgres/dev-assert/vpath/src/test/recovery/tmp_check/t_002_archiving_primary_data/archives/000000010000000000000004" "pg_wal/RECOVERYXLOG"" 2022-04-08 17:02:15.413 PDT [2441453][startup][1/0:0][] DEBUG: could not restore file "000000010000000000000004" from archive: child process exited with exit code 1 2022-04-08 17:02:15.413 PDT [2441453][startup][1/0:0][] DEBUG: could not open file "pg_wal/000000010000000000000004": No such file or directory 2022-04-08 17:02:15.414 PDT [2441453][startup][1/0:0][] LOG: REDO @ 0/3024508; LSN 0/3024548: prev 0/30244C8; xid 725; len 3; blkref #0: rel 1663/5/16384, blk 4 - Heap/INSERT: off 62 flags 0x00 2022-04-08 17:02:15.414 PDT [2441453][startup][1/0:0][] DEBUG: record known xact 725 latestObservedXid 725 2022-04-08 17:02:15.414 PDT [2441453][startup][1/0:0][] CONTEXT: WAL redo at 0/3024508 for Heap/INSERT: off 62 flags 0x00; blkref #0: rel 1663/5/16384, blk 4 2022-04-08 17:02:15.415 PDT [2441453][startup][1/0:0][] DEBUG: executing restore command "cp "/home/andres/build/postgres/dev-assert/vpath/src/test/recovery/tmp_check/t_002_archiving_primary_data/archives/000000010000000000000004" "pg_wal/RECOVERYXLOG"" note that we appear to wait between replaying of records, even though we apparently have WAL for the next record! And interestingly I'm not seeing the "switched WAL source from stream to archive after failure" lines I'd expect. Greetings, Andres Freund ^ permalink raw reply [nested|flat] 8+ messages in thread
end of thread, other threads:[~2022-04-09 00:59 UTC | newest] Thread overview: 8+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2021-07-31 00:54 [PATCH 3/4] Generation: keeper block Tomas Vondra <[email protected]> 2022-04-07 17:52 Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman Andres Freund <[email protected]> 2022-04-07 17:57 ` Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman Tom Lane <[email protected]> 2022-04-07 18:12 ` Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman Andres Freund <[email protected]> 2022-04-08 16:36 ` Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman Tom Lane <[email protected]> 2022-04-08 21:55 ` Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman Tom Lane <[email protected]> 2022-04-08 23:56 ` Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman Andres Freund <[email protected]> 2022-04-09 00:59 ` Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman Andres Freund <[email protected]>
This inbox is served by agora; see mirroring instructions for how to clone and mirror all data and code used for this inbox