2

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
3
  • Too many different questions lumped together.
    – jjanes
    Mar 9, 2023 at 13:08
  • If you turn on track_io_timing, you will be able to see how much of the time was spend waiting for IO versus other things.
    – jjanes
    Mar 9, 2023 at 13:14
  • The only different question is "Is there a way to do a string search more efficiently?", but the others are all about the same topic (why does my query takes 150ms). track_io_timing is on, however there was no disk IO because I set my shared buffer size to 4GB.
    – Madeorsk
    Mar 9, 2023 at 13:44

3 Answers 3

2

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.

1
  • Yes, the question was more about "what happens in the startup time". The thing I couldn't figure out was the difference between a normal startup time, and a startup time with this current index.
    – Madeorsk
    Mar 9, 2023 at 1:54
3

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.

3
  • 2
    To expand on this, for a LIKE it has to read the ctid list for every trigram occurring in the query from the index, (but then throws away all but the shortest ctid list). May guess is that one particular trigram is the culprit here, probably '000'.
    – jjanes
    Mar 9, 2023 at 13:13
  • I thought about the fact that the format of my id is a hard case for trigram indices, because it's a fixed format of 14 digits, and the last 5 digits are almost always (>95% I think) in the format "000XX". But in that case, isn't that strange that when I search with '502217755%' it takes longer than '502217755000%'?
    – Madeorsk
    Mar 9, 2023 at 13:56
  • @Madeorsk Yes, that does seem inconsistent with my theory. Maybe the real culprit then is a different trigram, like 502.
    – jjanes
    Mar 9, 2023 at 14:02
2

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).

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.