public inbox for [email protected]help / color / mirror / Atom feed
Commit with wait event on advisory lock! 14+ messages / 5 participants [nested] [flat]
* Commit with wait event on advisory lock! @ 2025-01-21 14:48 [email protected] 0 siblings, 2 replies; 14+ messages in thread From: [email protected] @ 2025-01-21 14:48 UTC (permalink / raw) To: [email protected] Hi all, I have long commits on a production database. To know why this happens I organized a snapshot system on table pg_stat_activity. When I check the result I have this row in it: postgres=# select * from public.fdj_ms_slow_stmts where pid = 2285947 \gx -[ RECORD 1 ]----+---------------------------------------------------------------------- ------------------------------------------------- datname | some_db pid | 2285947 leader_pid | usename | some_user application_name | PostgreSQL JDBC Driver backend_start | 2025-01-21 04:25:17.254477+01 xact_start | 2025-01-21 05:55:19.426945+01 query_start | 2025-01-21 05:55:19.428651+01 stmt_duration | 00:00:02.140691 tx_idle_duration | 00:00:00 ts_now | 2025-01-21 05:55:21.569342+01 state | active wait_event_type | Lock wait_event | advisory query_id | query | COMMIT . Is this possible ? I am really surprised ! Michel SALAIS ^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: Commit with wait event on advisory lock! @ 2025-01-21 14:56 Rajesh Kumar <[email protected]> parent: [email protected] 1 sibling, 1 reply; 14+ messages in thread From: Rajesh Kumar @ 2025-01-21 14:56 UTC (permalink / raw) To: [email protected]; +Cc: [email protected] Advisory locks are used by developers On Tue, 21 Jan 2025, 20:18 , <[email protected]> wrote: > Hi all, > > > > I have long commits on a production database. To know why this happens I > organized a snapshot system on table pg_stat_activity. > > When I check the result I have this row in it: > > > > postgres=# select * from public.fdj_ms_slow_stmts where pid = 2285947 \gx > > -[ RECORD 1 > ]----+----------------------------------------------------------------------------------------------------------------------- > > datname | some_db > > pid | 2285947 > > leader_pid | > > usename | some_user > > application_name | PostgreSQL JDBC Driver > > backend_start | 2025-01-21 04:25:17.254477+01 > > xact_start | 2025-01-21 05:55:19.426945+01 > > query_start | 2025-01-21 05:55:19.428651+01 > > stmt_duration | 00:00:02.140691 > > tx_idle_duration | 00:00:00 > > ts_now | 2025-01-21 05:55:21.569342+01 > > state | active > > wait_event_type | *Lock* > > wait_event | *advisory* > > query_id | > > query | *COMMIT* > > … > > > > Is this possible ? > > I am really surprised ! > > > > *Michel SALAIS* > ^ permalink raw reply [nested|flat] 14+ messages in thread
* RE: Commit with wait event on advisory lock! @ 2025-01-22 00:22 [email protected] parent: Rajesh Kumar <[email protected]> 0 siblings, 1 reply; 14+ messages in thread From: [email protected] @ 2025-01-22 00:22 UTC (permalink / raw) To: 'Rajesh Kumar' <[email protected]>; +Cc: [email protected] Hi I know very well advisory locks. The question is: How a COMMIT statement could be blocked by a lock whatever the kind of the lock could be. COMMIT releases locks. How could it be blocked by a lock?! Regards Michel SALAIS De : Rajesh Kumar <[email protected]> Envoyé : mardi 21 janvier 2025 15:57 À : [email protected] Cc : [email protected] Objet : Re: Commit with wait event on advisory lock! Advisory locks are used by developers On Tue, 21 Jan 2025, 20:18 , <[email protected] <mailto:[email protected]> > wrote: Hi all, I have long commits on a production database. To know why this happens I organized a snapshot system on table pg_stat_activity. When I check the result I have this row in it: postgres=# select * from public.fdj_ms_slow_stmts where pid = 2285947 \gx -[ RECORD 1 ]----+----------------------------------------------------------------------------------------------------------------------- datname | some_db pid | 2285947 leader_pid | usename | some_user application_name | PostgreSQL JDBC Driver backend_start | 2025-01-21 04:25:17.254477+01 xact_start | 2025-01-21 05:55:19.426945+01 query_start | 2025-01-21 05:55:19.428651+01 stmt_duration | 00:00:02.140691 tx_idle_duration | 00:00:00 ts_now | 2025-01-21 05:55:21.569342+01 state | active wait_event_type | Lock wait_event | advisory query_id | query | COMMIT … Is this possible ? I am really surprised ! Michel SALAIS ^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: Commit with wait event on advisory lock! @ 2025-01-22 00:48 Tom Lane <[email protected]> parent: [email protected] 0 siblings, 1 reply; 14+ messages in thread From: Tom Lane @ 2025-01-22 00:48 UTC (permalink / raw) To: [email protected]; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] <[email protected]> writes: > How a COMMIT statement could be blocked by a lock whatever the kind of the lock could be. COMMIT releases locks. How could it be blocked by a lock?! There could be pre-commit actions (for example, firing deferred triggers) that need to take locks the transaction didn't already hold. You've provided no details that would let anyone diagnose the exact cause, though. regards, tom lane ^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: Commit with wait event on advisory lock! @ 2025-01-22 03:15 Jeff Janes <[email protected]> parent: [email protected] 1 sibling, 0 replies; 14+ messages in thread From: Jeff Janes @ 2025-01-22 03:15 UTC (permalink / raw) To: [email protected]; +Cc: [email protected] On Tue, Jan 21, 2025 at 9:48 AM <[email protected]> wrote: > Hi all, > > > > I have long commits on a production database. To know why this happens I > organized a snapshot system on table pg_stat_activity. > > When I check the result I have this row in it: > > > > postgres=# select * from public.fdj_ms_slow_stmts where pid = 2285947 \gx > What is the full version()? What is the query used to populate this snapshot table? Are the advisory locks being used as session-level locks or transaction-level locks? Cheers, Jeff ^ permalink raw reply [nested|flat] 14+ messages in thread
* RE: Commit with wait event on advisory lock! @ 2025-01-22 17:19 [email protected] parent: Tom Lane <[email protected]> 0 siblings, 1 reply; 14+ messages in thread From: [email protected] @ 2025-01-22 17:19 UTC (permalink / raw) To: 'Tom Lane' <[email protected]>; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] Hi Tom, Sorry, - It is PG 14.4 - Replication is used (2 standby, one sync and the other potential) but no application connection to replica. - No deferrable constraints: some_db=# select count(*) from pg_constraint where condeferrable ; count ------- 0 (1 row) - No triggers: some_db=# select count(*) from pg_trigger ; count ------- 0 (1 row) I only capture statements executed within database some_db. And finally, this is how I take snaps (this is launched by crontab every hour). I also tried to capture 'idle in transaction' ... do $$ declare debut timestamptz := current_timestamp; begin set synchronous_commit = local; -- I don't care about replication for my table <<main>> loop insert into public.ms_slow_stmts(datname, pid, leader_pid, usename, application_name, backend_start, xact_start, query_start, stmt_duration, tx_idle_duration, ts_now, state, wait_event_type, wait_event, query_id, query) select datname, pid, leader_pid, usename, application_name, backend_start, xact_start, query_start, case when state = 'idle in transaction' then state_change - query_start else clock_timestamp - query_start end stmt_duration, case when state = 'idle in transaction' then clock_timestamp - state_change else interval '0s' end tx_idle_duration, clock_timestamp ts_now, state, wait_event_type, wait_event, query_id, query from pg_stat_activity where backend_type = 'client backend' and datname = 'some_db' and state != 'idle' and ( case when state = 'idle in transaction' then state_change - query_start -- last query execution time if in 'idle in transaction' state else clock_timestamp - query_start -- time from query start for current query end >= interval'2s' or case when state = 'idle in transaction' then clock_timestamp - state_change else interval'0s' end >= interval'1s' -- in state 'idle in transaction' for more than 1 s ); commit; exit when clock_timestamp - debut >= interval'00:59:55'; perform pg_sleep(1); end loop main; end; $$; Best regards --- Michel SALAIS -----Message d'origine----- De : Tom Lane <[email protected]> Envoyé : mercredi 22 janvier 2025 01:49 À : [email protected] Cc : 'Rajesh Kumar' <[email protected]>; [email protected] Objet : Re: Commit with wait event on advisory lock! <[email protected]> writes: > How a COMMIT statement could be blocked by a lock whatever the kind of the lock could be. COMMIT releases locks. How could it be blocked by a lock?! There could be pre-commit actions (for example, firing deferred triggers) that need to take locks the transaction didn't already hold. You've provided no details that would let anyone diagnose the exact cause, though. regards, tom lane ^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: Commit with wait event on advisory lock! @ 2025-01-22 17:24 Tom Lane <[email protected]> parent: [email protected] 0 siblings, 1 reply; 14+ messages in thread From: Tom Lane @ 2025-01-22 17:24 UTC (permalink / raw) To: [email protected]; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] <[email protected]> writes: > - Replication is used (2 standby, one sync and the other potential) but no > application connection to replica. Maybe you have synchronous_commit set to enforce waiting for the standby to receive/apply the transaction? If so I'd look for possible delays there. regards, tom lane ^ permalink raw reply [nested|flat] 14+ messages in thread
* RE: Commit with wait event on advisory lock! @ 2025-01-22 22:00 [email protected] parent: Tom Lane <[email protected]> 0 siblings, 1 reply; 14+ messages in thread From: [email protected] @ 2025-01-22 22:00 UTC (permalink / raw) To: 'Tom Lane' <[email protected]>; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] Hello Tom I do have delays sometimes because of synchronous_commit (We use actually the default value and synchronous_standby_names is not empty). I have sometimes commit execution time more than 10 sec but the problem is more general than commit/synchronization. But my concern here is really to understand in which situations, a COMMIT statement can wait on a lock especially that I have no triggers, and no deferrable constraints... What could it be? This can point something to look about... By the way I also have commits which are waiting on ClientRead... -- Michel SALAIS -----Message d'origine----- De : Tom Lane <[email protected]> Envoyé : mercredi 22 janvier 2025 18:24 À : [email protected] Cc : 'Rajesh Kumar' <[email protected]>; [email protected] Objet : Re: Commit with wait event on advisory lock! <[email protected]> writes: > - Replication is used (2 standby, one sync and the other potential) > but no application connection to replica. Maybe you have synchronous_commit set to enforce waiting for the standby to receive/apply the transaction? If so I'd look for possible delays there. regards, tom lane ^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: Commit with wait event on advisory lock! @ 2025-01-22 22:17 Tom Lane <[email protected]> parent: [email protected] 0 siblings, 2 replies; 14+ messages in thread From: Tom Lane @ 2025-01-22 22:17 UTC (permalink / raw) To: [email protected]; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] <[email protected]> writes: > But my concern here is really to understand in which situations, a COMMIT > statement can wait on a lock especially that I have no triggers, and no > deferrable constraints... The core code does nothing with advisory locks. If COMMIT is blocking on one of those, it must be a consequence of user-defined code that is running at pre-commit time. You've given us nothing to go on about what that could be. > By the way I also have commits which are waiting on ClientRead... That, on the other hand, is surely impossible. I think maybe you are misreading the stats display. Typically I'd expect that such a case indicates that the session is idle (awaiting a new command) and the COMMIT is the last thing it did before that. regards, tom lane ^ permalink raw reply [nested|flat] 14+ messages in thread
* RE: Commit with wait event on advisory lock! @ 2025-01-23 18:35 [email protected] parent: Tom Lane <[email protected]> 1 sibling, 1 reply; 14+ messages in thread From: [email protected] @ 2025-01-23 18:35 UTC (permalink / raw) To: 'Tom Lane' <[email protected]>; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] Hello, The session is marked ***active***. It is not in idle state and the query is 'commit' and the event is ***ClientRead***! There is no doubt... This one and the wait on advisory lock by a commit statement let me think about Oracle saying that it doesn't guarantee consistence for dynamic tables data, and it could be the same thing here for pg_stat_activity. Could it be? It could depend on protocol and when exactly this dynamic table is updated... Best regards --- Michel SALAIS -----Message d'origine----- De : Tom Lane <[email protected]> Envoyé : mercredi 22 janvier 2025 23:18 À : [email protected] Cc : 'Rajesh Kumar' <[email protected]>; [email protected] Objet : Re: Commit with wait event on advisory lock! <[email protected]> writes: > But my concern here is really to understand in which situations, a > COMMIT statement can wait on a lock especially that I have no > triggers, and no deferrable constraints... The core code does nothing with advisory locks. If COMMIT is blocking on one of those, it must be a consequence of user-defined code that is running at pre-commit time. You've given us nothing to go on about what that could be. > By the way I also have commits which are waiting on ClientRead... That, on the other hand, is surely impossible. I think maybe you are misreading the stats display. Typically I'd expect that such a case indicates that the session is idle (awaiting a new command) and the COMMIT is the last thing it did before that. regards, tom lane ^ permalink raw reply [nested|flat] 14+ messages in thread
* RE: Commit with wait event on advisory lock! @ 2025-01-24 08:55 [email protected] parent: [email protected] 0 siblings, 0 replies; 14+ messages in thread From: [email protected] @ 2025-01-24 08:55 UTC (permalink / raw) To: [email protected] Hi, Just an example of my result today: <code> postgres=# select pid, xact_start, query_start, ts_now, stmt_duration, state, wait_event_type, wait_event, query from public.ms_slow_stmts where query ilike 'commit' and wait_event_type in ('Client', 'Lock'); pid | xact_start | query_start | ts_now | stmt_duration | state | wait_event_type | wait_event | query ---------+-------------------------------+-------------------------------+-- -----------------------------+-----------------+--------+-----------------+- -----------+-------- 529392 | 2025-01-21 05:55:19.427214+01 | 2025-01-21 05:55:19.429889+01 | 2025-01-21 05:55:21.569339+01 | 00:00:02.13945 | active | Client | ClientRead | COMMIT 2285947 | 2025-01-21 05:55:19.426945+01 | 2025-01-21 05:55:19.428651+01 | 2025-01-21 05:55:21.569342+01 | 00:00:02.140691 | active | Lock | advisory | COMMIT 4106658 | 2025-01-22 13:04:29.551289+01 | 2025-01-22 13:04:29.726165+01 | 2025-01-22 13:04:33.191303+01 | 00:00:03.465138 | active | Client | ClientRead | COMMIT 4106652 | 2025-01-22 13:04:30.068406+01 | 2025-01-22 13:04:30.073688+01 | 2025-01-22 13:04:33.191322+01 | 00:00:03.117634 | active | Client | ClientRead | COMMIT 4106625 | 2025-01-22 13:04:30.064757+01 | 2025-01-22 13:04:30.070484+01 | 2025-01-22 13:04:33.191402+01 | 00:00:03.120918 | active | Client | ClientRead | COMMIT 119472 | 2025-01-22 19:19:43.156342+01 | 2025-01-22 19:19:43.159275+01 | 2025-01-22 19:19:45.208617+01 | 00:00:02.049342 | active | Client | ClientRead | COMMIT </code> Michel SALAIS -----Message d'origine----- De : [email protected] <[email protected]> Envoyé : jeudi 23 janvier 2025 19:36 À : 'Tom Lane' <[email protected]> Cc : 'Rajesh Kumar' <[email protected]>; [email protected] Objet : RE: Commit with wait event on advisory lock! Hello, The session is marked ***active***. It is not in idle state and the query is 'commit' and the event is ***ClientRead***! There is no doubt... This one and the wait on advisory lock by a commit statement let me think about Oracle saying that it doesn't guarantee consistence for dynamic tables data, and it could be the same thing here for pg_stat_activity. Could it be? It could depend on protocol and when exactly this dynamic table is updated... Best regards --- Michel SALAIS -----Message d'origine----- De : Tom Lane <[email protected]> Envoyé : mercredi 22 janvier 2025 23:18 À : [email protected] Cc : 'Rajesh Kumar' <[email protected]>; [email protected] Objet : Re: Commit with wait event on advisory lock! <[email protected]> writes: > But my concern here is really to understand in which situations, a > COMMIT statement can wait on a lock especially that I have no > triggers, and no deferrable constraints... The core code does nothing with advisory locks. If COMMIT is blocking on one of those, it must be a consequence of user-defined code that is running at pre-commit time. You've given us nothing to go on about what that could be. > By the way I also have commits which are waiting on ClientRead... That, on the other hand, is surely impossible. I think maybe you are misreading the stats display. Typically I'd expect that such a case indicates that the session is idle (awaiting a new command) and the COMMIT is the last thing it did before that. regards, tom lane ^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: Commit with wait event on advisory lock! @ 2025-02-04 15:22 Benoit Lobréau <[email protected]> parent: Tom Lane <[email protected]> 1 sibling, 2 replies; 14+ messages in thread From: Benoit Lobréau @ 2025-02-04 15:22 UTC (permalink / raw) To: Tom Lane <[email protected]>; [email protected]; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] On 1/22/25 11:17 PM, Tom Lane wrote: >> By the way I also have commits which are waiting on ClientRead... > > That, on the other hand, is surely impossible. I think maybe you > are misreading the stats display. Typically I'd expect that such a > case indicates that the session is idle (awaiting a new command) > and the COMMIT is the last thing it did before that. > > regards, tom lane I can reproduce the issue using pgbench spamming "BEGIN; COMMIT;" and and running this query in psql: SELECT DISTINCT state, wait_event, query FROM pg_stat_activity WHERE backend_type ILIKE '%client%' AND query ILIKE 'COMMIT%' \watch 0.5 After a short while I get the following : active | ClientRead | COMMIT; I looked into src/backend/utils/adt/pgstatfuncs.c and found that the state comes from the PgBackendStatus array, while the wait events are fetched from the proc array (using st_procpid taken from the backend status). I don't think there is a guarantee that this "snapshot" is consistent across both arrays. It might just be a case of spamming pg_stat_activity and occasionally ending up with an "inconsistent snapshot." Do you think this explanation holds weight? I haven't been able to reproduce the advisory lock issue yet. -- Benoit Lobréau Consultant http://dalibo.com ^ permalink raw reply [nested|flat] 14+ messages in thread
* Re: Commit with wait event on advisory lock! @ 2025-02-27 16:00 Benoit Lobréau <[email protected]> parent: Benoit Lobréau <[email protected]> 1 sibling, 0 replies; 14+ messages in thread From: Benoit Lobréau @ 2025-02-27 16:00 UTC (permalink / raw) To: Tom Lane <[email protected]>; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] On 2/4/25 4:22 PM, Benoit Lobréau wrote: > On 1/22/25 11:17 PM, Tom Lane wrote: >>> By the way I also have commits which are waiting on ClientRead... >> >> That, on the other hand, is surely impossible. I think maybe you >> are misreading the stats display. Typically I'd expect that such a >> case indicates that the session is idle (awaiting a new command) >> and the COMMIT is the last thing it did before that. >> >> regards, tom lane > > I can reproduce the issue using pgbench spamming "BEGIN; COMMIT;" and > and running this query in psql: > > SELECT DISTINCT state, wait_event, query > FROM pg_stat_activity > WHERE backend_type ILIKE '%client%' > AND query ILIKE 'COMMIT%' > \watch 0.5 > > After a short while I get the following : > > active | ClientRead | COMMIT; > > I looked into src/backend/utils/adt/pgstatfuncs.c and found that > the state comes from the PgBackendStatus array, while the wait > events are fetched from the proc array (using st_procpid taken > from the backend status). > > I don't think there is a guarantee that this "snapshot" is > consistent across both arrays. It might just be a case of spamming > pg_stat_activity and occasionally ending up with an "inconsistent > snapshot." > > Do you think this explanation holds weight? > > I haven't been able to reproduce the advisory lock issue yet. > Hi, is this explanation for the active transaction with the ClientRead wait event plausible? Thanks! I appreciate any insights you can share. -- Benoit Lobréau Consultant http://dalibo.com ^ permalink raw reply [nested|flat] 14+ messages in thread
* RE: Commit with wait event on advisory lock! @ 2025-03-19 14:51 [email protected] parent: Benoit Lobréau <[email protected]> 1 sibling, 0 replies; 14+ messages in thread From: [email protected] @ 2025-03-19 14:51 UTC (permalink / raw) To: 'Benoit Lobréau' <[email protected]>; 'Tom Lane' <[email protected]>; +Cc: 'Rajesh Kumar' <[email protected]>; [email protected] Hi Benoit, My reply comes very late but I think your explanation is a very good one. And it is some how what I suggested when I compared to Oracle. After all, content of dynamic tables in Oracle come from different arrays in memory... Best regards Michel SALAIS -----Message d'origine----- De : Benoit Lobréau <[email protected]> Envoyé : mardi 4 février 2025 16:23 À : Tom Lane <[email protected]>; [email protected] Cc : 'Rajesh Kumar' <[email protected]>; [email protected] Objet : Re: Commit with wait event on advisory lock! On 1/22/25 11:17 PM, Tom Lane wrote: >> By the way I also have commits which are waiting on ClientRead... > > That, on the other hand, is surely impossible. I think maybe you are > misreading the stats display. Typically I'd expect that such a case > indicates that the session is idle (awaiting a new command) and the > COMMIT is the last thing it did before that. > > regards, tom lane I can reproduce the issue using pgbench spamming "BEGIN; COMMIT;" and and running this query in psql: SELECT DISTINCT state, wait_event, query FROM pg_stat_activity WHERE backend_type ILIKE '%client%' AND query ILIKE 'COMMIT%' \watch 0.5 After a short while I get the following : active | ClientRead | COMMIT; I looked into src/backend/utils/adt/pgstatfuncs.c and found that the state comes from the PgBackendStatus array, while the wait events are fetched from the proc array (using st_procpid taken from the backend status). I don't think there is a guarantee that this "snapshot" is consistent across both arrays. It might just be a case of spamming pg_stat_activity and occasionally ending up with an "inconsistent snapshot." Do you think this explanation holds weight? I haven't been able to reproduce the advisory lock issue yet. -- Benoit Lobréau Consultant http://dalibo.com ^ permalink raw reply [nested|flat] 14+ messages in thread
end of thread, other threads:[~2025-03-19 14:51 UTC | newest] Thread overview: 14+ messages (download: mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2025-01-21 14:48 Commit with wait event on advisory lock! [email protected] 2025-01-21 14:56 ` Rajesh Kumar <[email protected]> 2025-01-22 00:22 ` [email protected] 2025-01-22 00:48 ` Tom Lane <[email protected]> 2025-01-22 17:19 ` [email protected] 2025-01-22 17:24 ` Tom Lane <[email protected]> 2025-01-22 22:00 ` [email protected] 2025-01-22 22:17 ` Tom Lane <[email protected]> 2025-01-23 18:35 ` [email protected] 2025-01-24 08:55 ` [email protected] 2025-02-04 15:22 ` Benoit Lobréau <[email protected]> 2025-02-27 16:00 ` Benoit Lobréau <[email protected]> 2025-03-19 14:51 ` [email protected] 2025-01-22 03:15 ` Jeff Janes <[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