[Bug]: SkipScan not used with LIKE 'abc%def'

[Yamakaky]

What type of bug is this?

Performance issue

What subsystems and features are affected?

SkipScan

What happened?

Timescaledb seems to have some trouble deciding to use SkipScan when using LIKE with characters after %.

                              Table "public.ltest"
       Column        |           Type           | Collation | Nullable | Default
---------------------+--------------------------+-----------+----------+---------
 time                | timestamp with time zone |           | not null |
 entity_id           | text                     |           | not null |
 device_class        | text                     |           |          |
 state               | text                     |           | not null |
 state_class         | text                     |           |          |
 attributes          | jsonb                    |           | not null |
 location            | geometry(Point,4326)     |           |          |
 friendly_name       | text                     |           |          |
 unit_of_measurement | text                     |           |          |
Indexes:
    "ltest_entity_id_time_idx" btree (entity_id, "time" DESC)

select distinct on (entity_id) * from ltest
where time > now() - interval '7 day' and entity_id like PATTERN
order by entity_id, time desc;

Examples of entity_id:

 sensor.atmos_salon_pressure
 sensor.atmos_salon_temperature
 sensor.atmos_utilitaire_battery
 sensor.atmos_utilitaire_humidity
 sensor.atmos_utilitaire_pressure
 sensor.chauffe_eau_tx
 sensor.chauffe_eau_uptime_2
 sensor.cloud_key_rx
 sensor.cloud_key_tx
 sensor.cloud_key_uptime
 sensor.desktop_de_mikael_eth_rx

When % is the last part of PATTERN, I get SkipScan as expected. It also happens for sensor%_ for some reason.

 Unique  (cost=209.57..99599.11 rows=209 width=175) (actual time=0.233..7.100 rows=118 loops=1)
   ->  Custom Scan (ConstraintAwareAppend)  (cost=209.57..88980.05 rows=4247627 width=175) (actual time=0.231..6.912 rows=235 loops=1)
         Hypertable: ltest
         Chunks left after exclusion: 2
         ->  Merge Append  (cost=209.57..88980.05 rows=4247627 width=175) (actual time=0.230..6.843 rows=235 loops=1)
               Sort Key: _hyper_4_61_chunk.entity_id, _hyper_4_61_chunk."time" DESC
               ->  Custom Scan (SkipScan) on _hyper_4_61_chunk  (cost=0.43..110.24 rows=209 width=180) (actual time=0.130..3.630 rows=118 loops=1)
                     ->  Index Scan using _hyper_4_61_chunk_ltest_entity_id_time_idx on _hyper_4_61_chunk  (cost=0.43..57995.66 rows=594921 width=180) (actual time=0.128..3.527 rows=118 loops=1)
                           Index Cond: ((entity_id >= 'sensor'::text) AND (entity_id < 'sensos'::text) AND ("time" > (now() - '7 days'::interval)))
                           Filter: (entity_id ~~ 'sensor%'::text)
               ->  Custom Scan (SkipScan) on _hyper_4_81_chunk  (cost=0.42..99.63 rows=209 width=133) (actual time=0.097..3.082 rows=117 loops=1)
                     ->  Index Scan using _hyper_4_81_chunk_ltest_entity_id_time_idx on _hyper_4_81_chunk  (cost=0.42..3949.11 rows=72878 width=133) (actual time=0.096..2.983 rows=117 loops=1)
                           Index Cond: ((entity_id >= 'sensor'::text) AND (entity_id < 'sensos'::text) AND ("time" > (now() - '7 days'::interval)))
                           Filter: (entity_id ~~ 'sensor%'::text)
 Planning Time: 22.176 ms
 Execution Time: 8.324 ms

However, depending on the end of PATTERN, I get other plans:

• 'sensor%tem'

 Unique  (cost=26140.41..26845.77 rows=9 width=226) (actual time=341.684..356.574 rows=0 loops=1)
   ->  Gather Merge  (cost=26140.41..26830.76 rows=6003 width=226) (actual time=341.682..356.571 rows=0 loops=1)
         Workers Planned: 1
         Workers Launched: 1
         ->  Sort  (cost=25140.40..25155.41 rows=6003 width=225) (actual time=251.228..251.230 rows=0 loops=2)
               Sort Key: ltest.entity_id, ltest."time" DESC
               Sort Method: quicksort  Memory: 25kB
               Worker 0:  Sort Method: quicksort  Memory: 25kB
               ->  Parallel Custom Scan (ChunkAppend) on ltest  (cost=34.09..24378.27 rows=6003 width=225) (actual time=250.938..250.939 rows=0 loops=2)
                     Chunks excluded during startup: 7
                     ->  Parallel Seq Scan on _hyper_4_61_chunk  (cost=0.00..22111.56 rows=1 width=180) (actual time=228.952..228.953 rows=0 loops=2)
                           Filter: ((entity_id ~~ 'sensor%tem'::text) AND ("time" > (now() - '7 days'::interval)))
                           Rows Removed by Filter: 346612
                     ->  Parallel Seq Scan on _hyper_4_81_chunk  (cost=0.00..2081.14 rows=1 width=133) (actual time=43.945..43.945 rows=0 loops=1)
                           Filter: ((entity_id ~~ 'sensor%tem'::text) AND ("time" > (now() - '7 days'::interval)))
                           Rows Removed by Filter: 76928
 Planning Time: 23.440 ms
 Execution Time: 357.331 ms

• sensor%temperature

 Unique  (cost=62357.72..63226.71 rows=209 width=175) (actual time=930.933..952.883 rows=14 loops=1)
   ->  Sort  (cost=62357.72..62792.22 rows=173799 width=175) (actual time=930.929..946.553 rows=18367 loops=1)
         Sort Key: ltest.entity_id, ltest."time" DESC
         Sort Method: external merge  Disk: 4144kB
         ->  Custom Scan (ChunkAppend) on ltest  (cost=0.42..29830.67 rows=173799 width=175) (actual time=0.243..802.951 rows=18367 loops=1)
               Chunks excluded during startup: 7
               ->  Index Scan using _hyper_4_61_chunk_ltest_time_idx on _hyper_4_61_chunk  (cost=0.43..26905.21 rows=16672 width=180) (actual time=0.241..736.887 rows=16270 loops=1)
                     Index Cond: ("time" > (now() - '7 days'::interval))
                     Filter: (entity_id ~~ 'sensor%temperature'::text)
                     Rows Removed by Filter: 600380
               ->  Seq Scan on _hyper_4_81_chunk  (cost=0.00..2714.74 rows=2126 width=133) (actual time=0.097..59.923 rows=2097 loops=1)
                     Filter: ((entity_id ~~ 'sensor%temperature'::text) AND ("time" > (now() - '7 days'::interval)))
                     Rows Removed by Filter: 74831
 Planning Time: 21.909 ms
 Execution Time: 957.779 ms

In the last case, the number of expected rows is accurate, but the index is not used even though it's a subset of sensor%. If I force the filter to happen after using a materialized CTE, I get the expected plan:

homeassistant=# explain analyze with a as materialized ( select distinct on (entity_id) * from ltest where time > now() - interval '7 day' order by entity_id, time desc) select * from a  where entity_id like 'sensor%temperature';
                                                                                                 QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 CTE Scan on a  (cost=114527.07..114531.77 rows=1 width=264) (actual time=32.072..39.422 rows=14 loops=1)
   Filter: (entity_id ~~ 'sensor%temperature'::text)
   Rows Removed by Filter: 199
   CTE a
     ->  Unique  (cost=197.35..114527.07 rows=209 width=175) (actual time=29.256..39.028 rows=213 loops=1)
           ->  Custom Scan (ConstraintAwareAppend)  (cost=197.35..102308.00 rows=4887627 width=175) (actual time=29.253..38.736 rows=407 loops=1)
                 Hypertable: ltest
                 Chunks left after exclusion: 2
                 ->  Merge Append  (cost=197.35..102308.00 rows=4887627 width=175) (actual time=29.251..38.626 rows=407 loops=1)
                       Sort Key: _hyper_4_61_chunk.entity_id, _hyper_4_61_chunk."time" DESC
                       ->  Custom Scan (SkipScan) on _hyper_4_61_chunk  (cost=0.43..108.41 rows=209 width=180) (actual time=29.140..34.011 rows=213 loops=1)
                             ->  Index Scan using _hyper_4_61_chunk_ltest_entity_id_time_idx on _hyper_4_61_chunk  (cost=0.43..54693.98 rows=616535 width=180) (actual time=29.133..33.803 rows=213 loops=1)
                                   Index Cond: ("time" > (now() - '7 days'::interval))
                       ->  Custom Scan (SkipScan) on _hyper_4_81_chunk  (cost=0.42..97.87 rows=209 width=133) (actual time=0.105..4.384 rows=194 loops=1)
                             ->  Index Scan using _hyper_4_81_chunk_ltest_entity_id_time_idx on _hyper_4_81_chunk  (cost=0.42..3528.89 rows=77068 width=133) (actual time=0.102..4.187 rows=194 loops=1)
                                   Index Cond: ("time" > (now() - '7 days'::interval))
 Planning Time: 17.991 ms
 JIT:
   Functions: 9
   Options: Inlining false, Optimization false, Expressions true, Deforming true
   Timing: Generation 4.205 ms, Inlining 0.000 ms, Optimization 1.082 ms, Emission 27.975 ms, Total 33.263 ms
 Execution Time: 45.225 ms

TimescaleDB version affected

2.6.0

PostgreSQL version used

14

What operating system did you use?

Home assistant OS on rpi 4

What installation method did you use?

Other

What platform did you run on?

On prem/Self-hosted

Relevant log output and stack trace

No response

How can we reproduce the bug?

I have 700k rows in the concerned chunk. If needed, I'll try to create a script for reproduction.

[Yamakaky]

Additional info: if I only select entity_id, I get an index-only SkipScan no matter the pattern. I also tried with create index on ltest(entity_id, time desc) include (friendly_name):

Subquery Scan on last_values  (cost=209.57..7160.22 rows=207 width=47) (actual time=0.527..621.835 rows=4 loops=1)
   ->  Result  (cost=209.57..7158.15 rows=207 width=247) (actual time=0.525..621.827 rows=4 loops=1)
         ->  Unique  (cost=209.57..7158.15 rows=207 width=247) (actual time=0.519..621.809 rows=4 loops=1)
               ->  Custom Scan (ConstraintAwareAppend)  (cost=209.57..7064.10 rows=37621 width=55) (actual time=0.515..621.781 rows=8 loops=1)
                     Hypertable: ltest
                     Chunks left after exclusion: 2
                     ->  Merge Append  (cost=209.57..7064.10 rows=37621 width=55) (actual time=0.513..621.768 rows=8 loops=1)
                           Sort Key: _hyper_4_61_chunk.entity_id, _hyper_4_61_chunk."time" DESC
                           ->  Custom Scan (SkipScan) on _hyper_4_61_chunk  (cost=0.43..1985.35 rows=207 width=55) (actual time=0.322..550.915 rows=4 loops=1)
                                 ->  Index Only Scan using _hyper_4_61_chunk_ltest_entity_id_time_friendly_name_idx on _hyper_4_61_chunk  (cost=0.43..25449.48 rows=2778 width=55) (actual time=0.319..550.894 rows=4 loops=1)
                                       Index Cond: ((entity_id > NULL::text) AND (entity_id >= 'sensor.'::text) AND (entity_id < 'sensor/'::text) AND ("time" > (now() - '7 days'::interval)))
                                       Filter: (entity_id ~~ 'sensor.%_humidity'::text)
                                       Rows Removed by Filter: 590741
                                       Heap Fetches: 18044
                           ->  Custom Scan (SkipScan) on _hyper_4_81_chunk  (cost=0.42..4085.61 rows=207 width=53) (actual time=0.187..70.836 rows=4 loops=1)
                                 ->  Index Only Scan using _hyper_4_81_chunk_ltest_entity_id_time_friendly_name_idx on _hyper_4_81_chunk  (cost=0.42..2723.38 rows=141 width=53) (actual time=0.185..70.818 rows=4 loops=1)
                                       Index Cond: ((entity_id > NULL::text) AND (entity_id >= 'sensor.'::text) AND (entity_id < 'sensor/'::text) AND ("time" > (now() - '7 days'::interval)))
                                       Filter: (entity_id ~~ 'sensor.%_humidity'::text)
                                       Rows Removed by Filter: 74054
                                       Heap Fetches: 2504
 Planning Time: 24.903 ms
 Execution Time: 623.296 ms
(22 rows)

[svenklemm]

This seems to be a planner cost issue not a problem with the SkipScan code itself.

[svenklemm]

@Yamakaky could you provide reproduction steps ideally in the form of a self-contained sql script to reproduce the issue?

[Yamakaky]

I'll try to do that, ok

[github-actions[bot]]

This issue has been automatically marked as stale due to lack of activity. You can remove the stale label or comment. Otherwise, this issue will be closed in 30 days. Thank you!

[github-actions[bot]]

Dear Author,

We are closing this issue due to lack of activity. Feel free to add a comment to this issue if you can provide more information and we will re-open it. Thank you!