Bad plan for ltree predicate <@

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(at)%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)