pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedFwd: different execution time for the same query (and same DB status)
10+ messages / 6 participants
[nested] [flat]
* Fwd: different execution time for the same query (and same DB status)
@ 2021-03-06 21:40 Francesco De Angelis <franc.tozzus@gmail.com>
0 siblings, 2 replies; 10+ messages in thread
From: Francesco De Angelis @ 2021-03-06 21:40 UTC (permalink / raw)
To: pgsql-performance@lists.postgresql.org
Hi all,
I would appreciate if somebody could help me understanding why the query
described below takes very different execution times to complete, almost
completely randomly.
I have two very "simple" tables, A and B:
CREATE TABLE A (
a1 varchar(10) NULL,
a2 varchar(10) NULL,
v int4 NULL
);
CREATE TABLE B (
a1 varchar(10) NULL,
a2 varchar(10) NULL,
v int4 NULL
);
I load A and B with some random numbers (10^7 records each one) and, when
the loading is complete, I run a query that "essentially" counts the number
of the records obtained through a sequence of JOINs, which has the
following form:
SELECT count(*) from (... A join B ....)
The query does not write/update any value, it is simply a SELECT applied
over the aforementioned tables (plus some unions and intersections).
The problem is the following: the query can take between 20 seconds and 4
minutes to complete. Most of times, when I run the query for the first time
after the server initialisation, it takes 20 seconds; but if I re-run it
again (without changing anything) right after the first execution, the
probability to take more than 4 minutes is very high.
My impression is that the "status" of the internal structures of the DBMS
is somehow affected by the first execution, but I cannot figure out neither
what nor how I can fix it.
To give some additional information, I can state the following facts:
- There are no other processes reading or writing the tables on the schema
and the status of A and B is constant.
- During the loading of A and B (process that takes more or less one minute
to complete), I get the following messages:
LOG: checkpoints are occurring too frequently (29 seconds apart).
HINT: Consider increasing the configuration parameter "max_wal_size".
LOG: checkpoints are occurring too frequently (18 seconds apart)
HINT: Consider increasing the configuration parameter "max_wal_size".
- I am running my query through DBeaver and PostgreSQL runs in a Docker
container.
The version that I am using is the following: 13.2 (Debian
13.2-1.pgdg100+1).
The only configuration parameters I have changed are the following:
- force_parallel_mode = on
- max_parallel_workers_per_gather = 64
- parallel_setup_cost = 1
- parallel_tuple_cost = 0.001
- work_mem = '800MB'
I hope somebody could help me, as I really don't know why I am experiencing
such a strange behaviour.
Thanks a lot.
Best regards,
Francesco
^ permalink raw reply [nested|flat] 10+ messages in thread
* RE: different execution time for the same query (and same DB status)
@ 2021-03-07 14:51 Michel SALAIS <msalais@msym.fr>
parent: Francesco De Angelis <franc.tozzus@gmail.com>
1 sibling, 1 reply; 10+ messages in thread
From: Michel SALAIS @ 2021-03-07 14:51 UTC (permalink / raw)
To: 'Francesco De Angelis' <franc.tozzus@gmail.com>; pgsql-performance@lists.postgresql.org
Hi,
Have you tried to use EXPLAIN ANALYZE at least?
It could give valuable information about why this is occurring.
Michel SALAIS
De : Francesco De Angelis <franc.tozzus@gmail.com>
Envoyé : samedi 6 mars 2021 22:40
À : pgsql-performance@lists.postgresql.org
Objet : Fwd: different execution time for the same query (and same DB status)
Hi all,
I would appreciate if somebody could help me understanding why the query described below takes very different execution times to complete, almost completely randomly.
I have two very "simple" tables, A and B:
CREATE TABLE A (
a1 varchar(10) NULL,
a2 varchar(10) NULL,
v int4 NULL
);
CREATE TABLE B (
a1 varchar(10) NULL,
a2 varchar(10) NULL,
v int4 NULL
);
I load A and B with some random numbers (10^7 records each one) and, when the loading is complete, I run a query that "essentially" counts the number of the records obtained through a sequence of JOINs, which has the following form:
SELECT count(*) from (... A join B ....)
The query does not write/update any value, it is simply a SELECT applied over the aforementioned tables (plus some unions and intersections).
The problem is the following: the query can take between 20 seconds and 4 minutes to complete. Most of times, when I run the query for the first time after the server initialisation, it takes 20 seconds; but if I re-run it again (without changing anything) right after the first execution, the probability to take more than 4 minutes is very high.
My impression is that the "status" of the internal structures of the DBMS is somehow affected by the first execution, but I cannot figure out neither what nor how I can fix it.
To give some additional information, I can state the following facts:
- There are no other processes reading or writing the tables on the schema and the status of A and B is constant.
- During the loading of A and B (process that takes more or less one minute to complete), I get the following messages:
LOG: checkpoints are occurring too frequently (29 seconds apart).
HINT: Consider increasing the configuration parameter "max_wal_size".
LOG: checkpoints are occurring too frequently (18 seconds apart)
HINT: Consider increasing the configuration parameter "max_wal_size".
- I am running my query through DBeaver and PostgreSQL runs in a Docker container.
The version that I am using is the following: 13.2 (Debian 13.2-1.pgdg100+1).
The only configuration parameters I have changed are the following:
- force_parallel_mode = on
- max_parallel_workers_per_gather = 64
- parallel_setup_cost = 1
- parallel_tuple_cost = 0.001
- work_mem = '800MB'
I hope somebody could help me, as I really don't know why I am experiencing such a strange behaviour.
Thanks a lot.
Best regards,
Francesco
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: different execution time for the same query (and same DB status)
@ 2021-03-07 15:08 Julien Rouhaud <rjuju123@gmail.com>
parent: Michel SALAIS <msalais@msym.fr>
0 siblings, 1 reply; 10+ messages in thread
From: Julien Rouhaud @ 2021-03-07 15:08 UTC (permalink / raw)
To: Michel SALAIS <msalais@msym.fr>; +Cc: Francesco De Angelis <franc.tozzus@gmail.com>; pgsql-performance@lists.postgresql.org
On Sun, Mar 07, 2021 at 03:51:05PM +0100, Michel SALAIS wrote:
>
> Have you tried to use EXPLAIN ANALYZE at least?
>
> It could give valuable information about why this is occurring.
+1, and more generally please follow
https://wiki.postgresql.org/wiki/Slow_Query_Questions.
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: different execution time for the same query (and same DB status)
@ 2021-03-07 16:37 Tom Lane <tgl@sss.pgh.pa.us>
parent: Julien Rouhaud <rjuju123@gmail.com>
0 siblings, 1 reply; 10+ messages in thread
From: Tom Lane @ 2021-03-07 16:37 UTC (permalink / raw)
To: Julien Rouhaud <rjuju123@gmail.com>; +Cc: Michel SALAIS <msalais@msym.fr>; 'Francesco De Angelis' <franc.tozzus@gmail.com>; pgsql-performance@lists.postgresql.org
Julien Rouhaud <rjuju123@gmail.com> writes:
> +1, and more generally please follow
> https://wiki.postgresql.org/wiki/Slow_Query_Questions.
Yeah. FWIW, the most likely explanation for the change in behavior is
that by the time of the second execution, auto-analyze has managed to
update the table's statistics, and that for some reason that's changing
the plan for the worse. But then the next question is why and what
can be done about that. See the wiki entry for info that would be
helpful in diagnosing this.
regards, tom lane
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: different execution time for the same query (and same DB status)
@ 2021-03-08 17:03 Michael Lewis <mlewis@entrata.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 10+ messages in thread
From: Michael Lewis @ 2021-03-08 17:03 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Julien Rouhaud <rjuju123@gmail.com>; Michel SALAIS <msalais@msym.fr>; Francesco De Angelis <franc.tozzus@gmail.com>; Pgsql Performance <pgsql-performance@lists.postgresql.org>
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.
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: different execution time for the same query (and same DB status)
@ 2021-03-09 22:58 Francesco De Angelis <franc.tozzus@gmail.com>
parent: Michael Lewis <mlewis@entrata.com>
0 siblings, 0 replies; 10+ messages in thread
From: Francesco De Angelis @ 2021-03-09 22:58 UTC (permalink / raw)
To: Michael Lewis <mlewis@entrata.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; Julien Rouhaud <rjuju123@gmail.com>; Michel SALAIS <msalais@msym.fr>; Pgsql Performance <pgsql-performance@lists.postgresql.org>
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@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.
>
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: Fwd: different execution time for the same query (and same DB status)
@ 2021-03-10 08:27 Justin Pryzby <pryzby@telsasoft.com>
parent: Francesco De Angelis <franc.tozzus@gmail.com>
1 sibling, 1 reply; 10+ messages in thread
From: Justin Pryzby @ 2021-03-10 08:27 UTC (permalink / raw)
To: Francesco De Angelis <franc.tozzus@gmail.com>; +Cc: pgsql-performance@lists.postgresql.org, Michael Lewis <mlewis@entrata.com>; Tom Lane <tgl@sss.pgh.pa.us>; Julien Rouhaud <rjuju123@gmail.com>; Michel SALAIS <msalais@msym.fr>
On Sat, Mar 06, 2021 at 10:40:00PM +0100, Francesco De Angelis wrote:
> The problem is the following: the query can take between 20 seconds and 4
> minutes to complete. Most of times, when I run the query for the first time
> after the server initialisation, it takes 20 seconds; but if I re-run it
> again (without changing anything) right after the first execution, the
> probability to take more than 4 minutes is very high.
On Tue, Mar 09, 2021 at 11:58:05PM +0100, Francesco De Angelis wrote:
> 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),
You said it takes between 20s and 4min (240s), but both the explain analyze
show ~1300s.
explain analyze can be slower than the query, due to timing overhead.
Is that what's happening here? You could try explain(analyze,timing off,buffers).
You should send a result for the "20sec" result, and one for the "4min" result,
to compare.
I assume the crash is a result of OOM - you could find the result in dmesg
output ("Out of memory: Killed process") or the postgres logfile will say
"terminated by signal 9: Killed". It's important to avoid setting work_mem so
high that the process is killed and has to go into recovery mode.
--
Justin
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: Fwd: different execution time for the same query (and same DB status)
@ 2021-03-10 11:48 Francesco De Angelis <franc.tozzus@gmail.com>
parent: Justin Pryzby <pryzby@telsasoft.com>
0 siblings, 1 reply; 10+ messages in thread
From: Francesco De Angelis @ 2021-03-10 11:48 UTC (permalink / raw)
To: Justin Pryzby <pryzby@telsasoft.com>; +Cc: pgsql-performance@lists.postgresql.org, Michael Lewis <mlewis@entrata.com>; Tom Lane <tgl@sss.pgh.pa.us>; Julien Rouhaud <rjuju123@gmail.com>; Michel SALAIS <msalais@msym.fr>
Hello,
yes exactly in the previous analyses, as mentioned in the wiki, I ran
EXPLAIN (ANALYZE, BUFFERS)* query*, which took much longer to complete
(around 30 minutes) as showed in https://explain.depesz.com/s/gHrb and
https://explain.depesz.com/s/X2as .
As you said, I did the new tests with EXPLAIN (ANALYZE, timing off BUFFERS)*
query,* and these are the results:
- First execution: https://explain.depesz.com/s/ynAv
- Second execution: https://explain.depesz.com/s/z1eb
Now they are pretty aligned with the execution time of *query* (a few
seconds more to complete) and the difference between the first and second
execution is visible.
Also, from what I can see, the plans are different...
Il giorno mer 10 mar 2021 alle ore 09:27 Justin Pryzby <pryzby@telsasoft.com>
ha scritto:
> On Sat, Mar 06, 2021 at 10:40:00PM +0100, Francesco De Angelis wrote:
> > The problem is the following: the query can take between 20 seconds and 4
> > minutes to complete. Most of times, when I run the query for the first
> time
> > after the server initialisation, it takes 20 seconds; but if I re-run it
> > again (without changing anything) right after the first execution, the
> > probability to take more than 4 minutes is very high.
>
> On Tue, Mar 09, 2021 at 11:58:05PM +0100, Francesco De Angelis wrote:
> > 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),
>
> You said it takes between 20s and 4min (240s), but both the explain analyze
> show ~1300s.
>
> explain analyze can be slower than the query, due to timing overhead.
> Is that what's happening here? You could try explain(analyze,timing
> off,buffers).
> You should send a result for the "20sec" result, and one for the "4min"
> result,
> to compare.
>
> I assume the crash is a result of OOM - you could find the result in dmesg
> output ("Out of memory: Killed process") or the postgres logfile will say
> "terminated by signal 9: Killed". It's important to avoid setting
> work_mem so
> high that the process is killed and has to go into recovery mode.
>
> --
> Justin
>
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: Fwd: different execution time for the same query (and same DB status)
@ 2021-03-10 13:29 Michael Lewis <mlewis@entrata.com>
parent: Francesco De Angelis <franc.tozzus@gmail.com>
0 siblings, 1 reply; 10+ messages in thread
From: Michael Lewis @ 2021-03-10 13:29 UTC (permalink / raw)
To: Francesco De Angelis <franc.tozzus@gmail.com>; +Cc: Justin Pryzby <pryzby@telsasoft.com>; Pgsql Performance <pgsql-performance@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>; Julien Rouhaud <rjuju123@gmail.com>; Michel SALAIS <msalais@msym.fr>
I would increase shared_buffers to 1GB or more. Also, it would be very
interesting to see these queries executed with JIT off.
^ permalink raw reply [nested|flat] 10+ messages in thread
* Re: Fwd: different execution time for the same query (and same DB status)
@ 2021-03-12 13:39 Francesco De Angelis <franc.tozzus@gmail.com>
parent: Michael Lewis <mlewis@entrata.com>
0 siblings, 0 replies; 10+ messages in thread
From: Francesco De Angelis @ 2021-03-12 13:39 UTC (permalink / raw)
To: Michael Lewis <mlewis@entrata.com>; +Cc: Justin Pryzby <pryzby@telsasoft.com>; Pgsql Performance <pgsql-performance@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>; Julien Rouhaud <rjuju123@gmail.com>; Michel SALAIS <msalais@msym.fr>
I have re-tested the execution times with several different values of
shared_buffers in the range 256 MB - 4 GB.
It didn't solve the problem and I noticed that for values greater than 3GB
the executions halt very frequently.
I also tried to disable JIT and this further slowed it down.
But there is an interesting news. I managed to exploit some properties of
the data I am modelling and I have changed the types of the tables and the
query as follows:
CREATE TABLE A (
a1 int2,
a2 int2,
v int4 primary key
);
CREATE TABLE B (
a1 int2,
a2 int2,
v int4 primary key
);
create index hash_pkA on A using hash(v);
create index hash_pkB on B using hash(v);
CREATE TABLE C (
la1 int2,
la2 int2,
va1 int2,
va2 int2,
res text,
c int8
);
create index hash_C on C using hash(c);
select count(*) from (
((select A.v,
coalesce(A.a1,0) as la1,
coalesce(A.a2,0) as la2,
coalesce(B.a1,0) as va1,
coalesce(B.a2,0) as va2
from A
left join B on A.v = B.v)
union all
select B.v,
0 as la1,
0 as la2,
B.a1 as va1,
B.a2 as va2
from B where B.v not in (select A.v from A))as
ta inner join C on
ta.la1 | (ta.la2::int8 << 10) |
(ta.va1::int8 << 20) |
(ta.va2::int8 << 30)
= C.c);
With these changes I get stable results around 15 seconds. Here is the
plan: https://explain.depesz.com/s/Y9dT.
I also verified that I can decrease work_mem to 300MB (against 800MB of the
original query) by keeping the same execution time. In the original one,
decreasing such a value worsens the overall performances instead.
In the new query there is only one comparison on a single column (they were
four in the original one) and I started guessing whether, in the previous
case, the DBMS considers the overall memory consumption is too high and
changes the plan. If yes, I would be interesting in understanding how the
optimisation algorithm works and whether there is a way to disable it.
In this way I can try to better figure out what to do, in the future, in
case the data model cannot be re-arranged like in this case.
Thanks again.
Best regards,
Francesco De Angelis
Il giorno mer 10 mar 2021 alle ore 14:29 Michael Lewis <mlewis@entrata.com>
ha scritto:
> I would increase shared_buffers to 1GB or more. Also, it would be very
> interesting to see these queries executed with JIT off.
>
^ permalink raw reply [nested|flat] 10+ messages in thread
end of thread, other threads:[~2021-03-12 13:39 UTC | newest]
Thread overview: 10+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-03-06 21:40 Fwd: different execution time for the same query (and same DB status) Francesco De Angelis <franc.tozzus@gmail.com>
2021-03-07 14:51 ` Michel SALAIS <msalais@msym.fr>
2021-03-07 15:08 ` Julien Rouhaud <rjuju123@gmail.com>
2021-03-07 16:37 ` Tom Lane <tgl@sss.pgh.pa.us>
2021-03-08 17:03 ` Michael Lewis <mlewis@entrata.com>
2021-03-09 22:58 ` Francesco De Angelis <franc.tozzus@gmail.com>
2021-03-10 08:27 ` Justin Pryzby <pryzby@telsasoft.com>
2021-03-10 11:48 ` Francesco De Angelis <franc.tozzus@gmail.com>
2021-03-10 13:29 ` Michael Lewis <mlewis@entrata.com>
2021-03-12 13:39 ` Francesco De Angelis <franc.tozzus@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox