2

I have a compound LIKE in a query that would have seemed to have benefited from a gin index however on two practically identical servers I see vastly different performance, with the worst case being almost as slow as a Seq Scan:

Bad:

EXPLAIN (ANALYZE, BUFFERS) SELECT nodes.node_path FROM nodes WHERE nodes.node_path LIKE 'company%/path%';
                                                                    QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------
 Bitmap Heap Scan on nodes  (cost=2114.03..17149.31 rows=3875 width=42) (actual time=11000.379..11036.533 rows=52 loops=1)
   Recheck Cond: ((node_path)::text ~~ 'company%/path%'::text)
   Rows Removed by Index Recheck: 46597
   Heap Blocks: exact=27913
   Buffers: shared hit=73481
   ->  Bitmap Index Scan on nodes_node_path_gin_idx  (cost=0.00..2113.06 rows=3875 width=0) (actual time=10992.576..10992.576 rows=46649 loops=1)
         Index Cond: ((node_path)::text ~~ 'company%/path%'::text)
         Buffers: shared hit=45568
 Planning time: 0.245 ms
 Execution time: 11036.769 ms
(10 rows)

Good:

EXPLAIN (ANALYZE, BUFFERS) SELECT nodes.node_path FROM nodes WHERE nodes.node_path LIKE 'company%/path%';
                                                                   QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------
 Bitmap Heap Scan on nodes  (cost=2528.05..20571.91 rows=4651 width=43) (actual time=1329.024..1354.603 rows=56 loops=1)
   Recheck Cond: ((node_path)::text ~~ 'company%/path%'::text)
   Rows Removed by Index Recheck: 48704
   Heap Blocks: exact=16106
   Buffers: shared hit=126080
   ->  Bitmap Index Scan on nodes_node_path_gin_idx  (cost=0.00..2526.89 rows=4651 width=0) (actual time=1324.801..1324.802 rows=48760 loops=1)
         Index Cond: ((node_path)::text ~~ 'company%/path%'::text)
         Buffers: shared hit=109974
 Planning time: 0.237 ms
 Execution time: 1354.748 ms
(10 rows)

For index:

CREATE INDEX nodes_node_path_gin_idx ON public.nodes USING gin (node_path gin_trgm_ops)

Where node_path stores slash delimited file paths.

These hosts otherwise exhibit very similar performance, and there's seemingly no disk I/O or other factors obviously different between these executions.

I enabled track_io_timing, I/O Timings is not emitted, and BUFFERS indicates Buffers: shared hit=43783. I dumped this column to a local 9.6.16 instance and it runs in milliseconds, but on the RDS Postgres 9.6.11 instance it's always 10 seconds:

EXPLAIN (ANALYZE, BUFFERS) SELECT nodes.node_path FROM nodes WHERE nodes.node_path LIKE 'company%/path%';
                                                                QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------
 Bitmap Heap Scan on nodes  (cost=403.14..15246.51 rows=4018 width=42) (actual time=76.402..76.421 rows=52 loops=1)
   Recheck Cond: ((node_path)::text ~~ 'company%/path%'::text)
   Rows Removed by Index Recheck: 48576
   Heap Blocks: exact=506
   Buffers: shared hit=8530
   ->  Bitmap Index Scan on nodes_node_path_gin_idx  (cost=0.00..402.13 rows=4018 width=0) (actual time=71.494..71.494 rows=48628 loops=1)
         Index Cond: ((node_path)::text ~~ 'company%/path%'::text)
         Buffers: shared hit=8024
 Planning time: 0.188 ms
 Execution time: 76.452 ms
(10 rows)

How do I get information on where the cost is for the Bitmap Index Scan itself - I assume it's something specific to the implementation of the ~~ operator for the gin index type, but is there additional instrumentation I can enable to understand the unexplained time?

8
  • No IO at all it seems. I/O Timings is not emitted, Buffers: shared hit=43783. Dec 10, 2019 at 1:05
  • Is it 43783 on both the fast server and the slow server? Does "top" show you anything different between servers, maybe a high steal ("st") percentage? I think my next step would to run perf top -p <process pid> on them. You might want to run the queries in a tight loop to (in psql, you can end the command with "\watch 0.001" rather than than ";") give perf enough time to collect enough samples.
    – jjanes
    Dec 10, 2019 at 1:43
  • 1
    Another thought, do they have the same versions of pg_trgm installed?
    – jjanes
    Dec 10, 2019 at 1:45
  • The fast server reads more blocks and has higher row counts, thus the confusion. Unfortunately they're RDS instances so I have less access than I'd like. Yes, same version of pg_trgm. Trying to reproduce on an instance I have more access to. Dec 10, 2019 at 3:22
  • You should post the complete EXPLAIN (ANALYZE, BUFFERS) output. Dec 10, 2019 at 3:54

1 Answer 1

2

Substantial improvements were made to pg_trgm in PostgreSQL v9.6, pg_trgm v1.3.

But if you upgraded your server from before 9.6 to 9.6 or later using "pg_upgrade", you will not benefit from these improvements until you do alter extension pg_trgm update TO "1.3".

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.