From: Bhaskar Annamalai <BAnnamalai@walmartlabs.com>
To: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Subject: Slow queries after db upgrade to 9.6
Thread-Topic: Slow queries after db upgrade to 9.6
Thread-Index: AQHTDOg9FATiAkbDMUK4MBlLOeWc3Q==
Date: Fri, 4 Aug 2017 06:09:33 +0000
Message-ID: <D5A95DAC.16302%bannamalai@walmartlabs.com>
Accept-Language: en-US
Content-Language: en-US
received-spf: None (protection.outlook.com: walmartlabs.com does not designate
 permitted sender hosts)
spamdiagnosticoutput: 1:99
spamdiagnosticmetadata: NSPM
Content-Type: text/plain; charset="us-ascii"
Content-ID: <741397466F0EDD4FAA4B93667E09E83F@NAMP100.PROD.OUTLOOK.COM>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-originalarrivaltime: 04 Aug 2017 06:09:33.5284
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 3cbcc3d3-094d-4006-9849-0d11d61f484d
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BN6P100MB0226
X-OriginatorOrg: walmartlabs.com
X-CFilter-Loop: oser500438
X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10432:,,
 definitions=2017-08-04_02:,,
 signatures=0
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0
 priorityscore=1501 malwarescore=0
 suspectscore=0 phishscore=0 bulkscore=0 spamscore=0 clxscore=1015
 lowpriorityscore=0 impostorscore=0 adultscore=0 classifier=spam adjust=0
 reason=mlx scancount=1 engine=8.0.1-1706020000 definitions=main-1708040091
List-Archive: <http://archives.postgresql.org/pgsql-performance>
List-Help: <mailto:majordomo@postgresql.org?body=help>
List-ID: <pgsql-performance.postgresql.org>
List-Owner: <mailto:pgsql-performance-owner@postgresql.org>
List-Post: <mailto:pgsql-performance@postgresql.org>
List-Subscribe: <mailto:majordomo@postgresql.org?body=sub%20pgsql-performance>
List-Unsubscribe: 
 <mailto:majordomo@postgresql.org?body=unsub%20pgsql-performance>
X-Mailing-List: pgsql-performance
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Hi,

  We recently upgraded our database from 9.1 to 9.6. We are seeing some
unusual slow queries after the upgrade.
Sometimes the queries are faster after vacuum analyze, but not consistent.
We tried with different settings of random_page_cost, work_mem,
effective_cache_size but the query results are the same. I am trying to
understand if changing the queries/indexes would give us better
performance. Please provide your suggestions. Below is our table,index
definition.=20

Table : cm_ci_relations

       Column        |            Type             |       Modifiers
 | Storage  | Stats target | Description
---------------------+-----------------------------+-----------------------
-+----------+--------------+-------------
 ci_relation_id      | bigint                      | not null
 | plain    |              |
 ns_id               | bigint                      | not null
 | plain    | 200          |
 from_ci_id          | bigint                      | not null
 | plain    |              |
 relation_goid       | character varying(256)      | not null
 | extended |              |
 relation_id         | integer                     | not null
 | plain    |              |
 to_ci_id            | bigint                      | not null
 | plain    |              |
 ci_state_id         | integer                     | not null
 | plain    |              |
 last_applied_rfc_id | bigint                      |
 | plain    |              |
 comments            | character varying(2000)     |
 | extended |              |
 created_by          | character varying(200)      |
 | extended |              |
 update_by           | character varying(200)      |
 | extended |              |
 created             | timestamp without time zone | not null default
now() | plain    |              |
 updated             | timestamp without time zone | not null default
now() | plain    |              |
Indexes:
    "cm_ci_relations_pk" PRIMARY KEY, btree (ci_relation_id)
    "cm_ci_relations_goid_idx" UNIQUE, btree (relation_goid)
    "cm_ci_relations_uniq_idx" UNIQUE, btree (from_ci_id, relation_id,
to_ci_id)
    "cm_ci_relations_fromci_idx" btree (from_ci_id)
    "cm_ci_relations_ns_idx" btree (ns_id)
    "cm_ci_relations_r_ns_idx" btree (relation_id, ns_id)
    "cm_ci_relations_toci_idx" btree (to_ci_id)


Table : ns_namespaces

 Column  |            Type             |       Modifiers        | Storage
| Stats target | Description
---------+-----------------------------+------------------------+----------
+--------------+-------------
 ns_id   | bigint                      | not null               | plain
|              |
 ns_path | character varying(200)      | not null               | extended
| 300          |
 created | timestamp without time zone | not null default now() | plain
|              |
Indexes:
    "ns_namespaces_pk" PRIMARY KEY, btree (ns_id)
    "ns_namespaces_ak" UNIQUE, btree (ns_path)
    "ns_namespaces_vpo" btree (ns_path varchar_pattern_ops)


Table : cm_ci

       Column        |            Type             |       Modifiers
 | Storage  | Stats target | Description
---------------------+-----------------------------+-----------------------
-+----------+--------------+-------------
 ci_id               | bigint                      | not null
 | plain    |              |
 ns_id               | bigint                      | not null
 | plain    |              |
 class_id            | integer                     | not null
 | plain    |              |
 ci_name             | character varying(200)      | not null
 | extended |              |
 ci_goid             | character varying(256)      | not null
 | extended |              |
 comments            | character varying(2000)     |
 | extended |              |
 ci_state_id         | integer                     | not null
 | plain    |              |
 last_applied_rfc_id | bigint                      |
 | plain    |              |
 created_by          | character varying(200)      |
 | extended |              |
 updated_by          | character varying(200)      |
 | extended |              |
 created             | timestamp without time zone | not null default
now() | plain    |              |
 updated             | timestamp without time zone | not null default
now() | plain    |              |
Indexes:
    "cm_ci_pk" PRIMARY KEY, btree (ci_id)
    "cm_ci_3cols_idx" UNIQUE, btree (ns_id, class_id, ci_name)
    "df_ci_goid_idx" UNIQUE, btree (ci_goid)
    "cm_ci_cl_idx" btree (class_id)
    "cm_ci_ns_idx" btree (ns_id)


Table : md_relations

       Column        |            Type             |       Modifiers
 | Storage  | Stats target | Description
---------------------+-----------------------------+-----------------------
-+----------+--------------+-------------
 relation_id         | integer                     | not null
 | plain    |              |
 relation_name       | character varying(200)      | not null
 | extended |              |
 short_relation_name | character varying(200)      | not null
 | extended |              |
 description         | text                        | not null
 | extended |              |
 created             | timestamp without time zone | not null default
now() | plain    |              |
Indexes:
    "md_relations_pk" PRIMARY KEY, btree (relation_id)
    "md_relations_rln_idx" UNIQUE, btree (relation_name)
    "md_relations_srn_idx" btree (short_relation_name)


Table : md_classes
                                           Table "kloopzcm.md_classes"
      Column      |            Type             |       Modifiers        |
Storage  | Stats target | Description
------------------+-----------------------------+------------------------+-
---------+--------------+-------------
 class_id         | integer                     | not null               |
plain    |              |
 class_name       | character varying(200)      | not null               |
extended |              |
 short_class_name | character varying(200)      | not null               |
extended |              |
 super_class_id   | integer                     |                        |
plain    |              |
 is_namespace     | boolean                     | not null               |
plain    |              |
 flags            | integer                     | not null default 0     |
plain    |              |
 impl             | character varying(200)      |                        |
extended |              |
 access_level     | character varying(200)      |                        |
extended |              |
 description      | text                        |                        |
extended |              |
 format           | text                        |                        |
extended |              |
 created          | timestamp without time zone | not null default now() |
plain    |              |
Indexes:
    "md_classes_pk" PRIMARY KEY, btree (class_id)
    "md_classes_cln_idx" UNIQUE, btree (class_name)
    "md_classes_comp_names_idx" btree (class_name, short_class_name)
    "md_classes_scln_idx" btree (short_class_name)


Table : cm_ci_state

   Column    |         Type          | Modifiers | Storage  | Stats target
| Description
-------------+-----------------------+-----------+----------+--------------
+-------------
 ci_state_id | integer               | not null  | plain    |
|
 state_name  | character varying(64) | not null  | extended |
|
Indexes:
    "cm_ci_state_pk" PRIMARY KEY, btree (ci_state_id)


The below query has been really slow after the upgrade, the explain plan
shows that it uses the cm_ci_relations_fromci_idx index on the
cm_ci_relations table. But when another set of parameters are used for the
ns_path the query plan is better. In general I expect the ns_namespaces,
md_relations being queried first and then the results are further used on
the cm_ci_relations_r_ns_idx index (cm_ci_relations table) and then cm_ci
table. That would filter out a lot of records and will be much faster.

Table Data
----------
The ns_namespaces table contains data like a folder structure and can go
upto five levels separated by slash
/f1/f2/f3/f4/f5
/f1/f2/a1
/f1/f2/b1
/f1/c1
/g1/b1

There would be a lot of duplicates matching the beginning section of the
path.

cm_ci is the instances table with around 3 million records;
cm_ci_relations is the relations between instances table, with around 7.5
million records. this table is the largest in this query.
md_classes contains around 2k records
md_relations contains around 100+ records

Its not that the longer the ns_path parameter provided, the query is
faster. In some cases where the ns_path parameter is very much focused
like (/a/b/c/d/e) with different relation names and class names the query
was still slow as the planner was not using the best possible index
cm_ci_relations_r_ns_idx.


slow performing query:

explain (buffers, analyze) select
          cir.ci_relation_id as ciRelationId,
          cir.ns_id as nsId,
          ns.ns_path as nsPath,
          cir.from_ci_id as fromCiId,
          cir.relation_goid as relationGoid,
          cir.relation_id as relationId,
          mdr.relation_name as relationName,
          cir.to_ci_id toCiId,
          cir.ci_state_id as relationStateId,
          cis.state_name as relationState,
          cir.last_applied_rfc_id as lastAppliedRfcId,
          cir.comments,
               cir.created,
          cir.updated
  from cm_ci_relations cir, md_relations mdr, cm_ci_state cis, cm_ci
from_ci, md_classes from_mdc, cm_ci to_ci, md_classes to_mdc,
ns_namespaces ns
  where (ns.ns_path like '/test1/%' or ns.ns_path =3D '/test1')
    and cir.ns_id =3D ns.ns_id
    and cir.ci_state_id =3D cis.ci_state_id
    and cir.relation_id =3D mdr.relation_id
    and (mdr.relation_name =3D 'base.DeployedTo')
    and cir.from_ci_id =3D from_ci.ci_id
    and from_ci.class_id =3D from_mdc.class_id
    and ( from_mdc.class_name =3D 'bom.Compute')
    and cir.to_ci_id =3D to_ci.ci_id
    and to_ci.class_id =3D to_mdc.class_id;


below is the explain plan for this query
=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20
             QUERY PLAN

---------------------------------------------------------------------------
-----------------------------------------------------------------
-----------------------------------------------
 Nested Loop  (cost=3D139.97..18932.15 rows=3D1 width=3D288) (actual
time=3D63.741..7213.251 rows=3D276 loops=3D1)
   Buffers: shared hit=3D552715 read=3D6114
   ->  Nested Loop  (cost=3D139.69..18931.84 rows=3D1 width=3D292) (actual
time=3D63.675..7211.745 rows=3D276 loops=3D1)
         Buffers: shared hit=3D552162 read=3D6114
         ->  Nested Loop  (cost=3D139.26..18931.35 rows=3D1 width=3D288) (a=
ctual
time=3D63.646..7206.066 rows=3D276 loops=3D1)
               Buffers: shared hit=3D551058 read=3D6114
               ->  Nested Loop  (cost=3D139.12..18931.19 rows=3D1 width=3D2=
77)
(actual time=3D63.637..7199.116 rows=3D276 loops=3D1)
                     Buffers: shared hit=3D550506 read=3D6114
                     ->  Nested Loop  (cost=3D138.70..18919.38 rows=3D26
width=3D228) (actual time=3D58.446..6620.992 rows=3D62689 loops=3D1)
                           Join Filter: (cir.relation_id =3D mdr.relation_i=
d)
                           Rows Removed by Join Filter: 125384
                           Buffers: shared hit=3D299270 read=3D6114
                           ->  Seq Scan on md_relations mdr
(cost=3D0.00..7.59 rows=3D1 width=3D22) (actual time=3D0.017..0.060 rows=3D=
1 loops=3D1)
                                 Filter: ((relation_name)::text =3D
'base.DeployedTo'::text)
                                 Rows Removed by Filter: 126
                                 Buffers: shared hit=3D6
                           ->  Nested Loop  (cost=3D138.70..18869.86
rows=3D3355 width=3D210) (actual time=3D58.418..6551.520 rows=3D188073 loop=
s=3D1)
                                 Buffers: shared hit=3D299264 read=3D6114
                                 ->  Nested Loop  (cost=3D138.27..17306.08
rows=3D1271 width=3D8) (actual time=3D58.367..1012.918 rows=3D62710 loops=
=3D1
)
                                       Buffers: shared hit=3D28631
                                       ->  Index Scan using
md_classes_comp_names_idx on md_classes from_mdc  (cost=3D0.28..8.30 rows=
=3D1
width=3D
4) (actual time=3D0.031..0.037 rows=3D1 loops=3D1)
                                             Index Cond:
((class_name)::text =3D 'bom.Compute'::text)
                                             Buffers: shared hit=3D3
                                       ->  Bitmap Heap Scan on cm_ci
from_ci  (cost=3D137.99..17238.99 rows=3D5879 width=3D12) (actual time=3D58=
.332
..980.258 rows=3D62710 loops=3D1)
                                             Recheck Cond: (class_id =3D
from_mdc.class_id)
                                             Heap Blocks: exact=3D28001
                                             Buffers: shared hit=3D28628
                                             ->  Bitmap Index Scan on
cm_ci_cl_idx  (cost=3D0.00..136.52 rows=3D5879 width=3D0) (actual time=3D52=
.52
0..52.520 rows=3D63497 loops=3D1)
                                                   Index Cond: (class_id =3D
from_mdc.class_id)
                                                   Buffers: shared hit=3D627
                                 ->  Index Scan using
cm_ci_relations_fromci_idx on cm_ci_relations cir  (cost=3D0.43..1.07
rows=3D16 width=3D210)
 (actual time=3D0.067..0.084 rows=3D3 loops=3D62710)
                                       Index Cond: (from_ci_id =3D
from_ci.ci_id)
                                       Buffers: shared hit=3D270633 read=3D=
6114
                     ->  Index Scan using ns_namespaces_pk on
ns_namespaces ns  (cost=3D0.42..0.44 rows=3D1 width=3D57) (actual
time=3D0.008..0.008
rows=3D0 loops=3D62689)
                           Index Cond: (ns_id =3D cir.ns_id)
                           Filter: (((ns_path)::text ~~ '/test1/%'::text)
OR ((ns_path)::text =3D '/test1'::text))
                           Rows Removed by Filter: 1
                           Buffers: shared hit=3D251236
               ->  Index Scan using cm_ci_state_pk on cm_ci_state cis
(cost=3D0.13..0.15 rows=3D1 width=3D15) (actual time=3D0.002..0.003 rows=3D=
1 lo
ops=3D276)
                     Index Cond: (ci_state_id =3D cir.ci_state_id)
                     Buffers: shared hit=3D552
         ->  Index Scan using cm_ci_pk on cm_ci to_ci  (cost=3D0.43..0.48
rows=3D1 width=3D12) (actual time=3D0.015..0.016 rows=3D1 loops=3D276)
               Index Cond: (ci_id =3D cir.to_ci_id)
               Buffers: shared hit=3D1104
   ->  Index Only Scan using md_classes_pk on md_classes to_mdc
(cost=3D0.28..0.30 rows=3D1 width=3D4) (actual time=3D0.003..0.004 rows=3D1=
 loops=3D276
)
         Index Cond: (class_id =3D to_ci.class_id)
         Heap Fetches: 0
         Buffers: shared hit=3D553
 Planning time: 12.641 ms
 Execution time: 7214.707 ms


similar query with different parameters, this gets executed much faster

 explain (buffers, analyze) select
          cir.ci_relation_id as ciRelationId,
          cir.ns_id as nsId,
          ns.ns_path as nsPath,
          cir.from_ci_id as fromCiId,
          cir.relation_goid as relationGoid,
          cir.relation_id as relationId,
          mdr.relation_name as relationName,
          cir.to_ci_id toCiId,
          cir.ci_state_id as relationStateId,
          cis.state_name as relationState,
          cir.last_applied_rfc_id as lastAppliedRfcId,
          cir.comments,
               cir.created,
          cir.updated
  from cm_ci_relations cir, md_relations mdr, cm_ci_state cis, cm_ci
from_ci, md_classes from_mdc, cm_ci to_ci, md_classes to_mdc,
ns_namespaces ns
  where (ns.ns_path like '/test1/test2/%' or ns.ns_path =3D '/test1/test2')
    and cir.ns_id =3D ns.ns_id
    and cir.ci_state_id =3D cis.ci_state_id
    and cir.relation_id =3D mdr.relation_id
    and (mdr.relation_name =3D 'base.DeployedTo')
    and cir.from_ci_id =3D from_ci.ci_id
    and from_ci.class_id =3D from_mdc.class_id
    and ( from_mdc.class_name =3D 'bom.Compute')
    and cir.to_ci_id =3D to_ci.ci_id
    and to_ci.class_id =3D to_mdc.class_id;


=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20
              QUERY PLAN

---------------------------------------------------------------------------
-----------------------------------------------------------------
--------------------------------------------------
 Nested Loop  (cost=3D10.72..479.62 rows=3D1 width=3D288) (actual
time=3D5.101..98.016 rows=3D114 loops=3D1)
   Buffers: shared hit=3D13321 read=3D31
   ->  Nested Loop  (cost=3D10.44..479.31 rows=3D1 width=3D292) (actual
time=3D5.068..97.647 rows=3D114 loops=3D1)
         Buffers: shared hit=3D13092 read=3D31
         ->  Nested Loop  (cost=3D10.01..478.82 rows=3D1 width=3D288) (actu=
al
time=3D5.037..94.108 rows=3D114 loops=3D1)
               Join Filter: (cir.ci_state_id =3D cis.ci_state_id)
               Rows Removed by Join Filter: 456
               Buffers: shared hit=3D12636 read=3D31
               ->  Nested Loop  (cost=3D10.01..477.71 rows=3D1 width=3D277)
(actual time=3D5.030..93.568 rows=3D114 loops=3D1)
                     Buffers: shared hit=3D12522 read=3D31
                     ->  Nested Loop  (cost=3D9.73..475.54 rows=3D7 width=
=3D281)
(actual time=3D0.383..87.509 rows=3D1578 loops=3D1)
                           Buffers: shared hit=3D7788 read=3D31
                           ->  Nested Loop  (cost=3D9.30..472.10 rows=3D7
width=3D277) (actual time=3D0.362..53.412 rows=3D1578 loops=3D1)
                                 Buffers: shared hit=3D1475 read=3D26
                                 ->  Seq Scan on md_relations mdr
(cost=3D0.00..7.59 rows=3D1 width=3D22) (actual time=3D0.014..0.037 rows=3D=
1 loops=3D
1)
                                       Filter: ((relation_name)::text =3D
'base.DeployedTo'::text)
                                       Rows Removed by Filter: 126
                                       Buffers: shared hit=3D6
                                 ->  Nested Loop  (cost=3D9.30..463.63
rows=3D88 width=3D259) (actual time=3D0.333..52.719 rows=3D1578 loops=3D1)
                                       Buffers: shared hit=3D1469 read=3D26
                                       ->  Bitmap Heap Scan on
ns_namespaces ns  (cost=3D8.87..12.88 rows=3D22 width=3D57) (actual
time=3D0.202..0.4
51 rows=3D119 loops=3D1)
                                             Recheck Cond:
(((ns_path)::text ~~ '/test1/test2/%'::text) OR ((ns_path)::text =3D
'/test1/test2'
::text))
                                             Filter: (((ns_path)::text ~~
'/test1/test2/%'::text) OR ((ns_path)::text =3D '/test1/test2'::text
))
                                             Heap Blocks: exact=3D48
                                             Buffers: shared hit=3D54 read=
=3D1
                                             ->  BitmapOr
(cost=3D8.87..8.87 rows=3D1 width=3D0) (actual time=3D0.187..0.187 rows=3D0=
 loops=3D1)
                                                   Buffers: shared hit=3D6
read=3D1
                                                   ->  Bitmap Index Scan
on ns_namespaces_vpo  (cost=3D0.00..4.43 rows=3D1 width=3D0) (actual time
=3D0.181..0.181 rows=3D118 loops=3D1)
                                                         Index Cond:
(((ns_path)::text ~>=3D~ '/test1/test2/'::text) AND ((ns_path)::text ~<~
'/test1/test20'::text))
                                                         Buffers: shared
hit=3D3 read=3D1
                                                   ->  Bitmap Index Scan
on ns_namespaces_vpo  (cost=3D0.00..4.43 rows=3D1 width=3D0) (actual time
=3D0.004..0.004 rows=3D1 loops=3D1)
                                                         Index Cond:
((ns_path)::text =3D '/test1/test2'::text)
                                                         Buffers: shared
hit=3D3
                                       ->  Index Scan using
cm_ci_relations_r_ns_idx on cm_ci_relations cir  (cost=3D0.43..20.45 rows=
=3D4
width=3D
210) (actual time=3D0.010..0.429 rows=3D13 loops=3D119)
                                             Index Cond: ((relation_id =3D
mdr.relation_id) AND (ns_id =3D ns.ns_id))
                                             Buffers: shared hit=3D1415
read=3D25
                           ->  Index Scan using cm_ci_pk on cm_ci from_ci
(cost=3D0.43..0.48 rows=3D1 width=3D12) (actual time=3D0.020..0.020 rows=3D
1 loops=3D1578)
                                 Index Cond: (ci_id =3D cir.from_ci_id)
                                 Buffers: shared hit=3D6313 read=3D5
                     ->  Index Scan using md_classes_pk on md_classes
from_mdc  (cost=3D0.28..0.30 rows=3D1 width=3D4) (actual time=3D0.003..0.00=
3 r
ows=3D0 loops=3D1578)
                           Index Cond: (class_id =3D from_ci.class_id)
                           Filter: ((class_name)::text =3D
'bom.Compute'::text)
                           Rows Removed by Filter: 1
                           Buffers: shared hit=3D4734
               ->  Seq Scan on cm_ci_state cis  (cost=3D0.00..1.05 rows=3D5
width=3D15) (actual time=3D0.001..0.002 rows=3D5 loops=3D114)
                     Buffers: shared hit=3D114
         ->  Index Scan using cm_ci_pk on cm_ci to_ci  (cost=3D0.43..0.48
rows=3D1 width=3D12) (actual time=3D0.030..0.030 rows=3D1 loops=3D114)
               Index Cond: (ci_id =3D cir.to_ci_id)
               Buffers: shared hit=3D456
   ->  Index Only Scan using md_classes_pk on md_classes to_mdc
(cost=3D0.28..0.30 rows=3D1 width=3D4) (actual time=3D0.002..0.002 rows=3D1=
 loops=3D114
)
         Index Cond: (class_id =3D to_ci.class_id)
         Heap Fetches: 0
         Buffers: shared hit=3D229
 Planning time: 8.468 ms
 Execution time: 98.223 ms


Thanks,
Bhaskar


--=20
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance