Re: Unable to start replica after failover
Hi Igor, On Fri, 26 Aug 2022 at 13:43, Lahnov, Igor wrote: > I can't answer your question. What do you think, the recovery from the > archive should work in this case? > > 1. the partial file should not be restored at all cases > > 2. the partial file should recover as a partial and replace the local > partial > > 3. recovery command, should return a conflict - file already exists > The partial file should never be restored automatically. I have no clue why pg_probackup developers decided to do it. Postgres never requests the partial file using the restore_command, instead, it requests a file from the next timeline. Regards, -- Alexander Kukushkin
Missing query plan for auto_explain.
Our Postgres recently started reporting considerably different execution times for the same query. When executed from our JDBC application the Postgres logs report an average execution time of 1500 ms but when the query is manually executed through `psql` it doesn't take longer than 50 ms. With a view to investigate discrepancies in the plan we enabled `auto_explain` in `session_preload_libraries` with `auto_explain.log_min_duration = '1s'`. All application servers were bounced to ensure new connections were created and picked up the changes. However this trouble query does not have an explain plan printed, even when its execution time exceeds the threshold (other queries do though). Does anyone have ideas of why the explain plan is not being printed? Sample log entry for trouble query executed from application: ``` Aug 26 09:11:33 db-931 postgres[8106]: [66-1] 2022-08-26 09:11:33 GMT [8106]: [5-1] db=betwave,user=betwave_app_readonly_user LOG: duration: 1423.481 ms bind : /*@ org.sixty6.as66.QueryID:report.framework.userSearch */select users.user_id, users.unique_identifier, user_profile.name, user_profile.email, organisation.organisation_id, organisation.description, user_realm.user_realm_id, user_realm.description as col_8, user_realm.type, user_realm_category.description as col_10, vip_schema.description as col_11, vip_level.description as col_12, affiliate.description as col_13, users.status, users.creation_date, user_statistics.last_user_session_creation_date, users.real_base_currency, users.fun_base_currency, local_balance_account.balance Aug 26 09:11:33 db-931 postgres[8106]: [66-2] #011from users users Aug 26 09:11:33 db-931 postgres[8106]: [66-3] #011join user_profile user_profile Aug 26 09:11:33 db-931 postgres[8106]: [66-4] #011on user_profile.user_id = users.user_id Aug 26 09:11:33 db-931 postgres[8106]: [66-5] #011join user_realm user_realm Aug 26 09:11:33 db-931 postgres[8106]: [66-6] #011on user_realm.user_realm_id = users.user_realm_id Aug 26 09:11:33 db-931 postgres[8106]: [66-7] #011join organisation organisation Aug 26 09:11:33 db-931 postgres[8106]: [66-8] #011on organisation.organisation_id = user_realm.organisation_id Aug 26 09:11:33 db-931 postgres[8106]: [66-9] #011join acl_allowed_organisation acl_allowed_organisation Aug 26 09:11:33 db-931 postgres[8106]: [66-10] #011on acl_allowed_organisation.organisation_id = organisation.organisation_id and acl_allowed_organisation.permission = $1 and acl_allowed_organisation.user_id = $2 Aug 26 09:11:33 db-931 postgres[8106]: [66-11] #011join affiliate affiliate Aug 26 09:11:33 db-931 postgres[8106]: [66-12] #011on affiliate.affiliate_id = users.affiliate_id Aug 26 09:11:33 db-931 postgres[8106]: [66-13] #011join acl_allowed_affiliate acl_allowed_affiliate Aug 26 09:11:33 db-931 postgres[8106]: [66-14] #011on acl_allowed_affiliate.affiliate_id = affiliate.affiliate_id and acl_allowed_affiliate.permission = $3 and acl_allowed_affiliate.user_id = $4 Aug 26 09:11:33 db-931 postgres[8106]: [66-15] #011join acl_allowed_user_realm_category acl_allowed_user_realm_category Aug 26 09:11:33 db-931 postgres[8106]: [66-16] #011on acl_allowed_user_realm_category.user_realm_category_id = user_realm.user_realm_category_id and acl_allowed_user_realm_category.permission = $5 and acl_allowed_user_realm_category.user_id = $6 Aug 26 09:11:33 db-931 postgres[8106]: [66-17] #011join user_statistics user_statistics Aug 26 09:11:33 db-931 postgres[8106]: [66-18] #011on user_statistics.user_id = users.user_id Aug 26 09:11:33 db-931 postgres[8106]: [66-19] #011join vip_level vip_level Aug 26 09:11:33 db-931 postgres[8106]: [66-20] #011on vip_level.vip_level_id = users.vip_level_id Aug 26 09:11:33 db-931 postgres[8106]: [66-21] #011join vip_schema vip_schema Aug 26 09:11:33 db-931 postgres[8106]: [66-22] #011on vip_schema.vip_schema_id = vip_level.vip_schema_id Aug 26 09:11:33 db-931 postgres[8106]: [66-23] #011join user_realm_category user_realm_category Aug 26 09:11:33 db-931 postgres[8106]: [66-24] #011on user_realm_category.user_realm_category_id = user_realm.user_realm_category_id Aug 26 09:11:33 db-931 postgres[8106]: [66-25] #011left join local_balance_account local_balance_account Aug 26 09:11:33 db-931 postgres[8106]: [66-26] #011on local_balance_account.user_id = users.user_id and local_balance_account.currency = users.real_base_currency and local_balance_account.balance_category = $7 and local_balance_account.primary_balance = $8 Aug 26 09:11:33 db-931 postgres[8106]: [66-27] #011where users.type in ($9, $10) and user_realm.type in ($11, $12, $13) and users.unique_identifier like $14 escape '\' Aug 26 09:11:33 db-931 postgres[8106]: [66-28] #011order by users.unique_identifier asc, user_realm.user_realm_id asc Aug 26 09:11:33 db-931 postgres[8106]: [66-29] #011limit $15 Aug 26 09:11:33 db-931 postgres[8106]: [66-30] 2022-08-26 09:11:33 GMT [8106]: [6-1] db=betwave,user=betwave_app_readonly_user DETAIL: parameters: $1 = 'READ', $2 = '1468137', $3 = 'READ
Re: Missing query plan for auto_explain.
On 2022-Aug-30, Matheus Martin wrote: > Our Postgres recently started reporting considerably different > execution times for the same query. When executed from our JDBC > application the Postgres logs report an average execution time of 1500 > ms but when the query is manually executed through `psql` it doesn't > take longer than 50 ms. I don't know why the plan is not saved by auto_explain (maybe we're missing ExecutorEnd calls somewhere? that would be strange), but one frequent reason for queries to show different plan in JDBC than psql is the use of prepared statements. Did you try using "PREPARE yourquery(...)" and then EXPLAIN EXECUTE(...)? Sometimes that helps to recreate the original problem. (Apparently, ExecutorEnd is called from PortalCleanup; what happens with the portal for an extended-protocol query?) -- Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/
Re: Missing query plan for auto_explain.
Hi, On Tue, Aug 30, 2022 at 01:16:43PM +0200, Alvaro Herrera wrote: > On 2022-Aug-30, Matheus Martin wrote: > > > Our Postgres recently started reporting considerably different > > execution times for the same query. When executed from our JDBC > > application the Postgres logs report an average execution time of 1500 > > ms but when the query is manually executed through `psql` it doesn't > > take longer than 50 ms. > > I don't know why the plan is not saved by auto_explain (maybe we're > missing ExecutorEnd calls somewhere? that would be strange), but one > frequent reason for queries to show different plan in JDBC than psql is > the use of prepared statements. Did you try using "PREPARE > yourquery(...)" and then EXPLAIN EXECUTE(...)? Sometimes that helps to > recreate the original problem. > > (Apparently, ExecutorEnd is called from PortalCleanup; what happens with > the portal for an extended-protocol query?) AFAICS log_min_duration_statements threshold is based on the full query processing time while auto_explain is only based on the executor runtime, so one more likely explanation is that out of the 1423ms, more than 423ms were spent in the planner?
Re: Missing query plan for auto_explain.
Good idea on using an actual prepared statement but unfortunately it didn't produce any different result. Could you please elaborate a bit on your advice concerning ExecutorEnd/PortalCleanup? I am afraid it doesn't mean much to me. On Tue, 30 Aug 2022 at 12:16, Alvaro Herrera wrote: > On 2022-Aug-30, Matheus Martin wrote: > > > Our Postgres recently started reporting considerably different > > execution times for the same query. When executed from our JDBC > > application the Postgres logs report an average execution time of 1500 > > ms but when the query is manually executed through `psql` it doesn't > > take longer than 50 ms. > > I don't know why the plan is not saved by auto_explain (maybe we're > missing ExecutorEnd calls somewhere? that would be strange), but one > frequent reason for queries to show different plan in JDBC than psql is > the use of prepared statements. Did you try using "PREPARE > yourquery(...)" and then EXPLAIN EXECUTE(...)? Sometimes that helps to > recreate the original problem. > > > (Apparently, ExecutorEnd is called from PortalCleanup; what happens with > the portal for an extended-protocol query?) > > -- > Álvaro Herrera PostgreSQL Developer — > https://www.EnterpriseDB.com/ >
Re: Missing query plan for auto_explain.
The threshold for `auto_explain` was changed to 500 ms and explain plans are still not being logged. On Tue, 30 Aug 2022 at 13:30, Julien Rouhaud wrote: > Hi, > > On Tue, Aug 30, 2022 at 01:16:43PM +0200, Alvaro Herrera wrote: > > On 2022-Aug-30, Matheus Martin wrote: > > > > > Our Postgres recently started reporting considerably different > > > execution times for the same query. When executed from our JDBC > > > application the Postgres logs report an average execution time of 1500 > > > ms but when the query is manually executed through `psql` it doesn't > > > take longer than 50 ms. > > > > I don't know why the plan is not saved by auto_explain (maybe we're > > missing ExecutorEnd calls somewhere? that would be strange), but one > > frequent reason for queries to show different plan in JDBC than psql is > > the use of prepared statements. Did you try using "PREPARE > > yourquery(...)" and then EXPLAIN EXECUTE(...)? Sometimes that helps to > > recreate the original problem. > > > > (Apparently, ExecutorEnd is called from PortalCleanup; what happens with > > the portal for an extended-protocol query?) > > AFAICS log_min_duration_statements threshold is based on the full query > processing time while auto_explain is only based on the executor runtime, > so > one more likely explanation is that out of the 1423ms, more than 423ms were > spent in the planner? >
Re: Missing query plan for auto_explain.
On 2022-Aug-30, Matheus Martin wrote: > Good idea on using an actual prepared statement but unfortunately it didn't > produce any different result. I should have also mentioned to try the EXPLAIN EXECUTE six times and see if the last one produces a different plan. That's when it switches from planning every time to planning with generic arguments, as I recall. > Could you please elaborate a bit on your advice concerning > ExecutorEnd/PortalCleanup? I am afraid it doesn't mean much to me. That wasn't advice actually, just a note that the code might be doing that thing wrong, causing auto_explain to miss it. This is an unproven hypothesis that is likely to be all wrong. -- Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/ "I'm impressed how quickly you are fixing this obscure issue. I came from MS SQL and it would be hard for me to put into words how much of a better job you all are doing on [PostgreSQL]." Steve Midgley, http://archives.postgresql.org/pgsql-sql/2008-08/msg0.php
RE: Unable to archive logs in standby server
Hi Guillaume/team,
I set archive_mode = always in master and standby.
Archival to standby WAL directory completed when
* standby server was restarted
* pg_stop_backup was executed in master
But archival hangs when pg_stop_backup is executed in standby.
Could someone help to get this working?
postgres=# select pg_start_backup('test', true, false);
pg_start_backup
-
1/F960
(1 row)
postgres=# select pg_stop_backup('f');
NOTICE: base backup done, waiting for required WAL segments to be archived
WARNING: still waiting for all required WAL segments to be archived (60
seconds elapsed)
HINT: Check that your archive_command is executing properly. You can safely
cancel this backup, but the database backup will not be usable without all the
WAL segments.
WARNING: still waiting for all required WAL segments to be archived (120
seconds elapsed)
HINT: Check that your archive_command is executing properly. You can safely
cancel this backup, but the database backup will not be usable without all the
WAL segments.
……..
postgres=# select pg_is_in_recovery();
pg_is_in_recovery
---
t
(1 row)
postgres=# show wal_level;
wal_level
---
replica
(1 row)
postgres=# show archive_mode;
archive_mode
--
always
(1 row)
postgres=# select version();
version
-
PostgreSQL 12.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623
(Red Hat 4.8.5-39), 64-bit
(1 row)
Regards,
Meera
From: Guillaume Lelarge
Sent: Thursday, July 21, 2022 6:01 PM
To: Meera Nair
Cc: pgsql-general@lists.postgresql.org
Subject: Re: Unable to archive logs in standby server
External email. Inspect before opening.
Hi,
Le jeu. 21 juil. 2022 à 13:58, Meera Nair
mailto:mn...@commvault.com>> a écrit :
Hi team,
With non-exclusive backup method, trying backup from standby node.
But pg_stop_backup function returns “WAL archiving is not enabled…” and the
logs are not archived to WAL directory configured.
Please check if I am missing anything in configuring this properly,
Server was restarted after setting the archiving params in postgresql.conf
Below is from version 14:
postgres=# select pg_start_backup('label', false, false);
pg_start_backup
-
0/6D8
(1 row)
postgres=# select pg_stop_backup('false');
NOTICE: WAL archiving is not enabled; you must ensure that all required WAL
segments are copied through other means to complete the backup
pg_stop_backup
---
(0/60001C0,"START WAL LOCATION: 0/6D8 (file 00010006)+
CHECKPOINT LOCATION: 0/6000110 +
BACKUP METHOD: streamed +
BACKUP FROM: standby +
START TIME: 2022-07-21 12:42:11 IST +
LABEL: label +
START TIMELINE: 1+
","")
(1 row)
postgres=# select pg_is_in_recovery();
pg_is_in_recovery
---
t
(1 row)
postgres=# show wal_level;
wal_level
---
replica
(1 row)
postgres=# show archive_mode;
archive_mode
--
on
(1 row)
You're doing backups from the standby, and to allow archiving on the backups,
archive_mode should be set to always.
--
Guillaume.
Re: Missing query plan for auto_explain.
Alvaro Herrera writes: > On 2022-Aug-30, Matheus Martin wrote: >> Good idea on using an actual prepared statement but unfortunately it didn't >> produce any different result. > I should have also mentioned to try the EXPLAIN EXECUTE six times and > see if the last one produces a different plan. That's when it switches > from planning every time to planning with generic arguments, as I > recall. In recent versions you can bypass that with SET plan_cache_mode = force_generic_plan; regards, tom lane
