EXPLAIN ANALYZE does not show what takes time with my GIN index scan

Question

Context

I have a table named companies_establishments that holds ~33M rows. I created a GIN index with trigrams, so I can make LIKE queries much faster.

CREATE INDEX companies_establishments_id_index ON companies_establishments USING gin (id gin_trgm_ops);

However, it still takes 150ms and I don't understand why. I know that the index is big because I have a lot of records, but does it really explain these 150ms? Is there really only a 1 to 4 time difference between a full seq scan and an index scan with trigrams? What happens between 00.00 and 157.625 when index scan starts, according to the query plan (see below)? Is there a way to do a string search more efficiently?

EXPLAIN ANALYZE using GIN index

EXPLAIN (ANALYZE, VERBOSE, BUFFERS, COSTS OFF)
SELECT COUNT(*) FROM companies_establishments ce WHERE ce.id LIKE '502217755000%';

Result with the index:

                                                    QUERY PLAN                                                    
------------------------------------------------------------------------------------------------------------------
 Aggregate (actual time=157.640..157.641 rows=1 loops=1)
   Output: count(*)
   Buffers: shared hit=16356
   ->  Bitmap Heap Scan on public.companies_establishments ce (actual time=157.634..157.635 rows=2 loops=1)
         Recheck Cond: ((ce.id)::text ~~ '502217755000%'::text)
         Heap Blocks: exact=1
         Buffers: shared hit=16356
         ->  Bitmap Index Scan on companies_establishments_id_index (actual time=157.625..157.626 rows=2 loops=1)
               Index Cond: ((ce.id)::text ~~ '502217755000%'::text)
               Buffers: shared hit=16355
 Planning:
   Buffers: shared hit=11
 Planning Time: 0.446 ms
 Execution Time: 157.715 ms

Result without the index:

Finalize Aggregate (actual time=627.485..630.544 rows=1 loops=1)
  Output: count(*)
  Buffers: shared hit=225 read=353547
  I/O Timings: read=309.562
  ->  Gather (actual time=627.332..630.531 rows=3 loops=1)
        Output: (PARTIAL count(*))
        Workers Planned: 2
        Workers Launched: 2
        Buffers: shared hit=225 read=353547
        I/O Timings: read=309.562
        ->  Partial Aggregate (actual time=607.888..607.889 rows=1 loops=3)
              Output: PARTIAL count(*)
              Buffers: shared hit=225 read=353547
              I/O Timings: read=309.562
              Worker 0:  actual time=598.430..598.430 rows=1 loops=1
                Buffers: shared hit=71 read=114427
                I/O Timings: read=100.313
              Worker 1:  actual time=598.529..598.530 rows=1 loops=1
                Buffers: shared hit=72 read=114384
                I/O Timings: read=99.195
              ->  Parallel Seq Scan on public.companies_establishments ce (actual time=519.032..607.873 rows=1 loops=3)
"                    Output: id, siren, name, activity_code, public_name_1, public_name_2, public_name_3, diffusion, active, creation_date, association_id, workforce_size, workforce_size_update_year, can_employ, headquarter"
                    Filter: ((ce.id)::text ~~ '502217755000%'::text)
                    Rows Removed by Filter: 11183349
                    Buffers: shared hit=225 read=353547
                    I/O Timings: read=309.562
                    Worker 0:  actual time=598.419..598.419 rows=0 loops=1
                      Buffers: shared hit=71 read=114427
                      I/O Timings: read=100.313
                    Worker 1:  actual time=598.518..598.518 rows=0 loops=1
                      Buffers: shared hit=72 read=114384
                      I/O Timings: read=99.195
Planning:
  Buffers: shared hit=6
Planning Time: 0.367 ms
Execution Time: 632.989 ms

EXPLAIN ANALYZE using btree index

I also tried to use normal btree index by querying with a simple =, which really much faster.

EXPLAIN (ANALYZE, VERBOSE, BUFFERS, COSTS OFF)
SELECT COUNT(*) FROM companies_establishments ce WHERE ce.id = '50221775500011';

Result:

                                                                QUERY PLAN                                                                 
-------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate (actual time=0.070..0.071 rows=1 loops=1)
   Output: count(*)
   Buffers: shared hit=5
   ->  Index Only Scan using companies_establishments_pkey on public.companies_establishments ce (actual time=0.058..0.060 rows=1 loops=1)
         Output: id
         Index Cond: (ce.id = '50221775500011'::text)
         Heap Fetches: 1
         Buffers: shared hit=5
 Planning:
   Buffers: shared hit=1
 Planning Time: 0.336 ms
 Execution Time: 0.130 ms

Answer 1

Your question is a duplicate of this one, but perhaps it's worth an explanation specific to Bitmap Index Scan.

The numbers in the explain output: actual time=157.625..157.626, as indicated in the linked Q&A, signify the "startup" time and the total time for the stage. The startup time "is the time expended before the output phase can begin". If it were an index scan or a heap scan, the output phase could begin as soon as the first matching index entry or tuple was read. Not so with the bitmap scan -- it has to build the entire bitmap before it can pass it to the next stage, hence the startup time equals the total time.

Answer 2

The trigram index had to search through lots of data, probably because the trigrams 502, 022, 221 and so on occur frequently. Part of the problem might be a long GIN pending list. See if VACUUM on the table reduces the number of buffers scanned considerably. If yes, opt for no or a shorter pending list.

Answer 3

If the wildcard is always at the end of the pattern like in your example, then you can use just a btree index scan to handle it efficiently. But you will need to build the index using text_pattern_ops (unless you are using the C collation).