Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eKozO-0004R5-V5 for pgsql-performance@arkaria.postgresql.org; Fri, 01 Dec 2017 17:20:39 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eKozO-0003VU-BG for pgsql-performance@arkaria.postgresql.org; Fri, 01 Dec 2017 17:20:38 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1eKozN-0003VI-TW for pgsql-performance@lists.postgresql.org; Fri, 01 Dec 2017 17:20:38 +0000 Received: from mail-wm0-x244.google.com ([2a00:1450:400c:c09::244]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1eKozI-0002FY-Uy for pgsql-performance@lists.postgresql.org; Fri, 01 Dec 2017 17:20:37 +0000 Received: by mail-wm0-x244.google.com with SMTP id g130so6405492wme.0 for ; Fri, 01 Dec 2017 09:20:32 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:subject:message-id:date:to:mime-version; bh=PUsG/pvN5MqZcnvbDGdQq7n30C3Pm8mkx7NgJ9Txato=; b=p4nDrd6CLI3WkpMAfdBhbdvl9LhKEzlshrqX4zVaUSuWsnC4VXGZOAZay/xWsKeRqp okaKpJj196QJpE9oCfKLIjAk9rD1p7AQq/2zcsUjXGt4/5YHmkqNJdadpYBeJyUAIRlS H4OLXgaVnkR/cSqhw3XRMfgwqtJjM6g60rmL8x1tLlBM/JsOzrxyL46goBuBjzTX2PrC ce/UOFmI3+rQ8qOI6nqSIOAb3IkF4umomt887Zde4mPbhcYfMYfvHzeEGwvNm5QaPru8 7n9L38H4HxFCOC3VWWq0F8HKzbTnLejoKKq43vDrmloaQ8iGig8XNuGGl1YixyCH1aYe dp1A== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:subject:message-id:date:to:mime-version; bh=PUsG/pvN5MqZcnvbDGdQq7n30C3Pm8mkx7NgJ9Txato=; b=FeMpWAuavg4zAvXc1TTp4/lFfSinh8yrpii9RfupHdt6bLIi2t8fGmrpAm9I+gxta5 Jk4Q5KgmTOY9CRJfU+GyvebkZE9vW3MYV3mNMIJYIHbVGEWoVdgw880HInRdVTZTk5b3 x3ZAahyBGKhtFqRcGLIHeWhXyQ+wpX1hsmzXezv2lkfoRWywdTDzbKm89Nh+ogHtZS6Y Z60tT/31MZfu+kk13x+/M19oEuE8qMhP4LjggQ4l/BdifK0/F6MELbFE7L/OqHviaTi5 4bv1fKEg9kPR703hK67i84s8LepCAYok3nvVL3jtOw24xBObghea1gTZQFLFbLGMOhUe /i0w== X-Gm-Message-State: AJaThX5ygJ9BsXwLoyOsrXbuCittPS78LRmLwPd5oeE7qWwVzpKeiagM DB9+FpDRlea2O0HMfHgrxdWEYS8/ X-Google-Smtp-Source: AGs4zMZCR/K2lkeGKUutHNwC3R4dH3mSGahp1ro/v2MHozBFTKhR9jLqMfGlb93emYWouSKF8U1q4A== X-Received: by 10.80.240.17 with SMTP id r17mr18559279edl.57.1512148830964; Fri, 01 Dec 2017 09:20:30 -0800 (PST) Received: from ip-172-20-0-14.eu-west-1.compute.internal (ec2-34-241-66-6.eu-west-1.compute.amazonaws.com. [34.241.66.6]) by smtp.gmail.com with ESMTPSA id x49sm8265609edb.76.2017.12.01.09.20.29 for (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Fri, 01 Dec 2017 09:20:29 -0800 (PST) From: Roman Konoval Content-Type: multipart/alternative; boundary="Apple-Mail=_D476EA14-0C61-49EC-8F07-E3C422AE39F3" Subject: Bad plan for ltree predicate <@ Message-Id: <43899CF8-9D4F-4B06-8460-81CC2E0B68E5@gmail.com> Date: Fri, 1 Dec 2017 18:20:28 +0100 To: pgsql-performance@lists.postgresql.org Mime-Version: 1.0 (Mac OS X Mail 9.3 \(3124\)) X-Mailer: Apple Mail (2.3124) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --Apple-Mail=_D476EA14-0C61-49EC-8F07-E3C422AE39F3 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=us-ascii 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 =3D '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 =3D '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 =3D '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 = =3D '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 =3D '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 =3D= ANY (ARRAY['NEW'::text, 'READY_FOR_CUTOFF'::text, 'CUTOFF'::text, = 'READY_FOR_DISPOSITION'::text, 'DISPOSED'::text])) "document_head__sensitivity_check" CHECK (sensitivity =3D 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 =3D = 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')=20 AND d.id !=3D '78157c60-45bc-42c1-9aad-c5651995db5c') AND = d.state !=3D 'DELETED' ) SELECT COUNT(*) FROM trees; I get this plan https://explain.depesz.com/s/UQX4h = QUERY PLAN = --------------------------------------------------------------------------= --------------------------------------------------------------------------= -------------------------------------------------------------- Aggregate (cost=3D86227.19..86227.20 rows=3D1 width=3D0) (actual = time=3D3878.775..3878.776 rows=3D1 loops=3D1) Buffers: shared hit=3D747698, temp written=3D1587 CTE trees -> Seq Scan on document_head d (cost=3D0.00..82718.21 rows=3D155955= width=3D74) (actual time=3D0.211..3620.044 rows=3D154840 loops=3D1) 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=3D747698 -> CTE Scan on trees (cost=3D0.00..3119.10 rows=3D155955 width=3D0) = (actual time=3D0.215..3828.519 rows=3D154840 loops=3D1) Buffers: shared hit=3D747698, temp written=3D1587 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 !=3D '78157c60-45bc-42c1-9aad-c5651995db5c') AND = d.state !=3D 'DELETED' ) SELECT COUNT(*) FROM trees; https://explain.depesz.com/s/eUR = QUERY PLAN = --------------------------------------------------------------------------= --------------------------------------------------------------------------= -------- Aggregate (cost=3D763.19..763.20 rows=3D1 width=3D0) (actual = time=3D430.519..430.519 rows=3D1 loops=3D1) Buffers: shared hit=3D47768, temp written=3D1587 CTE trees -> Bitmap Heap Scan on document_head d (cost=3D82.05..759.20 = rows=3D177 width=3D74) (actual time=3D70.703..249.419 rows=3D154840 = loops=3D1) 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=3D47768 InitPlan 1 (returns $0) -> Result (cost=3D0.00..0.26 rows=3D1 width=3D0) (actual = time=3D0.083..0.084 rows=3D1 loops=3D1) Buffers: shared hit=3D4 -> Bitmap Index Scan on document_head__id_path__gist__idx = (cost=3D0.00..81.74 rows=3D178 width=3D0) (actual time=3D68.326..68.326 = rows=3D159979 loops=3D1) Index Cond: (id_path <@ $0) Buffers: shared hit=3D16238 -> CTE Scan on trees (cost=3D0.00..3.54 rows=3D177 width=3D0) = (actual time=3D70.707..388.714 rows=3D154840 loops=3D1) Buffers: shared hit=3D47768, temp written=3D1587 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 <@.=20 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.=20 My understanding how the planner works is that it evaluates some plans = and calculates cost based on the settings and and available statistics.=20= 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.=20 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,earthdi= stance,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,te= st_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) --Apple-Mail=_D476EA14-0C61-49EC-8F07-E3C422AE39F3 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=us-ascii
Hi,


I have a problem on 9.3.14 with a query = that accesses table:

Size: (retrieved by = query https://gist.github.com/romank0/74f9d1d807bd3f41c0729d0fc612674= 9)

 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 =3D '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 =3D '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 =3D '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 =3D '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 =3D '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 =3D ANY (ARRAY['NEW'::text, = 'READY_FOR_CUTOFF'::text, 'CUTOFF'::text, 'READY_FOR_DISPOSITION'::text, = 'DISPOSED'::text]))
    "document_head__sensitivity_check" CHECK = (sensitivity =3D 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 =3D = 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 = !=3D '78157c60-45bc-42c1-9aad-c5651995db5c') AND d.state !=3D = 'DELETED'
)
SELECT COUNT(*) FROM trees;

I get this plan https://explain.depesz.com/s/UQX4h
      =                     =                     =                     =                     =               QUERY = PLAN
---------------------------------------------------------------= --------------------------------------------------------------------------= -------------------------------------------------------------------------<= /font>
 Aggregate  (cost=3D86227.19..86227.20 rows=3D1 = width=3D0) (actual time=3D3878.775..3878.776 rows=3D1 = loops=3D1)
   Buffers: shared hit=3D747698, temp = written=3D1587
   CTE trees
     ->  Seq Scan = on document_head d  (cost=3D0.00..82718.21 rows=3D155955 width=3D74) = (actual time=3D0.211..3620.044 rows=3D154840 loops=3D1)
      =      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=3D747698
   ->  CTE Scan on trees =  (cost=3D0.00..3119.10 rows=3D155955 width=3D0) (actual = time=3D0.215..3828.519 rows=3D154840 loops=3D1)
      =    Buffers: shared hit=3D747698, temp = written=3D1587
 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 = !=3D '78157c60-45bc-42c1-9aad-c5651995db5c') AND d.state !=3D = 'DELETED'
)
SELECT COUNT(*) FROM trees;


https://explain.depesz.com/s/eUR
      =                     =                     =                     =        QUERY PLAN
---------------------------------------------------------------= --------------------------------------------------------------------------= -------------------
 Aggregate  (cost=3D763.19..763.20 rows=3D1 = width=3D0) (actual time=3D430.519..430.519 rows=3D1 = loops=3D1)
   Buffers: shared hit=3D47768, temp = written=3D1587
   CTE trees
     ->  Bitmap = Heap Scan on document_head d  (cost=3D82.05..759.20 rows=3D177 = width=3D74) (actual time=3D70.703..249.419 rows=3D154840 = loops=3D1)
           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=3D47768
      =      InitPlan 1 (returns $0)
      =        ->  Result  (cost=3D0.00..0.26 = rows=3D1 width=3D0) (actual time=3D0.083..0.084 rows=3D1 = loops=3D1)
                =    Buffers: shared hit=3D4
          =  ->  Bitmap Index Scan on document_head__id_path__gist__idx =  (cost=3D0.00..81.74 rows=3D178 width=3D0) (actual = time=3D68.326..68.326 rows=3D159979 loops=3D1)
      =            Index Cond: (id_path <@ = $0)
                =  Buffers: shared hit=3D16238
   ->  CTE Scan on = trees  (cost=3D0.00..3.54 rows=3D177 width=3D0) (actual = time=3D70.707..388.714 rows=3D154840 loops=3D1)
      =    Buffers: shared hit=3D47768, temp = written=3D1587
 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,earthdi= stance,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,te= st_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)

= --Apple-Mail=_D476EA14-0C61-49EC-8F07-E3C422AE39F3--