Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1m1ZgP-0005QG-8y for pgsql-performance@arkaria.postgresql.org; Thu, 08 Jul 2021 19:27:37 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1m1Zfq-0001ev-42 for pgsql-performance@arkaria.postgresql.org; Thu, 08 Jul 2021 19:27:02 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1m1UP9-0000WE-Lw for pgsql-performance@lists.postgresql.org; Thu, 08 Jul 2021 13:49:27 +0000 Received: from mail-io1-xd30.google.com ([2607:f8b0:4864:20::d30]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1m1UP6-0006lj-Ra for pgsql-performance@lists.postgresql.org; Thu, 08 Jul 2021 13:49:27 +0000 Received: by mail-io1-xd30.google.com with SMTP id q2so8169089iot.11 for ; Thu, 08 Jul 2021 06:49:24 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=1voYWsWcwyb2K2oisf6sTCFBeufTknO/UKPEoKTe7/k=; b=h1ItSRTKaoMPf8dVlZnDfBoTcWrmmXnUkcOKqhShSvUJD6WBsAC9JrcTfezM+ceAjB W4cXPnu9trxiV+iloCvGV7YPOhTVkVR2sJhDhyXDLX6Wp5q4NL164K5J4Fre0AFafyRK p+hsJ7M43RKc8qwnZ0cICv2lCxV7wrlK3HZVDv0xhOErWWwP2PgUdj0n9j2JzVp+2YiC RBwYTL3rP/KlKM5CMrgfPB0bcBrpojkb1tdRXLssVzm+J3GTBLUNIPwkYAYNAL2V5A4V 2Co9bb/H2NkmLstSwrcJlUblG9W7/PAEr3W+0jvwSknnzVGhCRNL/QZRDjGXos5lyHcV aQ8g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=1voYWsWcwyb2K2oisf6sTCFBeufTknO/UKPEoKTe7/k=; b=HMJsd6T3BnRLNCF80BkgCK8PrRpOrOUgS7X/LpTlOhDDu71VW5zZD66gBt6+PmMWgk kqiwd2t2LU/E3s+sI5DShURUJbigOyi5LSmmpQh8fdrVtGOEUUu/FukO0WvyWalF5T3C jD2R4weJHiOlT5KRPDyIPnBwh48VwkNrRFGf4Gp0kl9dMVjzfTCdhShc8sSZwSKt5g2p ii2svjgsD8GW7R07qV0RcnEsyP7UNhh6iIUDHAcqVx+rbiNpyhLAHMXO0Id3F+0Mj/Qp XvAxcZ6gh3r0YC9Pip6iXJfQKr1Fm4dYwGwqfR67UwhCO3KJmmkjjGVsj9YJI6l5+mmy i0Tw== X-Gm-Message-State: AOAM533BTIwzwPqGmQ1V4Ix6PunXP+KE+yzVF7+cRXfOg8D84zc+Jo50 10saeXq6GwwNG8O1cRobsKhga3GA64ncbl3JRgU= X-Google-Smtp-Source: ABdhPJztcDjEB6TGW28LyrG1eA3lw41QbWWP/CfUdBsakU2Bo2ekS1lurQpTkE6kqQg6b6CZLg89+WwVSc6DEZ6TP60= X-Received: by 2002:a05:6638:3882:: with SMTP id b2mr15212324jav.15.1625752162969; Thu, 08 Jul 2021 06:49:22 -0700 (PDT) MIME-Version: 1.0 References: <20210708123320.GB22043@telsasoft.com> In-Reply-To: <20210708123320.GB22043@telsasoft.com> From: Allan Barrielle Date: Thu, 8 Jul 2021 15:49:12 +0200 Message-ID: Subject: Re: ETL - sql orchestrator is stuck when there is not sleep() between queries To: Justin Pryzby Cc: pgsql-performance@lists.postgresql.org, Pierrick Martin Content-Type: multipart/alternative; boundary="0000000000002aabe805c69cec97" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --0000000000002aabe805c69cec97 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Hello, > Is it true that the SELECTs have no joins in them ? Yes there is a lot of LEFT JOIN. > When it doesn't work, you could check SELECT * FROM pg_stat_activity, and >SELECT pg_blocking_pids(pid), * FROM pg_locks, to see what's going on. I can't see any blocking queries blocking pg_locks, pg_blocking_pids. > It'd be very useful to get "explain analyze" for a working query and for = a > stuck query. It sound like the stuck query never finishes, so maybe the second > part is impossible (?) We run an explain analysis and we see some very interesting stuff going on. It seems without explicitly adding a `ANALYZE`, the query has a cost of over billions, so the query is not stuck but took forever. When I run the same scripts with an ANALYZE right before running the query, the query is exec is 50secondes and the cost is normal Explain analyze WITHOUT ANALYZE https://explain.depesz.com/s/RaSr Explain analyze same query WITH ANALYZE BEFORE https://explain.depesz.com/s/tYVl The configuration is tuned by aws aurora, but this issue happens also with a default config. allow_system_table_mods,off application_name,DataGrip 2021.1.3 archive_command,(disabled) archive_mode,off archive_timeout,5min array_nulls,on authentication_timeout,1min autovacuum,on autovacuum_analyze_scale_factor,0.05 autovacuum_analyze_threshold,50 autovacuum_freeze_max_age,200000000 autovacuum_max_workers,12 autovacuum_multixact_freeze_max_age,400000000 autovacuum_naptime,5s autovacuum_vacuum_cost_delay,1ms autovacuum_vacuum_cost_limit,1200 autovacuum_vacuum_scale_factor,0.1 autovacuum_vacuum_threshold,50 autovacuum_work_mem,-1 backend_flush_after,0 backslash_quote,safe_encoding bgwriter_delay,200ms bgwriter_flush_after,0 bgwriter_lru_maxpages,100 bgwriter_lru_multiplier,2 bonjour,off bytea_output,hex check_function_bodies,on checkpoint_completion_target,0.9 checkpoint_flush_after,0 checkpoint_timeout,15min checkpoint_warning,30s client_encoding,UTF8 client_min_messages,notice commit_delay,0 commit_siblings,5 constraint_exclusion,partition cpu_index_tuple_cost,0.005 cpu_operator_cost,0.0025 cpu_tuple_cost,0.01 cursor_tuple_fraction,0.1 DateStyle,"ISO, MDY" db_user_namespace,off deadlock_timeout,1s debug_pretty_print,on debug_print_parse,off debug_print_plan,off debug_print_rewritten,off default_statistics_target,500 default_text_search_config,pg_catalog.simple default_transaction_deferrable,off default_transaction_isolation,read committed default_transaction_read_only,off dynamic_library_path,$libdir effective_cache_size,4GB effective_io_concurrency,600 enable_bitmapscan,on enable_gathermerge,on enable_hashagg,on enable_hashjoin,on enable_indexonlyscan,on enable_indexscan,on enable_material,on enable_mergejoin,on enable_nestloop,on enable_parallel_append,on enable_parallel_hash,on enable_partition_pruning,on enable_partitionwise_aggregate,off enable_partitionwise_join,off enable_seqscan,on enable_sort,on enable_tidscan,on escape_string_warning,on event_source,PostgreSQL exit_on_error,off extra_float_digits,3 force_parallel_mode,off from_collapse_limit,8 fsync,off full_page_writes,off geqo,on geqo_effort,5 geqo_generations,0 geqo_pool_size,0 geqo_seed,0 geqo_selection_bias,2 geqo_threshold,12 gin_fuzzy_search_limit,0 gin_pending_list_limit,4MB hot_standby,off hot_standby_feedback,on huge_pages,try idle_in_transaction_session_timeout,25min ignore_checksum_failure,off ignore_system_indexes,off IntervalStyle,postgres jit,off jit_above_cost,100000 jit_debugging_support,off jit_dump_bitcode,off jit_expressions,on jit_inline_above_cost,500000 jit_optimize_above_cost,500000 jit_profiling_support,off jit_provider,llvmjit jit_tuple_deforming,on join_collapse_limit,8 lc_monetary,C lc_numeric,C lc_time,C listen_addresses,* lock_timeout,0 lo_compat_privileges,off maintenance_work_mem,2GB max_connections,100 max_files_per_process,1000 max_locks_per_transaction,256 max_logical_replication_workers,4 max_parallel_maintenance_workers,12 max_parallel_workers,12 max_parallel_workers_per_gather,6 max_pred_locks_per_page,2 max_pred_locks_per_relation,-2 max_pred_locks_per_transaction,64 max_prepared_transactions,0 max_replication_slots,10 max_stack_depth,6MB max_standby_archive_delay,30s max_standby_streaming_delay,14s max_sync_workers_per_subscription,2 max_wal_senders,0 max_wal_size,8GB max_worker_processes,12 min_parallel_index_scan_size,512kB min_parallel_table_scan_size,8MB min_wal_size,2GB old_snapshot_threshold,-1 operator_precedence_warning,off parallel_leader_participation,off parallel_setup_cost,1000 parallel_tuple_cost,0.1 password_encryption,md5 port,5432 post_auth_delay,0 pre_auth_delay,0 quote_all_identifiers,off random_page_cost,1.1 restart_after_crash,on row_security,on search_path,public seq_page_cost,1 session_replication_role,origin shared_buffers,1GB standard_conforming_strings,on statement_timeout,0 superuser_reserved_connections,3 synchronize_seqscans,on synchronous_commit,on syslog_facility,local0 syslog_ident,postgres syslog_sequence_numbers,on syslog_split_messages,on tcp_keepalives_count,9 tcp_keepalives_idle,7200 tcp_keepalives_interval,75 temp_buffers,8MB temp_file_limit,-1 TimeZone,UTC trace_notify,off trace_recovery_messages,log trace_sort,off track_activities,on track_activity_query_size,4kB track_commit_timestamp,off track_counts,on track_functions,none track_io_timing,off transform_null_equals,off update_process_title,on vacuum_cleanup_index_scale_factor,0.1 vacuum_cost_delay,0 vacuum_cost_limit,200 vacuum_cost_page_dirty,20 vacuum_cost_page_hit,1 vacuum_cost_page_miss,0 vacuum_defer_cleanup_age,0 vacuum_freeze_min_age,50000000 vacuum_freeze_table_age,150000000 vacuum_multixact_freeze_min_age,5000000 vacuum_multixact_freeze_table_age,150000000 wal_buffers,16MB wal_compression,off wal_level,minimal wal_log_hints,off wal_receiver_status_interval,10s wal_receiver_timeout,30s wal_retrieve_retry_interval,5s wal_sender_timeout,1min wal_sync_method,fdatasync wal_writer_delay,200ms wal_writer_flush_after,1MB work_mem,2GB xmlbinary,base64 xmloption,content zero_damaged_pages,off On Thu, Jul 8, 2021 at 2:33 PM Justin Pryzby wrote: > On Thu, Jul 08, 2021 at 01:00:28AM +0200, Allan Barrielle wrote: > > All is fine, and can work great. > > But sometimes, some queries that used to take about 20 secs to complete > can > > suddenly end in 5mins. > > Important all queries have the same shape -> CREATE TABLE SELECT AS *(a > bit > > of transform) FROM TABLE). No update, nothing, it=E2=80=99s dead simple= . > > > > Nothing works, it=E2=80=99s very random, some query won=E2=80=99t simpl= y work ( even > after > > hours ). > > When it doesn't work, you could check SELECT * FROM pg_stat_activity, and > SELECT pg_blocking_pids(pid), * FROM pg_locks, to see what's going on. > > > Important all queries have the same shape -> CREATE TABLE SELECT AS *(a > bit > > of transform) FROM TABLE). No update, nothing, it=E2=80=99s dead simple= . > > We are just trying to copy a table from schema1, to schema2, to schema3 > and > > finally schema3. That=E2=80=99s it. > > Is it true that the SELECTs have no joins in them ? > > Did this ever work better or differently under different versions of > postgres ? > > > Why does the query never end even after hours ? Why there is no log abo= ut > > where the query is stuck. > > Please send your nondefault config. > https://wiki.postgresql.org/wiki/Server_Configuration > > Also enable logging (I just added this to the wiki). > https://wiki.postgresql.org/wiki/Slow_Query_Questions#Enable_Logging > > It'd be very useful to get "explain analyze" for a working query and for = a > stuck query. It sound like the stuck query never finishes, so maybe the > second > part is impossible (?) > > But it'd be good to get at least "explain" output. You'd have to edit > your sql > script to run an "explain" before each query, and run it, logging the > ouput, > until you capture the plan for a stuck query. Save the output and send > here, > along with the query plan for a working query. > > -- > Justin > --0000000000002aabe805c69cec97 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Hello,=C2=A0

> Is it true that the SELECTs have = no joins in them ?

Yes there is a lot of LEFT JOIN.

>=C2=A0When it doesn't work, you co= uld check SELECT * FROM pg_stat_activity, and
>SELECT pg_blocking_pid= s(pid), * FROM pg_locks, to see what's going on.

I can't see any blocking queries blocking pg= _locks, pg_blocking_pids.

> It'd be very useful to get "= explain analyze" for a working query and for a
> stuck query.=C2= =A0 It sound like the stuck query never finishes, so maybe the second
&g= t; part is impossible (?)

We run an explain analysis and we see some= very interesting stuff going on.
It seems without explicitly adding a `= ANALYZE`, the query has a cost of over billions, so the query=C2=A0is not s= tuck but took forever.
When I run the same scripts with an ANALYZE right= before running=C2=A0the query, the query is exec is 50secondes and the cos= t is normal

Explain analyze WITHOUT ANALYZE=C2=A0https://explain.depesz.com/s/RaSr
Explain= analyze same query WITH ANALYZE BEFORE=C2=A0https://explain.depesz.com/s/tYVl

The configurat= ion is tuned by aws aurora, but this issue happens also with a default conf= ig.

allow_system_table_mods,off
application_name,DataGrip 2021.1.= 3
archive_command,(disabled)
archive_mode,off
archive_timeout,5min=
array_nulls,on
authentication_timeout,1min
autovacuum,on
autov= acuum_analyze_scale_factor,0.05
autovacuum_analyze_threshold,50
autov= acuum_freeze_max_age,200000000
autovacuum_max_workers,12
autovacuum_m= ultixact_freeze_max_age,400000000
autovacuum_naptime,5s
autovacuum_va= cuum_cost_delay,1ms
autovacuum_vacuum_cost_limit,1200
autovacuum_vacu= um_scale_factor,0.1
autovacuum_vacuum_threshold,50
autovacuum_work_me= m,-1
backend_flush_after,0
backslash_quote,safe_encoding
bgwriter_= delay,200ms
bgwriter_flush_after,0
bgwriter_lru_maxpages,100
bgwri= ter_lru_multiplier,2
bonjour,off
bytea_output,hex
check_function_b= odies,on
checkpoint_completion_target,0.9
checkpoint_flush_after,0checkpoint_timeout,15min
checkpoint_warning,30s
client_encoding,UTF8=
client_min_messages,notice
commit_delay,0
commit_siblings,5
co= nstraint_exclusion,partition
cpu_index_tuple_cost,0.005
cpu_operator_= cost,0.0025
cpu_tuple_cost,0.01
cursor_tuple_fraction,0.1
DateStyl= e,"ISO, MDY"
db_user_namespace,off
deadlock_timeout,1s
d= ebug_pretty_print,on
debug_print_parse,off
debug_print_plan,off
de= bug_print_rewritten,off
default_statistics_target,500
default_text_se= arch_config,pg_catalog.simple
default_transaction_deferrable,off
defa= ult_transaction_isolation,read committed
default_transaction_read_only,o= ff
dynamic_library_path,$libdir
effective_cache_size,4GB
effective= _io_concurrency,600
enable_bitmapscan,on
enable_gathermerge,on
ena= ble_hashagg,on
enable_hashjoin,on
enable_indexonlyscan,on
enable_i= ndexscan,on
enable_material,on
enable_mergejoin,on
enable_nestloop= ,on
enable_parallel_append,on
enable_parallel_hash,on
enable_parti= tion_pruning,on
enable_partitionwise_aggregate,off
enable_partitionwi= se_join,off
enable_seqscan,on
enable_sort,on
enable_tidscan,on
= escape_string_warning,on
event_source,PostgreSQL
exit_on_error,offextra_float_digits,3
force_parallel_mode,off
from_collapse_limit,8fsync,off
full_page_writes,off
geqo,on
geqo_effort,5
geqo_gen= erations,0
geqo_pool_size,0
geqo_seed,0
geqo_selection_bias,2
g= eqo_threshold,12
gin_fuzzy_search_limit,0
gin_pending_list_limit,4MB<= br>hot_standby,off
hot_standby_feedback,on
huge_pages,try
idle_in_= transaction_session_timeout,25min
ignore_checksum_failure,off
ignore_= system_indexes,off
IntervalStyle,postgres
jit,off
jit_above_cost,1= 00000
jit_debugging_support,off
jit_dump_bitcode,off
jit_expressio= ns,on
jit_inline_above_cost,500000
jit_optimize_above_cost,500000
= jit_profiling_support,off
jit_provider,llvmjit
jit_tuple_deforming,on=
join_collapse_limit,8
lc_monetary,C
lc_numeric,C
lc_time,C
= listen_addresses,*
lock_timeout,0
lo_compat_privileges,off
mainten= ance_work_mem,2GB
max_connections,100
max_files_per_process,1000
m= ax_locks_per_transaction,256
max_logical_replication_workers,4
max_pa= rallel_maintenance_workers,12
max_parallel_workers,12
max_parallel_wo= rkers_per_gather,6
max_pred_locks_per_page,2
max_pred_locks_per_relat= ion,-2
max_pred_locks_per_transaction,64
max_prepared_transactions,0<= br>max_replication_slots,10
max_stack_depth,6MB
max_standby_archive_d= elay,30s
max_standby_streaming_delay,14s
max_sync_workers_per_subscri= ption,2
max_wal_senders,0
max_wal_size,8GB
max_worker_processes,12=
min_parallel_index_scan_size,512kB
min_parallel_table_scan_size,8MB<= br>min_wal_size,2GB
old_snapshot_threshold,-1
operator_precedence_war= ning,off
parallel_leader_participation,off
parallel_setup_cost,1000parallel_tuple_cost,0.1
password_encryption,md5
port,5432
post_a= uth_delay,0
pre_auth_delay,0
quote_all_identifiers,off
random_page= _cost,1.1
restart_after_crash,on
row_security,on
search_path,publi= c
seq_page_cost,1
session_replication_role,origin
shared_buffers,1= GB
standard_conforming_strings,on
statement_timeout,0
superuser_re= served_connections,3
synchronize_seqscans,on
synchronous_commit,onsyslog_facility,local0
syslog_ident,postgres
syslog_sequence_numbers= ,on
syslog_split_messages,on
tcp_keepalives_count,9
tcp_keepalives= _idle,7200
tcp_keepalives_interval,75
temp_buffers,8MB
temp_file_l= imit,-1
TimeZone,UTC
trace_notify,off
trace_recovery_messages,log<= br>trace_sort,off
track_activities,on
track_activity_query_size,4kBtrack_commit_timestamp,off
track_counts,on
track_functions,none
= track_io_timing,off
transform_null_equals,off
update_process_title,on=
vacuum_cleanup_index_scale_factor,0.1
vacuum_cost_delay,0
vacuum_= cost_limit,200
vacuum_cost_page_dirty,20
vacuum_cost_page_hit,1
va= cuum_cost_page_miss,0
vacuum_defer_cleanup_age,0
vacuum_freeze_min_ag= e,50000000
vacuum_freeze_table_age,150000000
vacuum_multixact_freeze_= min_age,5000000
vacuum_multixact_freeze_table_age,150000000
wal_buffe= rs,16MB
wal_compression,off
wal_level,minimal
wal_log_hints,offwal_receiver_status_interval,10s
wal_receiver_timeout,30s
wal_retrie= ve_retry_interval,5s
wal_sender_timeout,1min
wal_sync_method,fdatasyn= c
wal_writer_delay,200ms
wal_writer_flush_after,1MB
work_mem,2GBxmlbinary,base64
xmloption,content
zero_damaged_pages,off
=
On Thu= , Jul 8, 2021 at 2:33 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
On Thu, Jul 08, 2021 at 01:00:28AM +0200, Allan= Barrielle wrote:
> All is fine, and can work great.
> But sometimes, some queries that used to take about 20 secs to complet= e can
> suddenly end in 5mins.
> Important all queries have the same shape -> CREATE TABLE SELECT AS= *(a bit
> of transform) FROM TABLE). No update, nothing, it=E2=80=99s dead simpl= e.
>
> Nothing works, it=E2=80=99s very random, some query won=E2=80=99t simp= ly work ( even after
> hours ).

When it doesn't work, you could check SELECT * FROM pg_stat_activity, a= nd
SELECT pg_blocking_pids(pid), * FROM pg_locks, to see what's going on.<= br>
> Important all queries have the same shape -> CREATE TABLE SELECT AS= *(a bit
> of transform) FROM TABLE). No update, nothing, it=E2=80=99s dead simpl= e.
> We are just trying to copy a table from schema1, to schema2, to schema= 3 and
> finally schema3. That=E2=80=99s it.

Is it true that the SELECTs have no joins in them ?

Did this ever work better or differently under different versions of postgr= es ?

> Why does the query never end even after hours ? Why there is no log ab= out
> where the query is stuck.

Please send your nondefault config.
https://wiki.postgresql.org/wiki/Server_Configu= ration

Also enable logging (I just added this to the wiki).
https://wiki.postgresql.org/wiki= /Slow_Query_Questions#Enable_Logging

It'd be very useful to get "explain analyze" for a working qu= ery and for a
stuck query.=C2=A0 It sound like the stuck query never finishes, so maybe t= he second
part is impossible (?)

But it'd be good to get at least "explain" output.=C2=A0 You&= #39;d have to edit your sql
script to run an "explain" before each query, and run it, logging= the ouput,
until you capture the plan for a stuck query.=C2=A0 Save the output and sen= d here,
along with the query plan for a working query.

--
Justin
--0000000000002aabe805c69cec97--