Re: different execution time for the same query (and same DB status)

Hello,
many thanks to all the persons who replied.
I am back with the information requested in
https://wiki.postgresql.org/wiki/Slow_Query_Questions.
Here you can find the results of the EXPLAIN commands:
1) First execution: https://explain.depesz.com/s/X2as
2) Second execution (right after the first one):
https://explain.depesz.com/s/gHrb

Table A and B are both loaded with 7500000 records, whereas Table C
contains 1600 records.
Both queries are executed with work_mem=800MB (the other parameters are
reported in Section 7).
With such a value, I noticed also the following phenomenon: in addition to
variable execution times (as previusly stated, the range is between 20
seconds and 4 minutes),
sometimes the query crashes, returning the following error: SQL Error
[57P03]: FATAL: the database system is in recovery mode.
When this happens, in the log file I find many messages like these ones:
...
UTC [1] LOG: terminating any other active server processes
UTC [115] WARNING: terminating connection because of crash of another
server process
UTC [115] DETAIL: The postmaster has commanded this server process to roll
back the current transaction and exit, because another server process
exited abnormally and possibly corrupted shared memory.
HINT: In a moment you should be able to reconnect to the database and
repeat your command.
...
FATAL: the database system is in recovery mode
LOG: redo starts at 0/E8BFC8D0
LOG: invalid record length at 0/E8BFC9B8: wanted 24, got 0
LOG: redo done at 0/E8BFC980

If I re-run the query with with work_mem=400MB, the execution never crashes
(at least in all the tests I carried out) and response times are pretty
stable (always 4 minutes, plus/minus a small delta).
So I started wondering whether variable response times and crashes are
somehow correlated and due to the fact that the work_mem value is too high.
Anyway, in the following sections I tried to report all the information
described in the wiki.

============
1. Version
============

PostgreSQL 13.2 (Debian 13.2-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled
by gcc (Debian 8.3.0-6) 8.3.0, 64-bit

============
2. Tables
============

CREATE TABLE A (
a1 varchar(100),
a2 varchar(100),
v int4 primary key
);

CREATE TABLE B (
a1 varchar(100),
a2 varchar(100),
v int4 primary key
);

CREATE TABLE C (
la1 varchar(100),
la2 varchar(100),
va1 varchar(100),
va2 varchar(100),
res varchar (100),
c text
);

Schema | Name | Type | Owner
--------+------+-------+-------
public | a | table | admin
public | b | table | admin
public | c | table | admin
(3 rows)

List of relations
Schema | Name | Type | Owner | Persistence | Size | Description
--------+------+-------+-------+-------------+--------+-------------
public | a | table | admin | permanent | 317 MB |
(1 row)

List of relations
Schema | Name | Type | Owner | Persistence | Size | Description
--------+------+-------+-------+-------------+--------+-------------
public | b | table | admin | permanent | 317 MB |
(1 row)

List of relations
Schema | Name | Type | Owner | Persistence | Size | Description
--------+------+-------+-------+-------------+--------+-------------
public | c | table | admin | permanent | 152 kB |
(1 row)

============
3. Indices
============

tablename | indexname | indexdef
-----------+-------------+--------------------------------------------------------
a | a_pkey | CREATE UNIQUE INDEX a_pkey ON public.a USING
btree (v)
a | hash_pka | CREATE INDEX hash_pka ON public.a USING hash (v)
b | b_pkey | CREATE UNIQUE INDEX b_pkey ON public.b USING
btree (v)
b | hash_pkb | CREATE INDEX hash_pkb ON public.b USING hash (v)
c | hash_class0 | CREATE INDEX hash_class0 ON public.c USING hash
(la1)
c | hash_class1 | CREATE INDEX hash_class1 ON public.c USING hash
(la2)
c | hash_class2 | CREATE INDEX hash_class2 ON public.c USING hash
(va1)
c | hash_class3 | CREATE INDEX hash_class3 ON public.c USING hash
(va2)
c | hash_pkc | CREATE INDEX hash_pkc ON public.c USING hash (c)
(9 rows)

============
3. Table metadata
============
relname|relpages|reltuples|relallvisible|relkind|relnatts|relhassubclass|reloptions|pg_table_size|
-------|--------|---------|-------------|-------|--------|--------------|----------|-------------|
b | 40541|7499970.0| 40541|r | 3|false
|NULL | 332226560|
a | 40541|7499970.0| 40541|r | 3|false
|NULL | 332226560|
c | 14| 1600.0| 14|r | 6|false
|NULL | 155648|

============
4. Hardware and its performances
============
MacBook Pro (15-inch, 2018),
2.2 GHz Intel Core i7,
16 GB 2400 MHz DDR4

Results from bonnie++:
root(at)c1a8bd8320a0:/# bonnie++ -f -n0 -x4 -d /var/lib/postgresql/ -u root
Using uid:0, gid:0.
format_version,bonnie_version,name,concurrency,seed,file_size,io_chunk_size,putc,putc_cpu,put_block,put_block_cpu,rewrite,rewrite_cpu,getc,getc_cpu,get_block,get_block_cpu,seeks,seeks_cpu,num_files,max_size,min_size,num_dirs,file_chunk_size,seq_create,seq_create_cpu,seq_stat,seq_stat_cpu,seq_del,seq_del_cpu,ran_create,ran_create_cpu,ran_stat,ran_stat_cpu,ran_del,ran_del_cpu,putc_latency,put_block_latency,rewrite_latency,getc_latency,get_block_latency,seeks_latency,seq_create_latency,seq_stat_latency,seq_del_latency,ran_create_latency,ran_stat_latency,ran_del_latency
Writing intelligently...done
Rewriting...done
Reading intelligently...done
start 'em...done...done...done...done...done...
1.98,1.98,c1a8bd8320a0,1,1615294449,4G,,8192,5,,,248685,79,223758,81,,,362721,93,11439,463,,,,,,,,,,,,,,,,,,,1181ms,1186ms,,5784us,13082us,,,,,,
Writing intelligently...done
Rewriting...done
Reading intelligently...done
start 'em...done...done...done...done...done...
1.98,1.98,c1a8bd8320a0,1,1615294449,4G,,8192,5,,,259711,83,235606,81,,,402573,99,13113,687,,,,,,,,,,,,,,,,,,,692ms,1553ms,,1569us,21954us,,,,,,
Writing intelligently...done
Rewriting...done
Reading intelligently...done
start 'em...done...done...done...done...done...
1.98,1.98,c1a8bd8320a0,1,1615294449,4G,,8192,5,,,249913,84,207899,79,,,383606,99,12570,675,,,,,,,,,,,,,,,,,,,1363ms,940ms,,4864us,64727us,,,,,,
Writing intelligently...done
Rewriting...done
Reading intelligently...done
start 'em...done...done...done...done...done...
1.98,1.98,c1a8bd8320a0,1,1615294449,4G,,8192,5,,,265425,83,215268,81,,,373339,100,+++++,+++,,,,,,,,,,,,,,,,,,,817ms,920ms,,2355us,4786us,,,,,,

Results from dd:
14032+0 records in
14032+0 records out
14713618432 bytes transferred in 4.399248 secs (3344575895 bytes/sec)
4.40 real 0.01 user 3.39 sys

============
5. Maintenance setup
============

relid|schemaname|relname|seq_scan|seq_tup_read|idx_scan|idx_tup_fetch|n_tup_ins|n_tup_upd|n_tup_del|n_tup_hot_upd|n_live_tup|n_dead_tup|n_mod_since_analyze|n_ins_since_vacuum|last_vacuum|last_autovacuum
|last_analyze|last_autoanalyze
|vacuum_count|autovacuum_count|analyze_count|autoanalyze_count|
-----|----------|-------|--------|------------|--------|-------------|---------|---------|---------|-------------|----------|----------|-------------------|------------------|-----------|-------------------|------------|-------------------|------------|----------------|-------------|-----------------|
34944|public |b | 23| 30000000| 8| 0|
7500000| 0| 0| 0| 7499970| 0|
0| 0| |2021-03-09 19:52:43|
|2021-03-09 19:52:47| 0| 1| 0|
1|
34949|public |a | 24| 37500000| 8| 0|
7500000| 0| 0| 0| 7499970| 0|
0| 0| |2021-03-09 19:53:08|
|2021-03-09 19:53:12| 0| 1| 0|
1|
34956|public |c | 7| 1600|20000000| 2025000000|
1600| 0| 0| 0| 1600| 0|
0| 0| |2021-03-09 20:20:25|
|2021-03-09 20:20:25| 0| 1| 0|
1|

============
6. Statistics
============

frac_mcv
|tablename|attname|inherited|null_frac|n_distinct|n_mcv|n_hist|correlation|
----------|---------|-------|---------|---------|----------|-----|------|-----------|
|a |v |false | 0.0| -1.0| | 101|
1.0|
|c |c |false | 0.0| -1.0| |
101|0.016762745|
|b |v |false | 0.0| -1.0| | 101|
1.0|
|c |res |false | 0.0| -1.0| |
101|0.008681587|
0.37374988|c |la1 |false | 0.0| -0.500625| 100| 101|
0.04232038|
0.37374988|c |la2 |false | 0.0| -0.500625| 100| 101|
0.03672261|
0.37374988|c |va1 |false | 0.0| -0.500625| 100| 101|
0.06667662|
0.37374988|c |va2 |false | 0.0| -0.500625| 100| 101|
0.06553146|
0.19663344|a |a1 |false | 0.0| 800.0| 100| 101|
0.66633326|
0.19663344|a |a2 |false | 0.0| 800.0| 100| 101|
0.66686845|
0.19660011|b |a1 |false | 0.0| 800.0| 100| 101|
0.6654024|
0.19660011|b |a2 |false | 0.0| 800.0| 100| 101|
0.6656135|

============
7. Settings
============
allow_system_table_mods off
application_name DBeaver 21.0.0 - SQLEditor <Script-1.sql>
archive_cleanup_command
archive_command (disabled)
archive_mode off
archive_timeout 0
array_nulls on
authentication_timeout 1min
autovacuum on
autovacuum_analyze_scale_factor 0.1
autovacuum_analyze_threshold 50
autovacuum_freeze_max_age 200000000
autovacuum_max_workers 3
autovacuum_multixact_freeze_max_age 400000000
autovacuum_naptime 1min
autovacuum_vacuum_cost_delay 2ms
autovacuum_vacuum_cost_limit -1
autovacuum_vacuum_insert_scale_factor 0.2
autovacuum_vacuum_insert_threshold 1000
autovacuum_vacuum_scale_factor 0.2
autovacuum_vacuum_threshold 50
autovacuum_work_mem -1
backend_flush_after 0
backslash_quote safe_encoding
backtrace_functions
bgwriter_delay 200ms
bgwriter_flush_after 512kB
bgwriter_lru_maxpages 100
bgwriter_lru_multiplier 2
block_size 8192
bonjour off
bonjour_name
bytea_output hex
check_function_bodies on
checkpoint_completion_target 0.5
checkpoint_flush_after 256kB
checkpoint_timeout 5min
checkpoint_warning 30s
client_encoding UTF8
client_min_messages notice
cluster_name
commit_delay 0
commit_siblings 5
config_file /var/lib/postgresql/data/pgdata/postgresql.conf
constraint_exclusion partition
cpu_index_tuple_cost 0.005
cpu_operator_cost 0.0025
cpu_tuple_cost 0.01
cursor_tuple_fraction 0.1
data_checksums off
data_directory /var/lib/postgresql/data/pgdata
data_directory_mode 0700
data_sync_retry off
DateStyle ISO, MDY
db_user_namespace off
deadlock_timeout 1s
debug_assertions off
debug_pretty_print on
debug_print_parse off
debug_print_plan off
debug_print_rewritten off
default_statistics_target 100
default_table_access_method heap
default_tablespace
default_text_search_config pg_catalog.english
default_transaction_deferrable off
default_transaction_isolation read committed
default_transaction_read_only off
dynamic_library_path $libdir
dynamic_shared_memory_type posix
effective_cache_size 4GB
effective_io_concurrency 1
enable_bitmapscan on
enable_gathermerge on
enable_hashagg on
enable_hashjoin on
enable_incremental_sort 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
extension_destdir
external_pid_file
extra_float_digits 3
force_parallel_mode on
from_collapse_limit 8
fsync on
full_page_writes on
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
hash_mem_multiplier 1
hba_file /var/lib/postgresql/data/pgdata/pg_hba.conf
hot_standby on
hot_standby_feedback off
huge_pages try
ident_file /var/lib/postgresql/data/pgdata/pg_ident.conf
idle_in_transaction_session_timeout 0
ignore_checksum_failure off
ignore_invalid_pages off
ignore_system_indexes off
integer_datetimes on
IntervalStyle postgres
jit on
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
krb_caseins_users off
krb_server_keyfile FILE:/etc/postgresql-common/krb5.keytab
lc_collate en_US.utf8
lc_ctype en_US.utf8
lc_messages en_US.utf8
lc_monetary en_US.utf8
lc_numeric en_US.utf8
lc_time en_US.utf8
listen_addresses *
lo_compat_privileges off
local_preload_libraries
lock_timeout 0
log_autovacuum_min_duration -1
log_checkpoints off
log_connections off
log_destination stderr
log_directory log
log_disconnections off
log_duration off
log_error_verbosity default
log_executor_stats off
log_file_mode 0600
log_filename postgresql-%Y-%m-%d_%H%M%S.log
log_hostname off
log_line_prefix %m [%p]
log_lock_waits off
log_min_duration_sample -1
log_min_duration_statement -1
log_min_error_statement error
log_min_messages warning
log_parameter_max_length -1
log_parameter_max_length_on_error 0
log_parser_stats off
log_planner_stats off
log_replication_commands off
log_rotation_age 1d
log_rotation_size 10MB
log_statement none
log_statement_sample_rate 1
log_statement_stats off
log_temp_files -1
log_timezone Etc/UTC
log_transaction_sample_rate 0
log_truncate_on_rotation off
logging_collector off
logical_decoding_work_mem 64MB
maintenance_io_concurrency 10
maintenance_work_mem 64MB
max_connections 100
max_files_per_process 1000
max_function_args 100
max_identifier_length 63
max_index_keys 32
max_locks_per_transaction 64
max_logical_replication_workers 4
max_parallel_maintenance_workers 2
max_parallel_workers 8
max_parallel_workers_per_gather 16
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_slot_wal_keep_size -1
max_stack_depth 2MB
max_standby_archive_delay 30s
max_standby_streaming_delay 30s
max_sync_workers_per_subscription 2
max_wal_senders 10
max_wal_size 1GB
max_worker_processes 8
min_parallel_index_scan_size 512kB
min_parallel_table_scan_size 8MB
min_wal_size 80MB
old_snapshot_threshold -1
operator_precedence_warning off
parallel_leader_participation on
parallel_setup_cost 1
parallel_tuple_cost 0.001
password_encryption md5
plan_cache_mode auto
plpgsql.check_asserts on
plpgsql.extra_errors none
plpgsql.extra_warnings none
plpgsql.print_strict_params off
plpgsql.variable_conflict error
port 5432
post_auth_delay 0
pre_auth_delay 0
primary_conninfo
primary_slot_name
promote_trigger_file
quote_all_identifiers off
random_page_cost 4
recovery_end_command
recovery_min_apply_delay 0
recovery_target
recovery_target_action pause
recovery_target_inclusive on
recovery_target_lsn
recovery_target_name
recovery_target_time
recovery_target_timeline latest
recovery_target_xid
restart_after_crash on
restore_command
row_security on
search_path "$user", public
segment_size 1GB
seq_page_cost 1
server_encoding UTF8
server_version 13.2 (Debian 13.2-1.pgdg100+1)
server_version_num 130002
session_preload_libraries
session_replication_role origin
shared_buffers 128MB
shared_memory_type mmap
shared_preload_libraries plugin_debugger
ssl off
ssl_ca_file
ssl_cert_file server.crt
ssl_ciphers HIGH:MEDIUM:+3DES:!aNULL
ssl_crl_file
ssl_dh_params_file
ssl_ecdh_curve prime256v1
ssl_key_file server.key
ssl_library OpenSSL
ssl_max_protocol_version
ssl_min_protocol_version TLSv1.2
ssl_passphrase_command
ssl_passphrase_command_supports_reload off
ssl_prefer_server_ciphers on
standard_conforming_strings on
statement_timeout 0
stats_temp_directory pg_stat_tmp
superuser_reserved_connections 3
synchronize_seqscans on
synchronous_commit on
synchronous_standby_names
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
tcp_user_timeout 0
temp_buffers 8MB
temp_file_limit -1
temp_tablespaces
TimeZone Europe/Zurich
timezone_abbreviations Default
trace_notify off
trace_recovery_messages log
trace_sort off
track_activities on
track_activity_query_size 1kB
track_commit_timestamp off
track_counts on
track_functions none
track_io_timing on
transaction_deferrable off
transaction_isolation read committed
transaction_read_only off
transform_null_equals off
unix_socket_directories /var/run/postgresql
unix_socket_group
unix_socket_permissions 0777
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 10
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_block_size 8192
wal_buffers 4MB
wal_compression off
wal_consistency_checking
wal_init_zero on
wal_keep_size 0
wal_level replica
wal_log_hints off
wal_receiver_create_temp_slot off
wal_receiver_status_interval 10s
wal_receiver_timeout 1min
wal_recycle on
wal_retrieve_retry_interval 5s
wal_segment_size 16MB
wal_sender_timeout 1min
wal_skip_threshold 2MB
wal_sync_method fdatasync
wal_writer_delay 200ms
wal_writer_flush_after 1MB
work_mem 800MB
xmlbinary base64
xmloption content
zero_damaged_pages off

Again, thanks a lot for the time you spent on my messages.

Best regards,
Francesco De Angelis

You don't mention shared_buffers, which is quite low by default. Not sure
> of the memory of your docker container, but it might be prudent to increase
> shared_buffers to keep as much data as possible in memory rather than
> needing to read from disk by a second run. To test the possibility Tom Lane
> suggested, do a manual analyze after data insert to see if it is also slow.
> Explain (analyze, buffers) select... and then using
> https://explain.depesz.com/ or https://tatiyants.com/pev/#/plans/new
> would be a good option to have some visualization on where the query is
> going off the rails.
>