public inbox for [email protected]help / color / mirror / Atom feed
[PATCH v50 1/7] sequential scan for dshash 11+ messages / 4 participants [nested] [flat]
* [PATCH v50 1/7] sequential scan for dshash @ 2020-03-13 07:58 Kyotaro Horiguchi <[email protected]> 0 siblings, 0 replies; 11+ messages in thread From: Kyotaro Horiguchi @ 2020-03-13 07:58 UTC (permalink / raw) Dshash did not allow scan the all entries sequentially. This adds the functionality. The interface is similar but a bit different both from that of dynahash and simple dshash search functions. One of the most significant differences is the sequential scan interface of dshash always needs a call to dshash_seq_term when scan ends. Another is locking. Dshash holds partition lock when returning an entry, dshash_seq_next() also holds lock when returning an entry but callers shouldn't release it, since the lock is essential to continue a scan. The seqscan interface allows entry deletion while a scan. The in-scan deletion should be performed by dshash_delete_current(). --- src/backend/lib/dshash.c | 160 ++++++++++++++++++++++++++++++- src/include/lib/dshash.h | 22 +++++ src/tools/pgindent/typedefs.list | 1 + 3 files changed, 182 insertions(+), 1 deletion(-) diff --git a/src/backend/lib/dshash.c b/src/backend/lib/dshash.c index e0c763be32..520bfa0979 100644 --- a/src/backend/lib/dshash.c +++ b/src/backend/lib/dshash.c @@ -127,6 +127,10 @@ struct dshash_table #define NUM_SPLITS(size_log2) \ (size_log2 - DSHASH_NUM_PARTITIONS_LOG2) +/* How many buckets are there in a given size? */ +#define NUM_BUCKETS(size_log2) \ + (((size_t) 1) << (size_log2)) + /* How many buckets are there in each partition at a given size? */ #define BUCKETS_PER_PARTITION(size_log2) \ (((size_t) 1) << NUM_SPLITS(size_log2)) @@ -153,6 +157,10 @@ struct dshash_table #define BUCKET_INDEX_FOR_PARTITION(partition, size_log2) \ ((partition) << NUM_SPLITS(size_log2)) +/* Choose partition based on bucket index. */ +#define PARTITION_FOR_BUCKET_INDEX(bucket_idx, size_log2) \ + ((bucket_idx) >> NUM_SPLITS(size_log2)) + /* The head of the active bucket for a given hash value (lvalue). */ #define BUCKET_FOR_HASH(hash_table, hash) \ (hash_table->buckets[ \ @@ -324,7 +332,7 @@ dshash_destroy(dshash_table *hash_table) ensure_valid_bucket_pointers(hash_table); /* Free all the entries. */ - size = ((size_t) 1) << hash_table->size_log2; + size = NUM_BUCKETS(hash_table->size_log2); for (i = 0; i < size; ++i) { dsa_pointer item_pointer = hash_table->buckets[i]; @@ -592,6 +600,156 @@ dshash_memhash(const void *v, size_t size, void *arg) return tag_hash(v, size); } +/* + * dshash_seq_init/_next/_term + * Sequentially scan through dshash table and return all the + * elements one by one, return NULL when no more. + * + * dshash_seq_term should always be called when a scan finished. + * The caller may delete returned elements midst of a scan by using + * dshash_delete_current(). exclusive must be true to delete elements. + */ +void +dshash_seq_init(dshash_seq_status *status, dshash_table *hash_table, + bool exclusive) +{ + status->hash_table = hash_table; + status->curbucket = 0; + status->nbuckets = 0; + status->curitem = NULL; + status->pnextitem = InvalidDsaPointer; + status->curpartition = -1; + status->exclusive = exclusive; +} + +/* + * Returns the next element. + * + * Returned elements are locked and the caller must not explicitly release + * it. It is released at the next call to dshash_next(). + */ +void * +dshash_seq_next(dshash_seq_status *status) +{ + dsa_pointer next_item_pointer; + + if (status->curitem == NULL) + { + int partition; + + Assert(status->curbucket == 0); + Assert(!status->hash_table->find_locked); + + /* first shot. grab the first item. */ + partition = + PARTITION_FOR_BUCKET_INDEX(status->curbucket, + status->hash_table->size_log2); + LWLockAcquire(PARTITION_LOCK(status->hash_table, partition), + status->exclusive ? LW_EXCLUSIVE : LW_SHARED); + status->curpartition = partition; + + /* resize doesn't happen from now until seq scan ends */ + status->nbuckets = + NUM_BUCKETS(status->hash_table->control->size_log2); + ensure_valid_bucket_pointers(status->hash_table); + + next_item_pointer = status->hash_table->buckets[status->curbucket]; + } + else + next_item_pointer = status->pnextitem; + + Assert(LWLockHeldByMeInMode(PARTITION_LOCK(status->hash_table, + status->curpartition), + status->exclusive ? LW_EXCLUSIVE : LW_SHARED)); + + /* Move to the next bucket if we finished the current bucket */ + while (!DsaPointerIsValid(next_item_pointer)) + { + int next_partition; + + if (++status->curbucket >= status->nbuckets) + { + /* all buckets have been scanned. finish. */ + return NULL; + } + + /* Check if move to the next partition */ + next_partition = + PARTITION_FOR_BUCKET_INDEX(status->curbucket, + status->hash_table->size_log2); + + if (status->curpartition != next_partition) + { + /* + * Move to the next partition. Lock the next partition then release + * the current, not in the reverse order to avoid concurrent + * resizing. Avoid dead lock by taking lock in the same order + * with resize(). + */ + LWLockAcquire(PARTITION_LOCK(status->hash_table, + next_partition), + status->exclusive ? LW_EXCLUSIVE : LW_SHARED); + LWLockRelease(PARTITION_LOCK(status->hash_table, + status->curpartition)); + status->curpartition = next_partition; + } + + next_item_pointer = status->hash_table->buckets[status->curbucket]; + } + + status->curitem = + dsa_get_address(status->hash_table->area, next_item_pointer); + status->hash_table->find_locked = true; + status->hash_table->find_exclusively_locked = status->exclusive; + + /* + * The caller may delete the item. Store the next item in case of deletion. + */ + status->pnextitem = status->curitem->next; + + return ENTRY_FROM_ITEM(status->curitem); +} + +/* + * Terminates the seqscan and release all locks. + * + * Should be always called when finishing or exiting a seqscan. + */ +void +dshash_seq_term(dshash_seq_status *status) +{ + status->hash_table->find_locked = false; + status->hash_table->find_exclusively_locked = false; + + if (status->curpartition >= 0) + LWLockRelease(PARTITION_LOCK(status->hash_table, status->curpartition)); +} + +/* Remove the current entry while a seq scan. */ +void +dshash_delete_current(dshash_seq_status *status) +{ + dshash_table *hash_table = status->hash_table; + dshash_table_item *item = status->curitem; + size_t partition = PARTITION_FOR_HASH(item->hash); + + Assert(status->exclusive); + Assert(hash_table->control->magic == DSHASH_MAGIC); + Assert(hash_table->find_locked); + Assert(hash_table->find_exclusively_locked); + Assert(LWLockHeldByMeInMode(PARTITION_LOCK(hash_table, partition), + LW_EXCLUSIVE)); + + delete_item(hash_table, item); +} + +/* Get the current entry while a seq scan. */ +void * +dshash_get_current(dshash_seq_status *status) +{ + return ENTRY_FROM_ITEM(status->curitem); +} + /* * Print debugging information about the internal state of the hash table to * stderr. The caller must hold no partition locks. diff --git a/src/include/lib/dshash.h b/src/include/lib/dshash.h index c069ec9de7..a6ea377173 100644 --- a/src/include/lib/dshash.h +++ b/src/include/lib/dshash.h @@ -59,6 +59,21 @@ typedef struct dshash_parameters struct dshash_table_item; typedef struct dshash_table_item dshash_table_item; +/* + * Sequential scan state. The detail is exposed to let users know the storage + * size but it should be considered as an opaque type by callers. + */ +typedef struct dshash_seq_status +{ + dshash_table *hash_table; /* dshash table working on */ + int curbucket; /* bucket number we are at */ + int nbuckets; /* total number of buckets in the dshash */ + dshash_table_item *curitem; /* item we are currently at */ + dsa_pointer pnextitem; /* dsa-pointer to the next item */ + int curpartition; /* partition number we are at */ + bool exclusive; /* locking mode */ +} dshash_seq_status; + /* Creating, sharing and destroying from hash tables. */ extern dshash_table *dshash_create(dsa_area *area, const dshash_parameters *params, @@ -80,6 +95,13 @@ extern bool dshash_delete_key(dshash_table *hash_table, const void *key); extern void dshash_delete_entry(dshash_table *hash_table, void *entry); extern void dshash_release_lock(dshash_table *hash_table, void *entry); +/* seq scan support */ +extern void dshash_seq_init(dshash_seq_status *status, dshash_table *hash_table, + bool exclusive); +extern void *dshash_seq_next(dshash_seq_status *status); +extern void dshash_seq_term(dshash_seq_status *status); +extern void dshash_delete_current(dshash_seq_status *status); +extern void *dshash_get_current(dshash_seq_status *status); /* Convenience hash and compare functions wrapping memcmp and tag_hash. */ extern int dshash_memcmp(const void *a, const void *b, size_t size, void *arg); extern dshash_hash dshash_memhash(const void *v, size_t size, void *arg); diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index 8bd95aefa1..2b591e94e6 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -2954,6 +2954,7 @@ dshash_hash dshash_hash_function dshash_parameters dshash_partition +dshash_seq_status dshash_table dshash_table_control dshash_table_handle -- 2.27.0 ----Next_Part(Tue_Mar__9_18_29_34_2021_806)-- Content-Type: Text/X-Patch; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="v50-0002-Add-conditional-lock-feature-to-dshash.patch" ^ permalink raw reply [nested|flat] 11+ messages in thread
* pgsql: Add minimal tests for recovery conflict handling. @ 2022-04-07 21:54 Andres Freund <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Andres Freund @ 2022-04-07 21:54 UTC (permalink / raw) To: [email protected] Add minimal tests for recovery conflict handling. Previously none of our tests triggered recovery conflicts. The test is primarily motivated by needing tests for recovery conflict stats for shared memory based pgstats. But it's also a decent start for recovery conflict handling in general. The only type of recovery conflict not tested yet are rcovery deadlock conflicts. By configuring log_recovery_conflict_waits the test adds some very minimal testing for that path as well. Author: Melanie Plageman <[email protected]> Author: Andres Freund <[email protected]> Discussion: https://postgr.es/m/[email protected] Branch ------ master Details ------- https://git.postgresql.org/pg/commitdiff/9f8a050f68dcb38fb0a1ea87e0e5d04df32b56f4 Modified Files -------------- src/test/recovery/t/031_recovery_conflict.pl | 296 +++++++++++++++++++++++++++ 1 file changed, 296 insertions(+) ^ permalink raw reply [nested|flat] 11+ messages in thread
* Unstable tests for recovery conflict handling @ 2022-04-27 16:45 Tom Lane <[email protected]> parent: Andres Freund <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Tom Lane @ 2022-04-27 16:45 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: Melanie Plageman <[email protected]>; [email protected] [ starting a new thread cuz the shared-stats one is way too long ] Andres Freund <[email protected]> writes: > Add minimal tests for recovery conflict handling. It's been kind of hidden by other buildfarm noise, but 031_recovery_conflict.pl is not as stable as it should be [1][2][3][4]. Three of those failures look like [11:08:46.806](105.129s) ok 1 - buffer pin conflict: cursor with conflicting pin established Waiting for replication conn standby's replay_lsn to pass 0/33EF190 on primary [12:01:49.614](3182.807s) # poll_query_until timed out executing this query: # SELECT '0/33EF190' <= replay_lsn AND state = 'streaming' # FROM pg_catalog.pg_stat_replication # WHERE application_name IN ('standby', 'walreceiver') # expecting this output: # t # last actual query output: # f # with stderr: timed out waiting for catchup at t/031_recovery_conflict.pl line 123. In each of these examples we can see in the standby's log that it detected the expected buffer pin conflict: 2022-04-27 11:08:46.353 UTC [1961604][client backend][2/2:0] LOG: statement: BEGIN; 2022-04-27 11:08:46.416 UTC [1961604][client backend][2/2:0] LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1; 2022-04-27 11:08:46.730 UTC [1961604][client backend][2/2:0] LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2022-04-27 11:08:47.825 UTC [1961298][startup][1/0:0] LOG: recovery still waiting after 13.367 ms: recovery conflict on buffer pin 2022-04-27 11:08:47.825 UTC [1961298][startup][1/0:0] CONTEXT: WAL redo at 0/33E6E80 for Heap2/PRUNE: latestRemovedXid 0 nredirected 0 ndead 1; blkref #0: rel 1663/16385/16386, blk 0 but then nothing happens until the script times out and kills the test. I think this is showing us a real bug, ie we sometimes fail to cancel the conflicting query. The other example [3] looks different: [01:02:43.582](2.357s) ok 1 - buffer pin conflict: cursor with conflicting pin established Waiting for replication conn standby's replay_lsn to pass 0/342C000 on primary done [01:02:43.747](0.165s) ok 2 - buffer pin conflict: logfile contains terminated connection due to recovery conflict [01:02:43.804](0.057s) not ok 3 - buffer pin conflict: stats show conflict on standby [01:02:43.805](0.000s) [01:02:43.805](0.000s) # Failed test 'buffer pin conflict: stats show conflict on standby' # at t/031_recovery_conflict.pl line 295. [01:02:43.805](0.000s) # got: '0' # expected: '1' Not sure what to make of that --- could there be a race condition in the reporting of the conflict? regards, tom lane [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2022-04-27%2007%3A16%3A51 [2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=peripatus&dt=2022-04-21%2021%3A20%3A15 [3] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=morepork&dt=2022-04-13%2022%3A45%3A30 [4] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2022-04-11%2005%3A40%3A41 ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Unstable tests for recovery conflict handling @ 2022-04-27 18:08 Tom Lane <[email protected]> parent: Tom Lane <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Tom Lane @ 2022-04-27 18:08 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: Thomas Munro <[email protected]>; Melanie Plageman <[email protected]>; [email protected] I wrote: > It's been kind of hidden by other buildfarm noise, but > 031_recovery_conflict.pl is not as stable as it should be [1][2][3][4]. > ... > I think this is showing us a real bug, ie we sometimes fail to cancel > the conflicting query. After digging around in the code, I think this is almost certainly some manifestation of the previously-complained-of problem [1] that RecoveryConflictInterrupt is not safe to call in a signal handler, leading the conflicting backend to sometimes decide that it's not the problem. That squares with the observation that skink is more prone to show this than other animals: you'd have to get the SIGUSR1 while the target backend isn't idle, so a very slow machine ought to show it more. We don't seem to have that issue on the open items list, but I'll go add it. Not sure if the 'buffer pin conflict: stats show conflict on standby' failure could trace to a similar cause. regards, tom lane [1] https://www.postgresql.org/message-id/flat/CA%2BhUKGK3PGKwcKqzoosamn36YW-fsuTdOPPF1i_rtEO%3DnEYKSg%4... ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Unstable tests for recovery conflict handling @ 2022-07-26 17:57 Tom Lane <[email protected]> parent: Tom Lane <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Tom Lane @ 2022-07-26 17:57 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: Thomas Munro <[email protected]>; Melanie Plageman <[email protected]>; [email protected] I wrote: >> It's been kind of hidden by other buildfarm noise, but >> 031_recovery_conflict.pl is not as stable as it should be [1][2][3][4]. > After digging around in the code, I think this is almost certainly > some manifestation of the previously-complained-of problem [1] that > RecoveryConflictInterrupt is not safe to call in a signal handler, > leading the conflicting backend to sometimes decide that it's not > the problem. I happened to notice that while skink continues to fail off-and-on in 031_recovery_conflict.pl, the symptoms have changed! What we're getting now typically looks like [1]: [10:45:11.475](0.023s) ok 14 - startup deadlock: lock acquisition is waiting Waiting for replication conn standby's replay_lsn to pass 0/33FB8B0 on primary done timed out waiting for match: (?^:User transaction caused buffer deadlock with recovery.) at t/031_recovery_conflict.pl line 367. where absolutely nothing happens in the standby log, until we time out: 2022-07-24 10:45:11.452 UTC [1468367][client backend][2/4:0] LOG: statement: SELECT * FROM test_recovery_conflict_table2; 2022-07-24 10:45:11.472 UTC [1468547][client backend][3/2:0] LOG: statement: SELECT 'waiting' FROM pg_locks WHERE locktype = 'relation' AND NOT granted; 2022-07-24 10:48:15.860 UTC [1468362][walreceiver][:0] FATAL: could not receive data from WAL stream: server closed the connection unexpectedly So this is not a case of RecoveryConflictInterrupt doing the wrong thing: the startup process hasn't detected the buffer conflict in the first place. Don't know what to make of that, but I vaguely suspect a test timing problem. gull has shown this once as well, although at a different step in the script [2]. regards, tom lane [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2022-07-24%2007%3A00%3A29 [2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=gull&dt=2022-07-23%2009%3A34%3A54 ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Unstable tests for recovery conflict handling @ 2022-07-26 18:16 Andres Freund <[email protected]> parent: Tom Lane <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Andres Freund @ 2022-07-26 18:16 UTC (permalink / raw) To: Tom Lane <[email protected]>; +Cc: Thomas Munro <[email protected]>; Melanie Plageman <[email protected]>; [email protected] Hi, On 2022-07-26 13:57:53 -0400, Tom Lane wrote: > I happened to notice that while skink continues to fail off-and-on > in 031_recovery_conflict.pl, the symptoms have changed! What > we're getting now typically looks like [1]: > > [10:45:11.475](0.023s) ok 14 - startup deadlock: lock acquisition is waiting > Waiting for replication conn standby's replay_lsn to pass 0/33FB8B0 on primary > done > timed out waiting for match: (?^:User transaction caused buffer deadlock with recovery.) at t/031_recovery_conflict.pl line 367. > > where absolutely nothing happens in the standby log, until we time out: > > 2022-07-24 10:45:11.452 UTC [1468367][client backend][2/4:0] LOG: statement: SELECT * FROM test_recovery_conflict_table2; > 2022-07-24 10:45:11.472 UTC [1468547][client backend][3/2:0] LOG: statement: SELECT 'waiting' FROM pg_locks WHERE locktype = 'relation' AND NOT granted; > 2022-07-24 10:48:15.860 UTC [1468362][walreceiver][:0] FATAL: could not receive data from WAL stream: server closed the connection unexpectedly > > So this is not a case of RecoveryConflictInterrupt doing the wrong thing: > the startup process hasn't detected the buffer conflict in the first > place. I wonder if this, at least partially, could be be due to the elog thing I was complaining about nearby. I.e. we decide to FATAL as part of a recovery conflict interrupt, and then during that ERROR out as part of another recovery conflict interrupt (because nothing holds interrupts as part of FATAL). Greetings, Andres Freund ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Unstable tests for recovery conflict handling @ 2022-07-26 18:30 Tom Lane <[email protected]> parent: Andres Freund <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Tom Lane @ 2022-07-26 18:30 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: Thomas Munro <[email protected]>; Melanie Plageman <[email protected]>; [email protected] Andres Freund <[email protected]> writes: > On 2022-07-26 13:57:53 -0400, Tom Lane wrote: >> So this is not a case of RecoveryConflictInterrupt doing the wrong thing: >> the startup process hasn't detected the buffer conflict in the first >> place. > I wonder if this, at least partially, could be be due to the elog thing > I was complaining about nearby. I.e. we decide to FATAL as part of a > recovery conflict interrupt, and then during that ERROR out as part of > another recovery conflict interrupt (because nothing holds interrupts as > part of FATAL). There are all sorts of things one could imagine going wrong in the backend receiving the recovery conflict interrupt, but AFAICS in these failures, the startup process hasn't sent a recovery conflict interrupt. It certainly hasn't logged anything suggesting it noticed a conflict. regards, tom lane ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Unstable tests for recovery conflict handling @ 2022-07-26 20:03 Andres Freund <[email protected]> parent: Tom Lane <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Andres Freund @ 2022-07-26 20:03 UTC (permalink / raw) To: Tom Lane <[email protected]>; +Cc: Thomas Munro <[email protected]>; Melanie Plageman <[email protected]>; [email protected] Hi, On 2022-07-26 14:30:30 -0400, Tom Lane wrote: > Andres Freund <[email protected]> writes: > > On 2022-07-26 13:57:53 -0400, Tom Lane wrote: > >> So this is not a case of RecoveryConflictInterrupt doing the wrong thing: > >> the startup process hasn't detected the buffer conflict in the first > >> place. > > > I wonder if this, at least partially, could be be due to the elog thing > > I was complaining about nearby. I.e. we decide to FATAL as part of a > > recovery conflict interrupt, and then during that ERROR out as part of > > another recovery conflict interrupt (because nothing holds interrupts as > > part of FATAL). > > There are all sorts of things one could imagine going wrong in the > backend receiving the recovery conflict interrupt, but AFAICS in these > failures, the startup process hasn't sent a recovery conflict interrupt. > It certainly hasn't logged anything suggesting it noticed a conflict. I don't think we reliably emit a log message before the recovery conflict is resolved. I've wondered a couple times now about making tap test timeouts somehow trigger a core dump of all processes. Certainly would make it easier to debug some of these kinds of issues. Greetings, Andres Freund ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Unstable tests for recovery conflict handling @ 2022-08-03 17:57 Andres Freund <[email protected]> parent: Andres Freund <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Andres Freund @ 2022-08-03 17:57 UTC (permalink / raw) To: Tom Lane <[email protected]>; +Cc: Thomas Munro <[email protected]>; Melanie Plageman <[email protected]>; [email protected] Hi, On 2022-07-26 13:03:54 -0700, Andres Freund wrote: > On 2022-07-26 14:30:30 -0400, Tom Lane wrote: > > Andres Freund <[email protected]> writes: > > > On 2022-07-26 13:57:53 -0400, Tom Lane wrote: > > >> So this is not a case of RecoveryConflictInterrupt doing the wrong thing: > > >> the startup process hasn't detected the buffer conflict in the first > > >> place. > > > > > I wonder if this, at least partially, could be be due to the elog thing > > > I was complaining about nearby. I.e. we decide to FATAL as part of a > > > recovery conflict interrupt, and then during that ERROR out as part of > > > another recovery conflict interrupt (because nothing holds interrupts as > > > part of FATAL). > > > > There are all sorts of things one could imagine going wrong in the > > backend receiving the recovery conflict interrupt, but AFAICS in these > > failures, the startup process hasn't sent a recovery conflict interrupt. > > It certainly hasn't logged anything suggesting it noticed a conflict. > > I don't think we reliably emit a log message before the recovery > conflict is resolved. I played around trying to reproduce this kind of issue. One way to quickly run into trouble on a slow system is that ResolveRecoveryConflictWithVirtualXIDs() can end up sending signals more frequently than the target can process them. The next signal can arrive by the time SIGUSR1 processing finished, which, at least on linux, causes the queued signal to immediately be processed, without "normal" postgres code gaining control. The reason nothing might get logged in some cases is that e.g. ResolveRecoveryConflictWithLock() tells ResolveRecoveryConflictWithVirtualXIDs() to *not* report the waiting: /* * Prevent ResolveRecoveryConflictWithVirtualXIDs() from reporting * "waiting" in PS display by disabling its argument report_waiting * because the caller, WaitOnLock(), has already reported that. */ so ResolveRecoveryConflictWithLock() can end up looping indefinitely without logging anything. Another question I have about ResolveRecoveryConflictWithLock() is whether it's ok that we don't check deadlocks around the ResolveRecoveryConflictWithVirtualXIDs() call? It might be ok, because we'd only block if there's a recovery conflict, in which killing the process ought to succeed? I think there's also might be a problem with the wait loop in ProcSleep() wrt recovery conflicts: We rely on interrupts to be processed to throw recovery conflict errors, but ProcSleep() is called in a bunch of places with interrupts held. An Assert(INTERRUPTS_CAN_BE_PROCESSED()) after releasing the partition lock triggers a bunch. It's possible that these aren't problematic cases for recovery conflicts, because they're all around extension locks: #2 0x0000562032f1968d in ExceptionalCondition (conditionName=0x56203310623a "INTERRUPTS_CAN_BE_PROCESSED()", errorType=0x562033105f6c "FailedAssertion", fileName=0x562033105f30 "/home/andres/src/postgresql/src/backend/storage/lmgr/proc.c", lineNumber=1208) at /home/andres/src/postgresql/src/backend/utils/error/assert.c:69 #3 0x0000562032d50f41 in ProcSleep (locallock=0x562034cafaf0, lockMethodTable=0x562033281740 <default_lockmethod>) at /home/andres/src/postgresql/src/backend/storage/lmgr/proc.c:1208 #4 0x0000562032d3e2ce in WaitOnLock (locallock=0x562034cafaf0, owner=0x562034d12c58) at /home/andres/src/postgresql/src/backend/storage/lmgr/lock.c:1859 #5 0x0000562032d3cd0a in LockAcquireExtended (locktag=0x7ffc7b4d0810, lockmode=7, sessionLock=false, dontWait=false, reportMemoryError=true, locallockp=0x0) at /home/andres/src/postgresql/src/backend/storage/lmgr/lock.c:1101 #6 0x0000562032d3c1c4 in LockAcquire (locktag=0x7ffc7b4d0810, lockmode=7, sessionLock=false, dontWait=false) at /home/andres/src/postgresql/src/backend/storage/lmgr/lock.c:752 #7 0x0000562032d3a696 in LockRelationForExtension (relation=0x7f54646b1dd8, lockmode=7) at /home/andres/src/postgresql/src/backend/storage/lmgr/lmgr.c:439 #8 0x0000562032894276 in _bt_getbuf (rel=0x7f54646b1dd8, blkno=4294967295, access=2) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtpage.c:975 #9 0x000056203288f1cb in _bt_split (rel=0x7f54646b1dd8, itup_key=0x562034ea7428, buf=770, cbuf=0, newitemoff=408, newitemsz=16, newitem=0x562034ea3fc8, orignewitem=0x0, nposting=0x0, postingoff=0) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtinsert.c:1715 #10 0x000056203288e4bb in _bt_insertonpg (rel=0x7f54646b1dd8, itup_key=0x562034ea7428, buf=770, cbuf=0, stack=0x562034ea1fb8, itup=0x562034ea3fc8, itemsz=16, newitemoff=408, postingoff=0, split_only_page=false) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtinsert.c:1212 #11 0x000056203288caf9 in _bt_doinsert (rel=0x7f54646b1dd8, itup=0x562034ea3fc8, checkUnique=UNIQUE_CHECK_YES, indexUnchanged=false, heapRel=0x7f546823dde0) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtinsert.c:258 #12 0x000056203289851f in btinsert (rel=0x7f54646b1dd8, values=0x7ffc7b4d0c50, isnull=0x7ffc7b4d0c30, ht_ctid=0x562034dd083c, heapRel=0x7f546823dde0, checkUnique=UNIQUE_CHECK_YES, indexUnchanged=false, indexInfo=0x562034ea71c0) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtree.c:200 #13 0x000056203288710b in index_insert (indexRelation=0x7f54646b1dd8, values=0x7ffc7b4d0c50, isnull=0x7ffc7b4d0c30, heap_t_ctid=0x562034dd083c, heapRelation=0x7f546823dde0, checkUnique=UNIQUE_CHECK_YES, indexUnchanged=false, indexInfo=0x562034ea71c0) at /home/andres/src/postgresql/src/backend/access/index/indexam.c:193 #14 0x000056203292e9da in CatalogIndexInsert (indstate=0x562034dd02b0, heapTuple=0x562034dd0838) (gdb) p num_held_lwlocks $14 = 1 (gdb) p held_lwlocks[0] $15 = {lock = 0x7f1a0d18d2e4, mode = LW_EXCLUSIVE} (gdb) p held_lwlocks[0].lock->tranche $16 = 56 (gdb) p BuiltinTrancheNames[held_lwlocks[0].lock->tranche - NUM_INDIVIDUAL_LWLOCKS] $17 = 0x558ce5710ede "BufferContent" Independent of recovery conflicts, isn't it dangerous that we acquire the relation extension lock with a buffer content lock held? I *guess* it might be ok because BufferAlloc(P_NEW) only acquires buffer content locks in a conditional way. Greetings, Andres Freund ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Unstable tests for recovery conflict handling @ 2022-08-03 20:33 Robert Haas <[email protected]> parent: Andres Freund <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Robert Haas @ 2022-08-03 20:33 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: Tom Lane <[email protected]>; Thomas Munro <[email protected]>; Melanie Plageman <[email protected]>; PostgreSQL Hackers <[email protected]> On Wed, Aug 3, 2022 at 1:57 PM Andres Freund <[email protected]> wrote: > The reason nothing might get logged in some cases is that > e.g. ResolveRecoveryConflictWithLock() tells > ResolveRecoveryConflictWithVirtualXIDs() to *not* report the waiting: > /* > * Prevent ResolveRecoveryConflictWithVirtualXIDs() from reporting > * "waiting" in PS display by disabling its argument report_waiting > * because the caller, WaitOnLock(), has already reported that. > */ > > so ResolveRecoveryConflictWithLock() can end up looping indefinitely without > logging anything. I understand why we need to avoid adding "waiting" to the PS status when we've already done that, but it doesn't seem like that should imply skipping ereport() of log messages. I think we could redesign the way the ps display works to make things a whole lot simpler. Let's have a function set_ps_display() and another function set_ps_display_suffix(). What gets reported to the OS is the concatenation of the two. Calling set_ps_display() implicitly resets the suffix to empty. AFAICS, that'd let us get rid of this tricky logic, and some other tricky logic as well. Here, we'd just say set_ps_display_suffix(" waiting") and not worry about whether the caller might have already done something similar. > Another question I have about ResolveRecoveryConflictWithLock() is whether > it's ok that we don't check deadlocks around the > ResolveRecoveryConflictWithVirtualXIDs() call? It might be ok, because we'd > only block if there's a recovery conflict, in which killing the process ought > to succeed? The startup process is supposed to always "win" in any deadlock situation, so I'm not sure what you think is a problem here. We get the conflicting lockers. We kill them. If they don't die, that's a bug, but killing ourselves doesn't really help anything; if we die, the whole system goes down, which seems undesirable. > I think there's also might be a problem with the wait loop in ProcSleep() wrt > recovery conflicts: We rely on interrupts to be processed to throw recovery > conflict errors, but ProcSleep() is called in a bunch of places with > interrupts held. An Assert(INTERRUPTS_CAN_BE_PROCESSED()) after releasing the > partition lock triggers a bunch. It's possible that these aren't problematic > cases for recovery conflicts, because they're all around extension locks: > [...] > Independent of recovery conflicts, isn't it dangerous that we acquire the > relation extension lock with a buffer content lock held? I *guess* it might be > ok because BufferAlloc(P_NEW) only acquires buffer content locks in a > conditional way. These things both seem a bit sketchy but it's not 100% clear to me that anything is actually broken. Now it's also not clear to me that nothing is broken ... -- Robert Haas EDB: http://www.enterprisedb.com ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Unstable tests for recovery conflict handling @ 2022-08-03 22:07 Andres Freund <[email protected]> parent: Robert Haas <[email protected]> 0 siblings, 0 replies; 11+ messages in thread From: Andres Freund @ 2022-08-03 22:07 UTC (permalink / raw) To: Robert Haas <[email protected]>; +Cc: Tom Lane <[email protected]>; Thomas Munro <[email protected]>; Melanie Plageman <[email protected]>; PostgreSQL Hackers <[email protected]> Hi, On 2022-08-03 16:33:46 -0400, Robert Haas wrote: > On Wed, Aug 3, 2022 at 1:57 PM Andres Freund <[email protected]> wrote: > > The reason nothing might get logged in some cases is that > > e.g. ResolveRecoveryConflictWithLock() tells > > ResolveRecoveryConflictWithVirtualXIDs() to *not* report the waiting: > > /* > > * Prevent ResolveRecoveryConflictWithVirtualXIDs() from reporting > > * "waiting" in PS display by disabling its argument report_waiting > > * because the caller, WaitOnLock(), has already reported that. > > */ > > > > so ResolveRecoveryConflictWithLock() can end up looping indefinitely without > > logging anything. > > I understand why we need to avoid adding "waiting" to the PS status > when we've already done that, but it doesn't seem like that should > imply skipping ereport() of log messages. > > I think we could redesign the way the ps display works to make things > a whole lot simpler. Let's have a function set_ps_display() and > another function set_ps_display_suffix(). What gets reported to the OS > is the concatenation of the two. Calling set_ps_display() implicitly > resets the suffix to empty. > > AFAICS, that'd let us get rid of this tricky logic, and some other > tricky logic as well. Here, we'd just say set_ps_display_suffix(" > waiting") and not worry about whether the caller might have already > done something similar. That sounds like it'd be an improvement. Of course we still need to fix that we can signal at a rate not allowing the other side to handle the conflict, but at least that'd be easier to identify... > > Another question I have about ResolveRecoveryConflictWithLock() is whether > > it's ok that we don't check deadlocks around the > > ResolveRecoveryConflictWithVirtualXIDs() call? It might be ok, because we'd > > only block if there's a recovery conflict, in which killing the process ought > > to succeed? > > The startup process is supposed to always "win" in any deadlock > situation, so I'm not sure what you think is a problem here. We get > the conflicting lockers. We kill them. If they don't die, that's a > bug, but killing ourselves doesn't really help anything; if we die, > the whole system goes down, which seems undesirable. The way deadlock timeout for the startup process works is that we wait for it to pass and then send PROCSIG_RECOVERY_CONFLICT_STARTUP_DEADLOCK to the backends. So it's not that the startup process would die. The question is basically whether there are cases were PROCSIG_RECOVERY_CONFLICT_STARTUP_DEADLOCK would resolve a conflict but PROCSIG_RECOVERY_CONFLICT_LOCK wouldn't. It seems plausible that there isn't, but it's also not obvious enough that I'd fully trust it. Greetings, Andres Freund ^ permalink raw reply [nested|flat] 11+ messages in thread
end of thread, other threads:[~2022-08-03 22:07 UTC | newest] Thread overview: 11+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2020-03-13 07:58 [PATCH v50 1/7] sequential scan for dshash Kyotaro Horiguchi <[email protected]> 2022-04-07 21:54 pgsql: Add minimal tests for recovery conflict handling. Andres Freund <[email protected]> 2022-04-27 16:45 ` Unstable tests for recovery conflict handling Tom Lane <[email protected]> 2022-04-27 18:08 ` Re: Unstable tests for recovery conflict handling Tom Lane <[email protected]> 2022-07-26 17:57 ` Re: Unstable tests for recovery conflict handling Tom Lane <[email protected]> 2022-07-26 18:16 ` Re: Unstable tests for recovery conflict handling Andres Freund <[email protected]> 2022-07-26 18:30 ` Re: Unstable tests for recovery conflict handling Tom Lane <[email protected]> 2022-07-26 20:03 ` Re: Unstable tests for recovery conflict handling Andres Freund <[email protected]> 2022-08-03 17:57 ` Re: Unstable tests for recovery conflict handling Andres Freund <[email protected]> 2022-08-03 20:33 ` Re: Unstable tests for recovery conflict handling Robert Haas <[email protected]> 2022-08-03 22:07 ` Re: Unstable tests for recovery conflict handling 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