pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedLong Running Commits
2+ messages / 2 participants
[nested] [flat]
* Long Running Commits
@ 2009-03-04 16:18 Brad Nicholson <bnichols@ca.afilias.info>
0 siblings, 0 replies; 2+ messages in thread
From: Brad Nicholson @ 2009-03-04 16:18 UTC (permalink / raw)
To: pgsql-performance
Running PG 8.1.11 on AIX 5.3
Trying to track down the cause of long running commits on one of our DB servers.
I can rule checkpoints out (I've set log_min_messages to debug2 and the commits are not happening during checkpoints).
We have this problem over a period of ~ 35 minutes per day only. during that period we have no change in our write load, but we do have substantial
increase in reads on one table (pretty much all being served by index scans from the buffer pool - which most likely points to a shift
in activity over the time period, and not the problem itself).
Over the same time, we also see an abnormally large number of connections being opened and closed. We can see this in the DB connection pool
logs as well as the DB logs). This is most likely being driven by the activity shift that we can see in the stats.
What we do see is connections being opened and closed rapidly during this same period of time (DB logs below). I'm wondering if the
commits are waiting on something at the file system level due to the processes.
Ulimit settings on the server:
ulimit -a
core file size (blocks, -c) soft
data seg size (kbytes, -d) soft
file size (blocks, -f) unlimited
max memory size (kbytes, -m) hard
open files (-n) 4096
pipe size (512 bytes, -p) 64
stack size (kbytes, -s) soft
cpu time (seconds, -t) unlimited
max user processes (-u) 10240
virtual memory (kbytes, -v) unlimited
DB logs:
2009-03-04 09:56:13.465 CUT [561402] DEBUG: forked new backend, pid=794696 socket=9
2009-03-04 09:56:13.645 CUT [561402] DEBUG: forked new backend, pid=2101474 socket=9
2009-03-04 09:56:13.645 CUT [561402] DEBUG: server process (PID 516334) exited with exit code 0
2009-03-04 09:56:13.646 CUT [561402] DEBUG: server process (PID 1458332) exited with exit code 0
2009-03-04 09:56:13.646 CUT [561402] DEBUG: server process (PID 2174998) exited with exit code 0
2009-03-04 09:56:13.647 CUT [561402] DEBUG: server process (PID 1519662) exited with exit code 0
2009-03-04 09:56:13.647 CUT [561402] DEBUG: server process (PID 1646618) exited with exit code 0
2009-03-04 09:56:13.647 CUT [561402] DEBUG: server process (PID 999648) exited with exit code 0
2009-03-04 09:56:13.648 CUT [561402] DEBUG: server process (PID 2285774) exited with exit code 0
2009-03-04 09:56:13.648 CUT [561402] DEBUG: server process (PID 1622108) exited with exit code 0
2009-03-04 09:56:13.648 CUT [561402] DEBUG: server process (PID 1024216) exited with exit code 0
2009-03-04 09:56:13.649 CUT [561402] DEBUG: server process (PID 1392706) exited with exit code 0
2009-03-04 09:56:13.665 CUT [561402] DEBUG: forked new backend, pid=1392708 socket=9
2009-03-04 09:56:13.666 CUT [561402] DEBUG: server process (PID 1773680) exited with exit code 0
2009-03-04 09:56:13.669 CUT [561402] DEBUG: forked new backend, pid=1773682 socket=9
2009-03-04 09:56:13.805 CUT [561402] DEBUG: forked new backend, pid=1024218 socket=9
2009-03-04 09:56:13.805 CUT [561402] DEBUG: server process (PID 1589374) exited with exit code 0
2009-03-04 09:56:13.806 CUT [561402] DEBUG: server process (PID 995536) exited with exit code 0
2009-03-04 09:56:13.806 CUT [561402] DEBUG: server process (PID 688336) exited with exit code 0
2009-03-04 09:56:13.806 CUT [561402] DEBUG: server process (PID 2035798) exited with exit code 0
2009-03-04 09:56:13.807 CUT [561402] DEBUG: server process (PID 1429700) exited with exit code 0
2009-03-04 09:56:13.807 CUT [561402] DEBUG: server process (PID 2043960) exited with exit code 0
2009-03-04 09:56:13.807 CUT [561402] DEBUG: server process (PID 2158782) exited with exit code 0
2009-03-04 09:56:13.808 CUT [561402] DEBUG: server process (PID 2306144) exited with exit code 0
2009-03-04 09:56:13.808 CUT [561402] DEBUG: server process (PID 884978) exited with exit code 0
2009-03-04 09:56:13.808 CUT [561402] DEBUG: server process (PID 1781930) exited with exit code 0
2009-03-04 09:56:13.809 CUT [561402] DEBUG: server process (PID 2277572) exited with exit code 0
2009-03-04 09:56:13.809 CUT [561402] DEBUG: server process (PID 663656) exited with exit code 0
2009-03-04 09:56:13.809 CUT [561402] DEBUG: server process (PID 2343006) exited with exit code 0
2009-03-04 09:56:13.810 CUT [561402] DEBUG: server process (PID 889026) exited with exit code 0
2009-03-04 09:56:13.810 CUT [561402] DEBUG: server process (PID 2404546) exited with exit code 0
2009-03-04 09:56:13.810 CUT [561402] DEBUG: server process (PID 581830) exited with exit code 0
2009-03-04 09:56:13.811 CUT [561402] DEBUG: server process (PID 1433846) exited with exit code 0
2009-03-04 09:56:13.811 CUT [561402] DEBUG: server process (PID 667690) exited with exit code 0
2009-03-04 09:56:13.932 CUT [561402] DEBUG: forked new backend, pid=667692 socket=9
2009-03-04 09:56:13.933 CUT [561402] DEBUG: server process (PID 864402) exited with exit code 0
2009-03-04 09:56:13.933 CUT [561402] DEBUG: server process (PID 594124) exited with exit code 0
2009-03-04 09:56:13.934 CUT [561402] DEBUG: server process (PID 852202) exited with exit code 0
2009-03-04 09:56:13.935 CUT [561402] DEBUG: server process (PID 2433156) exited with exit code 0
2009-03-04 09:56:13.935 CUT [561402] DEBUG: server process (PID 2216120) exited with exit code 0
2009-03-04 09:56:13.936 CUT [561402] DEBUG: server process (PID 1761484) exited with exit code 0
2009-03-04 09:56:13.936 CUT [561402] DEBUG: server process (PID 815268) exited with exit code 0
2009-03-04 09:56:13.936 CUT [561402] DEBUG: server process (PID 876668) exited with exit code 0
2009-03-04 09:56:13.937 CUT [561402] DEBUG: server process (PID 897060) exited with exit code 0
2009-03-04 09:56:13.937 CUT [561402] DEBUG: server process (PID 2199742) exited with exit code 0
2009-03-04 09:56:13.937 CUT [561402] DEBUG: server process (PID 913618) exited with exit code 0
2009-03-04 09:56:13.937 CUT [561402] DEBUG: server process (PID 2334774) exited with exit code 0
2009-03-04 09:56:13.984 CUT [561402] DEBUG: forked new backend, pid=2334776 socket=9
2009-03-04 09:56:14.065 CUT [602282] appdb appuser 1.2.3.3 LOG: duration: 872.457 ms statement: EXECUTE <unnamed> [PREPARE: commit]
2009-03-04 09:56:14.065 CUT [868552] appdb appuser 1.2.3.4 LOG: duration: 873.756 ms statement: EXECUTE <unnamed> [PREPARE: commit]
2009-03-04 09:56:14.075 CUT [2212000] appdb appuser 1.2.3.5 LOG: duration: 586.276 ms statement: EXECUTE <unnamed> [PREPARE: commit]
2009-03-04 09:56:14.076 CUT [561402] DEBUG: forked new backend, pid=913620 socket=9
2009-03-04 09:56:14.095 CUT [561402] DEBUG: forked new backend, pid=782510 socket=9
2009-03-04 09:56:14.106 CUT [561402] DEBUG: forked new backend, pid=2285776 socket=9
2009-03-04 09:56:14.179 CUT [561402] DEBUG: forked new backend, pid=999650 socket=9
2009-03-04 09:56:14.194 CUT [561402] DEBUG: forked new backend, pid=1646620 socket=9
2009-03-04 09:56:14.245 CUT [561402] DEBUG: forked new backend, pid=921634 socket=9
2009-03-04 09:56:14.255 CUT [561402] DEBUG: forked new backend, pid=1257600 socket=9
2009-03-04 09:56:14.265 CUT [561402] DEBUG: forked new backend, pid=1622114 socket=9
2009-03-04 09:56:14.325 CUT [561402] DEBUG: forked new backend, pid=1519664 socket=9
2009-03-04 09:56:14.326 CUT [561402] DEBUG: forked new backend, pid=1839238 socket=9
2009-03-04 09:56:14.335 CUT [561402] DEBUG: forked new backend, pid=2412680 socket=9
2009-03-04 09:56:14.425 CUT [561402] DEBUG: forked new backend, pid=2007238 socket=9
2009-03-04 09:56:14.426 CUT [561402] DEBUG: server process (PID 2363424) exited with exit code 0
2009-03-04 09:56:14.426 CUT [561402] DEBUG: server process (PID 1749056) exited with exit code 0
2009-03-04 09:56:14.426 CUT [561402] DEBUG: server process (PID 2056242) exited with exit code 0
2009-03-04 09:56:14.427 CUT [561402] DEBUG: server process (PID 770156) exited with exit code 0
2009-03-04 09:56:14.433 CUT [561402] DEBUG: forked new backend, pid=770158 socket=9
2009-03-04 09:56:14.433 CUT [561402] DEBUG: server process (PID 2379944) exited with exit code 0
2009-03-04 09:56:14.484 CUT [561402] DEBUG: forked new backend, pid=2379946 socket=9
2009-03-04 09:56:14.485 CUT [561402] DEBUG: server process (PID 1130616) exited with exit code 0
2009-03-04 09:56:14.494 CUT [561402] DEBUG: forked new backend, pid=1130618 socket=9
2009-03-04 09:56:14.505 CUT [561402] DEBUG: forked new backend, pid=516338 socket=9
2009-03-04 09:56:14.506 CUT [561402] DEBUG: forked new backend, pid=2199744 socket=9
--
Brad Nicholson 416-673-4106
Database Administrator, Afilias Canada Corp.
^ permalink raw reply [nested|flat] 2+ messages in thread
* The wrong (?) query plan for queries with remote (postgres_fdw) tables
@ 2019-05-14 16:08 Vitaly Baranovsky <barvetalforums@gmail.com>
0 siblings, 0 replies; 2+ messages in thread
From: Vitaly Baranovsky @ 2019-05-14 16:08 UTC (permalink / raw)
To: pgsql-performance@lists.postgresql.org
Hello,
I have an inefficient query execution for queries with postgres_fdw.
I have an ineffective query with remote tables (postgres_fdw) that works
for about 1 second. The same query with local tables (with the same data)
instead of foreign ones has execution time less than 5 ms. So, the
difference is almost 200 times.
So, the query works with 3 tables. 2 of them are remote, 1 is a local one.
Remote db (works on the same Postgres instance):
foreign_table
foreign_filter_table
Local db:
local_table
The idea that local_table and foreign_table have the same structure. They
have 2 columns: primary key (primary_uuid) and foreign key (fkey_uuid).
Also, we have foreign_filter_table, that is a master table for 2 tables
mentioned above. In addition to the primary key (primary_uuid), it also has
a column filter_uuid.
What is the aim of a query: to filter the master table by filter_uuid, and
then select corresponding data from unioned (union all) local_table and
foreign_table, and make pagination sorted by the foreign key.
The master table (foreign_filter_table) contains 100K records. Slave tables
contain about 100K records each, where they refer to about 5% of master
table (each slave table contains 20 rows for 5% of master table rows).
Note, use_remote_estimate is true for the foreign server.
Logically, query execution should be: select rows from the master query and
make merge join between them. It works this way when I use local tables
instead of remote ones.
But with foreign tables it union child tables first, and then make a nested
loop for each row with the mater table. As a result, the query becomes very
slow...
So, the query is:
select *
from
(select * from local_table lt
union all
select * from foreign_server.foreign_table ft) a
join foreign_server.foreign_filter_table on a.fkey_uuid =
foreign_server.foreign_filter_table.primary_uuid
where foreign_server.foreign_filter_table.filter_uuid between
'56c77b02-8309-42f1-ae02-8d6922ea7dba' and
'67c77b02-8309-42f1-ae02-8d6922ea7dba'
order by a.fkey_uuid
limit 10 offset 90
A query plan is:
"Limit (cost=527.23..563.45 rows=10 width=80) (actual
time=915.919..920.302 rows=10 loops=1)"
" Output: lt.fkey_uuid, lt.primary_uuid,
foreign_filter_table.primary_uuid, foreign_filter_table.filter_uuid,
lt.fkey_uuid"
" Buffers: shared hit=949"
" -> Nested Loop (cost=201.28..20859148.42 rows=5759398 width=80) (actual
time=118.138..920.282 rows=100 loops=1)"
" Output: lt.fkey_uuid, lt.primary_uuid,
foreign_filter_table.primary_uuid, foreign_filter_table.filter_uuid,
lt.fkey_uuid"
" Buffers: shared hit=949"
" -> Merge Append (cost=100.85..19272.58 rows=192108 width=32)
(actual time=1.133..16.119 rows=1864 loops=1)"
" Sort Key: lt.fkey_uuid"
" Buffers: shared hit=949"
" -> Index Scan using fkey_uuid_idx on public.local_table lt
(cost=0.42..8937.22 rows=96054 width=32) (actual time=0.021..5.159
rows=940 loops=1)"
" Output: lt.fkey_uuid, lt.primary_uuid"
" Buffers: shared hit=949"
" -> Foreign Scan on foreign_server.foreign_table ft
(cost=100.42..8414.27 rows=96054 width=32) (actual time=1.109..9.756
rows=925 loops=1)"
" Output: ft.fkey_uuid, ft.primary_uuid"
" Remote SQL: SELECT fkey_uuid, primary_uuid FROM
public.foreign_table ORDER BY fkey_uuid ASC NULLS LAST"
" -> Foreign Scan on foreign_server.foreign_filter_table
(cost=100.43..108.47 rows=1 width=32) (actual time=0.380..0.380 rows=0
loops=1864)"
" Output: foreign_filter_table.primary_uuid,
foreign_filter_table.filter_uuid"
" Remote SQL: SELECT primary_uuid, filter_uuid FROM
public.foreign_filter_table WHERE ((filter_uuid >=
'56c77b02-8309-42f1-ae02-8d6922ea7dba'::uuid)) AND ((filter_uuid <=
'67c77b02-8309-42f1-ae02-8d6922ea7dba'::uuid)) AND (($1::uuid = primary_u
(...)"
"Planning Time: 1.825 ms"
"Execution Time: 920.617 ms"
But, when I do the same locally on a remote database with a query:
select *
from
(select * from foreign_table ft) a
join foreign_filter_table on a.fkey_uuid = foreign_filter_table.primary_uuid
where foreign_filter_table.filter_uuid between
'57c77b02-8309-42f1-ae02-8d6922ea7dba' and
'67c77b02-8309-42f1-ae02-8d6922ea7dba'
order by a.fkey_uuid
limit 10 offset 90
I get a query plan:
"Limit (cost=248.72..272.37 rows=10 width=80) (actual time=4.366..4.384
rows=10 loops=1)"
" Output: ft.fkey_uuid, ft.primary_uuid,
foreign_filter_table.primary_uuid, foreign_filter_table.filter_uuid,
ft.fkey_uuid"
" -> Merge Join (cost=35.91..13665.71 rows=5764 width=80) (actual
time=0.558..4.378 rows=100 loops=1)"
" Output: ft.fkey_uuid, ft.primary_uuid,
foreign_filter_table.primary_uuid, foreign_filter_table.filter_uuid,
ft.fkey_uuid"
" Inner Unique: true"
" Merge Cond: (ft.fkey_uuid = foreign_filter_table.primary_uuid)"
" -> Index Scan using fkey_uuid_idx on public.foreign_table ft
(cost=0.42..6393.19 rows=96054 width=32) (actual time=0.005..2.556
rows=1297 loops=1)"
" Output: ft.fkey_uuid, ft.primary_uuid"
" -> Index Scan using filter_table_pk on public.foreign_filter_table
(cost=0.42..6994.83 rows=5996 width=32) (actual time=0.043..1.684 rows=85
loops=1)"
" Output: foreign_filter_table.primary_uuid,
foreign_filter_table.filter_uuid"
" Filter: ((foreign_filter_table.filter_uuid >=
'57c77b02-8309-42f1-ae02-8d6922ea7dba'::uuid) AND
(foreign_filter_table.filter_uuid <=
'67c77b02-8309-42f1-ae02-8d6922ea7dba'::uuid))"
" Rows Removed by Filter: 1095"
"Planning Time: 1.816 ms"
"Execution Time: 4.605 ms"
So, why the behavior of the Postgres is like this? How can I optimize such
a query? It looks like query optimizer builds an ineffective plan, but
maybe I’m wrong
Thank you.
P.S.: scripts are attached
ᐧ
-- FOREIGN DATABASE
-- Table: public.foreign_table
CREATE TABLE public.foreign_table
(
fkey_uuid uuid NOT NULL,
primary_uuid uuid NOT NULL,
CONSTRAINT pkey PRIMARY KEY (primary_uuid)
);
CREATE INDEX fkey_uuid_idx
ON public.foreign_table
USING btree
(fkey_uuid);
-- Table: public.foreign_filter_table
CREATE TABLE public.foreign_filter_table
(
primary_uuid uuid NOT NULL,
filter_uuid uuid,
CONSTRAINT filter_table_pk PRIMARY KEY (primary_uuid)
)
CREATE INDEX filter_uuid_idx
ON public.foreign_filter_table
USING btree
(filter_uuid);
-- LOCAL DATABASE
-- Table: public.local_table
CREATE TABLE public.local_table
(
fkey_uuid uuid NOT NULL,
primary_uuid uuid NOT NULL,
CONSTRAINT pkey PRIMARY KEY (primary_uuid)
)
CREATE INDEX fkey_uuid_idx
ON public.local_table
USING btree
(fkey_uuid);
-- DATA Generation
create extension "uuid-ossp";
insert into foreign_filter_table
select uuid_generate_v4(), uuid_generate_v4()
FROM generate_series(1,100000)
insert into local_table (primary_uuid, fkey_uuid)
select uuid_generate_v4(), primary_uuid from
(
select primary_uuid
from foreign_server.foreign_filter_table
where (('x'||substr(md5(primary_uuid::text),1,8))::bit(32)::int)%20 = 0
)a,
(
select 0
from generate_series(0, 20)
)b
insert into foreign_server.foreign_table (primary_uuid, fkey_uuid)
select uuid_generate_v4(), primary_uuid from
(
select primary_uuid
from foreign_server.foreign_filter_table
where (('x'||substr(md5(primary_uuid::text),1,8))::bit(32)::int)%20 = 0
)a,
(
select 0
from generate_series(0, 20)
)b
Attachments:
[text/plain] Pagination query problem.sql (1.7K, ../../CALWbrdESymKzGOVHq1RAJnS_fy5i3R2of0uMdfb1596M9k2D0g@mail.gmail.com/3-Pagination%20query%20problem.sql)
download | inline:
-- FOREIGN DATABASE
-- Table: public.foreign_table
CREATE TABLE public.foreign_table
(
fkey_uuid uuid NOT NULL,
primary_uuid uuid NOT NULL,
CONSTRAINT pkey PRIMARY KEY (primary_uuid)
);
CREATE INDEX fkey_uuid_idx
ON public.foreign_table
USING btree
(fkey_uuid);
-- Table: public.foreign_filter_table
CREATE TABLE public.foreign_filter_table
(
primary_uuid uuid NOT NULL,
filter_uuid uuid,
CONSTRAINT filter_table_pk PRIMARY KEY (primary_uuid)
)
CREATE INDEX filter_uuid_idx
ON public.foreign_filter_table
USING btree
(filter_uuid);
-- LOCAL DATABASE
-- Table: public.local_table
CREATE TABLE public.local_table
(
fkey_uuid uuid NOT NULL,
primary_uuid uuid NOT NULL,
CONSTRAINT pkey PRIMARY KEY (primary_uuid)
)
CREATE INDEX fkey_uuid_idx
ON public.local_table
USING btree
(fkey_uuid);
-- DATA Generation
create extension "uuid-ossp";
insert into foreign_filter_table
select uuid_generate_v4(), uuid_generate_v4()
FROM generate_series(1,100000)
insert into local_table (primary_uuid, fkey_uuid)
select uuid_generate_v4(), primary_uuid from
(
select primary_uuid
from foreign_server.foreign_filter_table
where (('x'||substr(md5(primary_uuid::text),1,8))::bit(32)::int)%20 = 0
)a,
(
select 0
from generate_series(0, 20)
)b
insert into foreign_server.foreign_table (primary_uuid, fkey_uuid)
select uuid_generate_v4(), primary_uuid from
(
select primary_uuid
from foreign_server.foreign_filter_table
where (('x'||substr(md5(primary_uuid::text),1,8))::bit(32)::int)%20 = 0
)a,
(
select 0
from generate_series(0, 20)
)b
^ permalink raw reply [nested|flat] 2+ messages in thread
end of thread, other threads:[~2019-05-14 16:08 UTC | newest]
Thread overview: 2+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2009-03-04 16:18 Long Running Commits Brad Nicholson <bnichols@ca.afilias.info>
2019-05-14 16:08 The wrong (?) query plan for queries with remote (postgres_fdw) tables Vitaly Baranovsky <barvetalforums@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