title: Postgresql 12 high CPU Spike on Slave fixed by running analyze.. unable to RCA
body: <p>Hi Postgresql 12 gradually spiked to 100% CPU. App team was looking after issue from 60 minutes. 2 different queries were taking high cpu. Tables involved were small so i just ran analyze on all 3 involved tables to fix any underlying statistics issue without first checking the query plan. Just after analyze run, issue got fix.</p>
  <p>Now we tried to recreate the issue from backup  few hours older than issue time but there query plan is same before and after analyze. We are unable to find RCA.</p>
  <p><strong>System Details:</strong>
  vCPU:8
  RAM: 61 GB
  Mode: slave/read replica</p>
  <p><strong>Table details</strong>
  resource_type: 174 rows
  roles: 290026 rows
  user_role_mapping: 3332118 rows</p>
  <p><strong>Query with plan from prod copy machine(for RCA purpose):</strong>
  EXPLAIN (ANALYZE TRUE, VERBOSE TRUE, COSTS TRUE, BUFFERS TRUE, TIMING TRUE)
  SELECT * FROM user_role_mapping u WHERE u.user_profile_id = '44130444' AND u.service_name = 'GLOBAL' AND u.status = 'ACTIVE' AND EXISTS (SELECT * FROM roles r WHERE r.id=u.role_id AND r.role_name='Owner') AND EXISTS (SELECT * FROM resource_type_dummy r WHERE r.id=u.resource_type_id AND r.type='HOTEL');</p>
  <p>EXPLAIN (ANALYZE TRUE, VERBOSE TRUE, COSTS TRUE, BUFFERS TRUE, TIMING TRUE)
  SELECT * FROM user_role_mapping u WHERE u.user_profile_id = 'x1' AND u.service_name = 'GLOBAL' AND u.status = 'ACTIVE' AND EXISTS (SELECT * FROM roles r WHERE r.id=u.role_id AND r.role_name='Owner') AND EXISTS (SELECT * FROM resource_type r WHERE r.id=u.resource_type_id AND r.type='HOTEL');</p>
  <pre><code>                                                                                              QUERY PLAN                                                                                                   
  </code></pre>
  <hr />
  <p>Nested Loop  (cost=1.00..424.35 rows=1 width=361) (actual time=368.512..369.536 rows=1 loops=1)
  Output: u.id, u.status, u.created_by, u.created_at, u.modified_by, u.last_modified_at, u.service_name, u.crs_id, u.identity_id, u.role_id, u.resource_id, u.resource_type_id, u.user_profile_id
  Inner Unique: true
  Buffers: shared hit=3 read=9
  I/O Timings: read=369.368
  -&gt;  Nested Loop  (cost=0.57..415.82 rows=1 width=361) (actual time=281.798..282.821 rows=1 loops=1)
  Output: u.id, u.status, u.created_by, u.created_at, u.modified_by, u.last_modified_at, u.service_name, u.crs_id, u.identity_id, u.role_id, u.resource_id, u.resource_type_id, u.user_profile_id
  Join Filter: (u.resource_type_id = r_1.id)
  Buffers: shared hit=1 read=7
  I/O Timings: read=282.696
  -&gt;  Index Scan using type_index_resource_type on public.resource_type r_1  (cost=0.14..8.16 rows=1 width=16) (actual time=0.054..0.055 rows=1 loops=1)
  Output: r_1.id, r_1.status, r_1.created_by, r_1.created_at, r_1.modified_by, r_1.last_modified_at, r_1.service_name, r_1.crs_id, r_1.type, r_1.actions
  Index Cond: ((r_1.type)::text = 'HOTEL'::text)
  Buffers: shared hit=1 read=1
  I/O Timings: read=0.016
  -&gt;  Index Scan using user_profile_id_index_user_role_mapping on public.user_role_mapping u  (cost=0.43..407.19 rows=37 width=361) (actual time=281.739..282.759 rows=1 loops=1)
  Output: u.id, u.status, u.created_by, u.created_at, u.modified_by, u.last_modified_at, u.service_name, u.crs_id, u.identity_id, u.role_id, u.resource_id, u.resource_type_id, u.user_profile_id
  Index Cond: ((u.user_profile_id)::text = 'x1'::text)
  Filter: (((u.service_name)::text = 'GLOBAL'::text) AND ((u.status)::text = 'ACTIVE'::text))
  Rows Removed by Filter: 2
  Buffers: shared read=6
  I/O Timings: read=282.680
  -&gt;  Index Scan using pk_roles on public.roles r  (cost=0.42..8.44 rows=1 width=16) (actual time=86.708..86.708 rows=1 loops=1)
  Output: r.id, r.status, r.created_by, r.created_at, r.modified_by, r.last_modified_at, r.service_name, r.crs_id, r.role_name, r.team_name, r.access_category, r.crs_team_id, r.actions
  Index Cond: (r.id = u.role_id)
  Filter: ((r.role_name)::text = 'Owner'::text)
  Buffers: shared hit=2 read=2
  I/O Timings: read=86.672
  Planning Time: 0.439 ms
  Execution Time: 369.570 ms
  (30 rows)</p>
  <p>EXPLAIN (ANALYZE TRUE, VERBOSE TRUE, COSTS TRUE, BUFFERS TRUE, TIMING TRUE)
  SELECT CAST(urm.id AS VARCHAR), urm.status, urm.created_by, urm.created_at, CAST(urm.modified_by AS VARCHAR), urm.last_modified_at, urm.service_name, urm.crs_id, urm.identity_id, CAST(urm.role_id AS VARCHAR), urm.resource_id, CAST(urm.resource_type_id AS VARCHAR), urm.user_profile_id, r.role_name role_name, rt.type resource_type_name FROM user_role_mapping urm INNER JOIN (SELECT id, role_name FROM roles r WHERE r.role_name IN ('xa', 'xb', 'xc', 'xd'))r ON urm.role_id = r.id INNER JOIN (SELECT id, rt.type FROM resource_type rt WHERE rt.type = 'experiment')rt ON urm.resource_type_id = rt.id WHERE (urm.user_profile_id IN ('11', '12')) AND urm.service_name = 'CRS' AND urm.status = 'ACTIVE';</p>
  <hr />
  <p>Nested Loop  (cost=1.00..830.89 rows=1 width=271) (actual time=240.293..240.294 rows=0 loops=1)
  Output: (urm.id)::character varying, urm.status, urm.created_by, urm.created_at, (urm.modified_by)::character varying, urm.last_modified_at, urm.service_name, urm.crs_id, urm.identity_id, (urm.role_id)::character varying, urm.resource_id, (urm.resource_type_id)::character varying, urm.user_profile_id, r.role_name, rt.type
  Inner Unique: true
  Buffers: shared hit=8 read=5
  I/O Timings: read=240.145
  -&gt;  Nested Loop  (cost=0.57..822.43 rows=1 width=379) (actual time=240.292..240.293 rows=0 loops=1)
  Output: urm.id, urm.status, urm.created_by, urm.created_at, urm.modified_by, urm.last_modified_at, urm.service_name, urm.crs_id, urm.identity_id, urm.role_id, urm.resource_id, urm.resource_type_id, urm.user_profile_id, rt.type
  Join Filter: (urm.resource_type_id = rt.id)
  Rows Removed by Join Filter: 2
  Buffers: shared hit=8 read=5
  I/O Timings: read=240.145
  -&gt;  Index Scan using type_index_resource_type on public.resource_type rt  (cost=0.14..8.16 rows=1 width=34) (actual time=0.018..0.019 rows=1 loops=1)
  Output: rt.id, rt.status, rt.created_by, rt.created_at, rt.modified_by, rt.last_modified_at, rt.service_name, rt.crs_id, rt.type, rt.actions
  Index Cond: ((rt.type)::text = 'experiment'::text)
  Buffers: shared hit=2
  -&gt;  Index Scan using user_profile_id_index_user_role_mapping on public.user_role_mapping urm  (cost=0.43..814.21 rows=4 width=361) (actual time=138.694..240.267 rows=2 loops=1)
  Output: urm.id, urm.status, urm.created_by, urm.created_at, urm.modified_by, urm.last_modified_at, urm.service_name, urm.crs_id, urm.identity_id, urm.role_id, urm.resource_id, urm.resource_type_id, urm.user_profile_id
  Index Cond: ((urm.user_profile_id)::text = ANY ('{11,12}'::text[]))
  Filter: (((urm.service_name)::text = 'CRS'::text) AND ((urm.status)::text = 'ACTIVE'::text))
  Buffers: shared hit=6 read=5
  I/O Timings: read=240.145
  -&gt;  Index Scan using pk_roles on public.roles r  (cost=0.42..8.45 rows=1 width=32) (never executed)
  Output: r.id, r.status, r.created_by, r.created_at, r.modified_by, r.last_modified_at, r.service_name, r.crs_id, r.role_name, r.team_name, r.access_category, r.crs_team_id, r.actions
  Index Cond: (r.id = urm.role_id)
  Filter: ((r.role_name)::text = ANY ('{xa, xb, xc, xd}'::text[]))
  Planning Time: 0.860 ms
  Execution Time: 240.358 ms
  (27 rows)</p>
  <p>Any other directions to look?</p>