Discrepancy between Explain Analyze Actual Row Scanned vs. Total Row in Table

Question

Recently we experienced a performance problem in Production Aurora PG cluster. This is an EXPLAIN ANALYZE of the query.

The majority of the time is spent on

Bitmap Index Scan on job_stage  (cost=0.00..172.93 rows=9666 width=0) (actual time=238.410..238.410 rows=2019444 loops=1)

where 2019444 are scanned. However, what troubles me is that there are only 70k rows in this table. Autovacuum is turned on, but the RDS was overloaded recently from another issue. We suspect that the autovacuum was running behind. If that is the case, would it explain our observation the scanned row exceeds actual row in table?

Nested Loop  (cost=229.16..265.28 rows=1 width=464) (actual time=239.815..239.815 rows=0 loops=1)
  ->  Nested Loop  (cost=228.62..252.71 rows=1 width=540) (actual time=239.814..239.814 rows=0 loops=1)
        Join Filter: (job.scanner_uuid = scanner_resource_pool.resource_uuid)
        Rows Removed by Join Filter: 1
        ->  Index Scan using scanner_resource_pool_scanner_index on scanner_resource_pool  (cost=0.41..8.43 rows=1 width=115) (actual time=0.017..0.019 rows=1 loops=1)
              Index Cond: ((box_uuid = '5d8a7e0c-23ff-4853-bb6d-ffff6a38afa7'::text) AND (scanner_uuid = '9be9ac50-de05-4ddd-9545-ddddc484dce'::text))
        ->  Bitmap Heap Scan on job  (cost=228.22..244.23 rows=4 width=464) (actual time=239.790..239.791 rows=1 loops=1)
              Recheck Cond: ((box_uuid = '5d8a7e0c-23ff-4853-bb6d-ffff6a38afa7'::text) AND (stage = 'active'::text))
              Rows Removed by Index Recheck: 6
              Heap Blocks: exact=791
              ->  BitmapAnd  (cost=228.22..228.22 rows=4 width=0) (actual time=238.913..238.913 rows=0 loops=1)
                    ->  Bitmap Index Scan on job_box_status  (cost=0.00..55.04 rows=1398 width=0) (actual time=0.183..0.183 rows=899 loops=1)
                          Index Cond: (box_uuid = '5d8a7e0c-23ff-4853-bb6d-ffff6a38afa7'::text)
                    ->  Bitmap Index Scan on job_stage  (cost=0.00..172.93 rows=9666 width=0) (actual time=238.410..238.410 rows=2019444 loops=1)
                          Index Cond: (stage = 'active'::text)
  ->  Index Only Scan using uc_box_uuid on scanner  (cost=0.54..12.56 rows=1 width=87) (never executed)
        Index Cond: ((box_uuid = '5d8a7e0c-23ff-4853-bb6d-ffff6a38afa7'::text) AND (uuid = '9be9ac50-de05-4ddd-9545-ddddc484dce'::text))
        Heap Fetches: 0
Planning time: 1.274 ms
Execution time: 239.876 ms

askldjd askldjd · Accepted Answer · 2019-05-31T01:47:17

I found my answer by confirming with AWS. If autovacuum was running behind, the EXPLAIN ANALYZE result may show this discrepancy.

Discrepancy between Explain Analyze Actual Row Scanned vs. Total Row in Table

1 Answers