pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedBad plan for ltree predicate <@
3+ messages / 2 participants
[nested] [flat]
* Bad plan for ltree predicate <@
@ 2017-12-01 17:20 Roman Konoval <rkonoval@gmail.com>
2017-12-01 21:33 ` Re: Bad plan for ltree predicate <@ Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 3+ messages in thread
From: Roman Konoval @ 2017-12-01 17:20 UTC (permalink / raw)
To: pgsql-performance@lists.postgresql.org
Hi,
I have a problem on 9.3.14 with a query that accesses table:
Size: (retrieved by query https://gist.github.com/romank0/74f9d1d807bd3f41c0729d0fc6126749)
schemaname | relname | size | toast | associated_idx_size | total
------------+---------------+--------+--------+---------------------+---------
public | document_head | 275 MB | 630 MB | 439 MB | 1345 MB
Definition:
Table "public.document_head"
Column | Type | Modifiers
-----------------------------+--------------------------+-------------------------------------
snapshot_id | character varying(36) | not null
id | character varying(36) | not null
base_type | character varying(50) | not null
is_cascade | boolean | not null default false
parent_id | character varying(36) |
fileplan_node_id | character varying(36) |
state | character varying(10) | default 'ACTIVE'::character varying
title | character varying(4096) | not null
properties | text | not null
properties_cache | hstore | not null
serial_number | integer | not null
major_version | integer | not null
minor_version | integer | not null
version_description | text |
sensitivity | integer | not null default 10
id_path | ltree |
path_name | character varying(4096) | collate C not null
ltx_id | bigint | not null
created_by | integer | not null
created_date | timestamp with time zone | not null
modified_by | integer | not null
modified_date | timestamp with time zone | not null
responsible_user_ids | integer[] |
origin_id | character varying(36) |
origin_snapshot_id | character varying(36) |
ssn | character varying(64) |
record_physical_location | text |
record_physical_location_id | text |
record_created_date | timestamp with time zone |
record_aggregated_date | timestamp with time zone |
record_last_review_comment | text |
record_last_review_date | timestamp with time zone |
record_next_review_date | timestamp with time zone |
record_originated_date | timestamp with time zone |
record_is_vital | boolean | not null default false
storage_plan_state | text | not null default 'New'::text
cut_off_date | timestamp with time zone |
dispose_date | timestamp with time zone |
archive_date | timestamp with time zone |
Indexes:
"document_head__id__uniq_key" PRIMARY KEY, btree (id)
"document_head__parent_id__path_name__unq_idx" UNIQUE, btree (parent_id, path_name) WHERE state::text = 'ACTIVE'::text
"document_head__snapshot_id__unq" UNIQUE, btree (snapshot_id)
"document_head__base_type__idx" btree (base_type) WHERE state::text <> 'DELETED'::text
"document_head__fileplan_node_id__idx" btree (fileplan_node_id)
"document_head__id__idx" btree (id) WHERE state::text <> 'DELETED'::text
"document_head__id_path__btree__idx" btree (id_path) WHERE state::text <> 'DELETED'::text
"document_head__id_path__gist__idx" gist (id_path)
"document_head__ltx_id__idx" btree (ltx_id)
"document_head__origin_id__hotfix__idx" btree (origin_id) WHERE origin_id IS NOT NULL
"document_head__origin_id__idx" btree (origin_id) WHERE state::text <> 'DELETED'::text AND origin_id IS NOT NULL
"document_head__parent_id__idx" btree (parent_id)
"document_head__properties_cache__contact_username_idx" btree ((properties_cache -> 'person_meta_info.username'::text)) WHERE base_type::text = 'Contact'::text AND exist(properties_cache, 'person_meta_info.username'::text)
"document_head__properties_cache__emailmeta_message_id__idx" btree ((properties_cache -> 'emailmeta.message_id'::text)) WHERE base_type::text = 'File'::text AND exist(properties_cache, 'emailmeta.message_id'::text)
"document_head__properties_cache__idx" gist (properties_cache) WHERE state::text <> 'DELETED'::text
"document_head__properties_cache__project_identifier__idx" btree ((properties_cache -> 'project.identifier'::text)) WHERE base_type::text = 'Project'::text AND exist(properties_cache, 'project.identifier'::text)
"document_head__properties_cache__published_origin__idx" btree ((properties_cache -> 'file_published_origin_id.origin_id'::text)) WHERE base_type::text = 'File'::text AND exist(properties_cache, 'file_published_origin_id.origin_id'::text)
"document_head__state__idx" btree (state)
"document_head__storage_plan_state__idx" btree (storage_plan_state) WHERE state::text <> 'DELETED'::text
Check constraints:
"document_base_storage_plan_state_check" CHECK (storage_plan_state = ANY (ARRAY['NEW'::text, 'READY_FOR_CUTOFF'::text, 'CUTOFF'::text, 'READY_FOR_DISPOSITION'::text, 'DISPOSED'::text]))
"document_head__sensitivity_check" CHECK (sensitivity = ANY (ARRAY[10, 20, 30]))
Foreign-key constraints:
"document_head__created_by__fk" FOREIGN KEY (created_by) REFERENCES auth_user(id)
"document_head__modified_by__fk" FOREIGN KEY (modified_by) REFERENCES auth_user(id)
"document_head__parent_id__fk" FOREIGN KEY (parent_id) REFERENCES document(id)
Some notes:
1. properties stores json that for some records may be as large as 300k
select count(*) from document_head where length(properties) > 100000;
count
-------
535
(1 row)
select count(*) from document_head where length(properties) > 20000;
count
-------
13917
(1 row)
select count(*) from document_head where length(properties) > 1000;
count
-------
51708
(1 row)
select count(*) from document_head where length(properties) > 300000;
count
-------
3
(1 row)
select max(length(properties)) from document_head;
max
--------
334976
(1 row)
2. properties_cache stores parsed properties: key is jsonpath of a key in json and value is a value.
3. all results here are retrieved after running `analyze document_head` and `vacuum document_head` manually.
4. I tried different work_mem settings up to 100MB and there's no effect on the main issue described below.
5. I haven't tested disks speed as first of all I think it is irrelevant to the problem and it is not easy to do as this is production system.
The function that is used in the query:
CREATE OR REPLACE FUNCTION public.get_doc_path(document_id character varying)
RETURNS ltree
LANGUAGE plpgsql
STABLE
AS $function$
DECLARE
path ltree;
BEGIN
select id_path into path from document_head where id = document_id;
RETURN path;
END $function$
The original query is rather big one and the simplified version where the issue can still be demonstrated is:
explain (analyze, buffers)
with trees AS (
SELECT d.id, d.snapshot_id , NULL :: text[] AS permissions
FROM document_head AS d
WHERE (d.id_path <@ get_doc_path('78157c60-45bc-42c1-9aad-c5651995db5c')
AND d.id != '78157c60-45bc-42c1-9aad-c5651995db5c') AND d.state != 'DELETED'
)
SELECT COUNT(*) FROM trees;
I get this plan https://explain.depesz.com/s/UQX4h
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=86227.19..86227.20 rows=1 width=0) (actual time=3878.775..3878.776 rows=1 loops=1)
Buffers: shared hit=747698, temp written=1587
CTE trees
-> Seq Scan on document_head d (cost=0.00..82718.21 rows=155955 width=74) (actual time=0.211..3620.044 rows=154840 loops=1)
Filter: (((id)::text <> '78157c60-45bc-42c1-9aad-c5651995db5c'::text) AND ((state)::text <> 'DELETED'::text) AND (id_path <@ get_doc_path('78157c60-45bc-42c1-9aad-c5651995db5c'::character varying)))
Rows Removed by Filter: 23357
Buffers: shared hit=747698
-> CTE Scan on trees (cost=0.00..3119.10 rows=155955 width=0) (actual time=0.215..3828.519 rows=154840 loops=1)
Buffers: shared hit=747698, temp written=1587
Total runtime: 3881.781 ms
(10 rows)
If I change the predicate for ltree to use subquery the plan and execution time changes:
explain (analyze, buffers)
with trees AS (
SELECT d.id, d.snapshot_id , NULL :: text[] AS permissions
FROM document_head AS d
WHERE (d.id_path <@ (select get_doc_path('78157c60-45bc-42c1-9aad-c5651995db5c'))
AND d.id != '78157c60-45bc-42c1-9aad-c5651995db5c') AND d.state != 'DELETED'
)
SELECT COUNT(*) FROM trees;
https://explain.depesz.com/s/eUR
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=763.19..763.20 rows=1 width=0) (actual time=430.519..430.519 rows=1 loops=1)
Buffers: shared hit=47768, temp written=1587
CTE trees
-> Bitmap Heap Scan on document_head d (cost=82.05..759.20 rows=177 width=74) (actual time=70.703..249.419 rows=154840 loops=1)
Recheck Cond: (id_path <@ $0)
Rows Removed by Index Recheck: 11698
Filter: (((id)::text <> '78157c60-45bc-42c1-9aad-c5651995db5c'::text) AND ((state)::text <> 'DELETED'::text))
Rows Removed by Filter: 23
Buffers: shared hit=47768
InitPlan 1 (returns $0)
-> Result (cost=0.00..0.26 rows=1 width=0) (actual time=0.083..0.084 rows=1 loops=1)
Buffers: shared hit=4
-> Bitmap Index Scan on document_head__id_path__gist__idx (cost=0.00..81.74 rows=178 width=0) (actual time=68.326..68.326 rows=159979 loops=1)
Index Cond: (id_path <@ $0)
Buffers: shared hit=16238
-> CTE Scan on trees (cost=0.00..3.54 rows=177 width=0) (actual time=70.707..388.714 rows=154840 loops=1)
Buffers: shared hit=47768, temp written=1587
Total runtime: 433.410 ms
(18 rows)
I can see that:
1. both queries return exactly the same data and require the same underlying data to produce the result.
2. when I use subquery postgres cannot estimate the number of records that are going to be found by <@.
3. number of buffers processed by the quicker query is 15 times smaller than on the slow one. I assume that this is the reason the query is slower.
My understanding how the planner works is that it evaluates some plans and calculates cost based on the settings and and available statistics.
Settings define relative cost of operations like random vs sequential io vs processing in memory data.
I assume that it is better to use queries that allows planner to use correct estimations and tune settings so that planner knows correct operations cost.
My questions:
1. how to find out why slow execution requires 15x more buffers.
2. In the slow executin planner either does not consider the plan similar to the quick on or estimates it as worse. How to find out which of thes cases (if any) is true? And what I can try to make planner use better plan?
I understand that one option to try is to upgrade to more recent version and I'm going to test this but this may take a while until the affected production system will get an upgrade.
More information:
OS: Ubuntu 14.04.2 LTS (GNU/Linux 3.13.0-125-generic x86_64)
PG version: PostgreSQL 9.3.14 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.8.2 20140120 (Red Hat 4.8.2-16), 64-bit
History: no history as this is a new query.
Hardware: aws m4.large (2 vCPUs, RAM 8GB) with gp2 (SSD) storage with throughtput up to ~20MB/s.
Non default server settings:
name | current_setting | source
--------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------
application_name | psql | client
archive_command | /etc/rds/dbbin/pgscripts/rds_wal_archive %p | configuration file
archive_mode | on | configuration file
archive_timeout | 5min | configuration file
checkpoint_completion_target | 0.9 | configuration file
checkpoint_segments | 16 | configuration file
client_encoding | UTF8 | client
effective_cache_size | 3987336kB | configuration file
fsync | on | configuration file
hot_standby | off | configuration file
listen_addresses | * | command line
lo_compat_privileges | off | configuration file
log_checkpoints | on | configuration file
log_destination | stderr | configuration file
log_directory | /rdsdbdata/log/error | configuration file
log_file_mode | 0644 | configuration file
log_filename | postgresql.log.%Y-%m-%d-%H | configuration file
log_hostname | on | configuration file
log_line_prefix | %t:%r:%u@%d:[%p]: | configuration file
log_min_duration_statement | 1s | configuration file
log_rotation_age | 1h | configuration file
log_timezone | UTC | configuration file
log_truncate_on_rotation | off | configuration file
logging_collector | on | configuration file
maintenance_work_mem | 127MB | configuration file
max_connections | 1000 | configuration file
max_locks_per_transaction | 64 | configuration file
max_prepared_transactions | 0 | configuration file
max_stack_depth | 6MB | configuration file
max_wal_senders | 5 | configuration file
port | 5432 | configuration file
rds.extensions | btree_gin,btree_gist,chkpass,citext,cube,dblink,dict_int,dict_xsyn,earthdistance,fuzzystrmatch,hstore,intagg,intarray,isn,ltree,pgcrypto,pgrowlocks,pg_stat_statements,pg_trgm,plcoffee,plls,plperl,plpgsql,pltcl,plv8,postgis,postgis_tiger_geocoder,postgis_topology,postgres_fdw,sslinfo,tablefunc,test_parser,tsearch2,unaccent,uuid-ossp | configuration file
rds.internal_databases | rdsadmin,template0 | configuration file
rds.superuser_variables | session_replication_role | configuration file
shared_buffers | 1993664kB | configuration file
shared_preload_libraries | rdsutils | configuration file
ssl | on | configuration file
ssl_ca_file | /rdsdbdata/rds-metadata/ca-cert.pem | configuration file
ssl_cert_file | /rdsdbdata/rds-metadata/server-cert.pem | configuration file
ssl_key_file | /rdsdbdata/rds-metadata/server-key.pem | configuration file
ssl_renegotiation_limit | 0 | configuration file
stats_temp_directory | /rdsdbdata/db/pg_stat_tmp | configuration file
superuser_reserved_connections | 3 | configuration file
synchronous_commit | on | configuration file
TimeZone | UTC | configuration file
unix_socket_directories | /tmp | configuration file
unix_socket_group | rdsdb | configuration file
unix_socket_permissions | 0700 | configuration file
wal_keep_segments | 32 | configuration file
wal_level | hot_standby | configuration file
wal_receiver_timeout | 30s | configuration file
wal_sender_timeout | 30s | configuration file
(52 rows)
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Bad plan for ltree predicate <@
2017-12-01 17:20 Bad plan for ltree predicate <@ Roman Konoval <rkonoval@gmail.com>
@ 2017-12-01 21:33 ` Tom Lane <tgl@sss.pgh.pa.us>
2017-12-02 02:34 ` Re: Bad plan for ltree predicate <@ Roman Konoval <rkonoval@gmail.com>
0 siblings, 1 reply; 3+ messages in thread
From: Tom Lane @ 2017-12-01 21:33 UTC (permalink / raw)
To: Roman Konoval <rkonoval@gmail.com>; +Cc: pgsql-performance@lists.postgresql.org
Roman Konoval <rkonoval@gmail.com> writes:
> I have a problem on 9.3.14 with a query that accesses table:
I think the root of the problem is your intermediate function:
> CREATE OR REPLACE FUNCTION public.get_doc_path(document_id character varying)
> RETURNS ltree
> LANGUAGE plpgsql
> STABLE
> AS $function$
> DECLARE
> path ltree;
> BEGIN
> select id_path into path from document_head where id = document_id;
> RETURN path;
> END $function$
This is quite expensive, as it involves another table search, but the
planner doesn't know that since you've not marked it as having higher than
normal cost. The seqscan formulation of the query results in evaluating
this function afresh at most of the rows, whereas shoving it into an
uncorrelated sub-select causes it to be evaluated only once. That, I
think, and not the seqscan-vs-indexscan aspect, is what makes the bitmap
formulation go faster. Certainly you'd not expect that a bitmap scan that
has to hit most of the rows anyway is going to win over a seqscan.
The fact that the planner goes for a bitmap scan in the second formulation
is an artifact of the fact that it doesn't try to pre-evaluate sub-selects
for selectivity estimation purposes, so you end up with a default estimate
that says that the <@ condition only selects a small fraction of the rows.
Not sure if we should try to change that or not.
I'd suggest setting the function's cost to 1000 or so and seeing if that
doesn't improve matters.
(BTW, what tipped me off to this was that the "buffers hit" count for
the seqscan node was so high, several times more than the actual size
of the table. I couldn't account for that until I realized that the
function itself would be adding a few buffer hits per execution.)
regards, tom lane
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Bad plan for ltree predicate <@
2017-12-01 17:20 Bad plan for ltree predicate <@ Roman Konoval <rkonoval@gmail.com>
2017-12-01 21:33 ` Re: Bad plan for ltree predicate <@ Tom Lane <tgl@sss.pgh.pa.us>
@ 2017-12-02 02:34 ` Roman Konoval <rkonoval@gmail.com>
0 siblings, 0 replies; 3+ messages in thread
From: Roman Konoval @ 2017-12-02 02:34 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance@lists.postgresql.org
Hi Tom,
Thanks for your help.
> On Dec 1, 2017, at 22:33, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
>
> The seqscan formulation of the query results in evaluating
> this function afresh at most of the rows
The function is defined as STABLE. I though that means that there is no need
to reevaluate it on every row as input parameter is the same for every row and
return value will be the same during the same query execution. Do I understand
incorrectly what STABLE means?
Why is the function evaluated more than once?
> , whereas shoving it into an
> uncorrelated sub-select causes it to be evaluated only once. That, I
> think, and not the seqscan-vs-indexscan aspect, is what makes the bitmap
> formulation go faster. Certainly you'd not expect that a bitmap scan that
> has to hit most of the rows anyway is going to win over a seqscan.
>
> The fact that the planner goes for a bitmap scan in the second formulation
> is an artifact of the fact that it doesn't try to pre-evaluate sub-selects
> for selectivity estimation purposes, so you end up with a default estimate
> that says that the <@ condition only selects a small fraction of the rows.
> Not sure if we should try to change that or not.
>
> I'd suggest setting the function's cost to 1000 or so and seeing if that
> doesn't improve matters.
>
If I set function cost to 1000 I get slightly better plan but still 3.5 more buffers are read when compared to bitmap scan which as you wrote one would expect to be slower than seq scan.
Here is the plan:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=216438.81..216438.82 rows=1 width=0) (actual time=1262.244..1262.245 rows=1 loops=1)
Buffers: shared hit=169215
CTE trees
-> Index Scan using document_head__id_path__gist__idx on document_head d (cost=2.91..212787.85 rows=162265 width=74) (actual time=0.115..727.119 rows=154854 loops=1)
Index Cond: (id_path <@ get_doc_path('78157c60-45bc-42c1-9aad-c5651995db5c'::character varying))
Filter: (((id)::text <> '78157c60-45bc-42c1-9aad-c5651995db5c'::text) AND ((state)::text <> 'DELETED'::text))
Rows Removed by Filter: 23
Buffers: shared hit=169215
-> CTE Scan on trees (cost=0.00..3245.30 rows=162265 width=0) (actual time=0.119..1118.899 rows=154854 loops=1)
Buffers: shared hit=169215
Total runtime: 1277.010 ms
(11 rows)
My understanding is that the optimal plan in this case should read less data than bitmap scan by the amount of buffers hit by bitmap index scan.
It should read roughly all buffers of the table itself. Something like the query with predicate using ltree literal instead of function invocation:
explain (analyze, buffers)
with trees AS (
SELECT d.id, d.snapshot_id , NULL :: text[] AS permissions
FROM document_head AS d
WHERE (d.id_path <@ '869c0187_51ae_4deb_a36f_0425fdafda6e.78157c60_45bc_42c1_9aad_c5651995db5c'::ltree AND d.id != '78157c60-45bc-42c1-9aad-c5651995db5c') AND d.state != 'DELETED'
)
SELECT COUNT(*) FROM trees;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=42114.02..42114.03 rows=1 width=0) (actual time=997.427..997.427 rows=1 loops=1)
Buffers: shared hit=35230
CTE trees
-> Seq Scan on document_head d (cost=0.00..38463.06 rows=162265 width=74) (actual time=0.013..593.082 rows=154854 loops=1)
Filter: ((id_path <@ '869c0187_51ae_4deb_a36f_0425fdafda6e.78157c60_45bc_42c1_9aad_c5651995db5c'::ltree) AND ((id)::text <> '78157c60-45bc-42c1-9aad-c5651995db5c'::text) AND ((state)::text <> 'DELETED'::text))
Rows Removed by Filter: 23357
Buffers: shared hit=35230
-> CTE Scan on trees (cost=0.00..3245.30 rows=162265 width=0) (actual time=0.017..888.076 rows=154854 loops=1)
Buffers: shared hit=35230
Total runtime: 1011.565 ms
(10 rows)
The question is if it possible to get plan like that using function or some other way to get ltree value for given document_head.id value in one query?
As an alternative I can get ltree value with the separate query but this would require
1. a round-trip to postgres
2. me to change isolation level to REPEATABLE READ to make sure that I get consistent result
so I would like to avoid that.
Regards,
Roman Konoval=
^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2017-12-02 02:34 UTC | newest]
Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2017-12-01 17:20 Bad plan for ltree predicate <@ Roman Konoval <rkonoval@gmail.com>
2017-12-01 21:33 ` Tom Lane <tgl@sss.pgh.pa.us>
2017-12-02 02:34 ` Roman Konoval <rkonoval@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