[Bug]: Incorrect Index choice based on filtering crieteria

[gustavo-delfosim]

What type of bug is this?

Performance issue

What subsystems and features are affected?

Query planner

What happened?

This is a bug report following a discussion started in Slack with @davidkohn88 . I got it "solved" for my use-case by deleting the "bad" index used by Query 2 (see below). However, @davidkohn88 believes it could be a bug related to the query planner, so I am reporting here to hopefully help TimescaleDB team to track and fix it.

---

I am getting a very strange query plan when using timestamp filters with non-comple 'hours', i.e., with a timestamp with HH:MM not being 00:00.

Query 1:

explain
select *
from variable.signal_data sd 
where tag_id in (6846, 6899)
and "timestamp" > '2022-10-27 00:00'
and "timestamp" <= '2022-10-28 00:00'
order by "timestamp"

Planner 1:

Sort  (cost=44281.11..44486.14 rows=82011 width=28)
  Sort Key: sd."timestamp"
  ->  Index Scan using _hyper_2_200_chunk_ix_tag_id_timestamp_desc on _hyper_2_200_chunk sd  (cost=0.56..37587.57 rows=82011 width=28)
        Index Cond: ((tag_id = ANY ('{6846,6899}'::integer[])) AND ("timestamp" > '2022-10-27 00:00:00'::timestamp without time zone) AND ("timestamp" <= '2022-10-28 00:00:00'::timestamp without time zone))

Query 2: Only changing the timestamp <= ... filter by 1 minute!

explain
select *
from variable.signal_data sd 
where tag_id in (6846, 6899)
and "timestamp" > '2022-10-27 00:00'
and "timestamp" <= '2022-10-27 23:59'
order by "timestamp" 
Planner:
Index Scan Backward using _hyper_2_200_chunk_signal_data_timestamp_idx on _hyper_2_200_chunk sd  (cost=0.44..2.66 rows=1 width=28)
  Index Cond: (("timestamp" > '2022-10-27 00:00:00'::timestamp without time zone) AND ("timestamp" <= '2022-10-27 23:59:00'::timestamp without time zone))
  Filter: (tag_id = ANY ('{6846,6899}'::integer[]))

For some reason, Query 2 is not able to use the (tag_id, timestamp desc) index used by Query 1. The are many tag_ids in this table, so the planning on Query 2 leads to very bad performance.
I already tried to run reorder_chunk on that given chunk (_hyper_2_200_chunk), but without success.
Any insight on why it is happening?

TimescaleDB version affected

2.6.0

PostgreSQL version used

14.2

What operating system did you use?

Probably some recent version of Debian or Ubuntu, not sure.

What installation method did you use?

Docker

What platform did you run on?

Not applicable

Relevant log output and stack trace

No response

How can we reproduce the bug?

I tried to reproduce it by recreating a table with the same configuration and copying the data into it, but the new table ended up using the correct index.
Unfortunately I cannot share the data of the table, but please let me know if I can help with anything else.

[akuzm]

Would be good to have:

• table and index definitions
• full EXPLAIN ANALYZE for both queries.

We can see that the postgres planner thinks only one row is going to match the second query, let's check how many actually match looking at EXPLAIN ANALYZE. If this estimate is off, maybe running ANALYZE on the table will help?

The reorder_chunk just changes the order in which the data is stored, and won't influence the choice of plans.

[gustavo-delfosim]

Hi @akuzm

Table and index definitions below:

CREATE TABLE variable.signal_data (
	tag_id int4 NOT NULL,
	"timestamp" timestamp NOT NULL,
	value float8 NULL,
	updated_at timestamp NULL,
	PRIMARY KEY (tag_id, "timestamp"),
	FOREIGN KEY (tag_id) REFERENCES variable.signal_tag(id) ON DELETE CASCADE ON UPDATE CASCADE
);
CREATE UNIQUE INDEX ON variable.signal_data USING btree (tag_id, "timestamp" DESC);
CREATE INDEX  ON variable.signal_data USING btree ("timestamp" DESC);

Unfortunately, I can't run the full EXPLAIN ANALYZE anymore because I ended up deleting the two indexes other than the Primary Key, which ended up solving the problem, as the planner picked up the correct index (the only one remaining, the PK) for the query.

However, I tried running ANALYZE directly in the targeted chunk, but it did not help.

[akuzm]

Can you run the two following queries? This will help us check how many rows there actually are, because planner thinks there's only one matching row for some reason.

explain analyze
select *
from variable.signal_data sd 
where tag_id in (6846, 6899)
and "timestamp" > '2022-10-27 00:00'
and "timestamp" <= '2022-10-27 23:59'
order by "timestamp";


explain analyze
select *
from _timescaledb_internal._hyper_2_200_chunk sd 
where tag_id in (6846, 6899)
and "timestamp" > '2022-10-27 00:00'
and "timestamp" <= '2022-10-27 23:59'
order by "timestamp";

We're looking here at the general postgres planner behavior, not specific to TimescaleDB. If ANALYZE doesn't help, and the estimate is badly off, we'll have to look at the actual data to debug this.

By the way, if dropping indexes works for you, there's also the create_default_indexes => false argument to create_hypertable that prevents creating them in the first place.

[gustavo-delfosim]

As requested:

Querying the hypertable:

Sort  (cost=1322.05..1324.89 rows=1138 width=28) (actual time=0.114..0.130 rows=287 loops=1)
  Sort Key: sd."timestamp"
  Sort Method: quicksort  Memory: 47kB
  ->  Index Scan using "200_400_pk_signal_data" on _hyper_2_200_chunk sd  (cost=0.57..1264.28 rows=1138 width=28) (actual time=0.022..0.087 rows=287 loops=1)
        Index Cond: ((tag_id = ANY ('{6846,6899}'::integer[])) AND ("timestamp" > '2022-10-27 00:00:00'::timestamp without time zone) AND ("timestamp" <= '2022-10-27 23:59:00'::timestamp without time zone))
Planning Time: 0.306 ms
Execution Time: 0.153 ms

Querying the chunk directly:

Sort  (cost=1322.05..1324.89 rows=1138 width=28) (actual time=0.115..0.131 rows=287 loops=1)
  Sort Key: "timestamp"
  Sort Method: quicksort  Memory: 47kB
  ->  Index Scan using "200_400_pk_signal_data" on _hyper_2_200_chunk sd  (cost=0.57..1264.28 rows=1138 width=28) (actual time=0.021..0.087 rows=287 loops=1)
        Index Cond: ((tag_id = ANY ('{6846,6899}'::integer[])) AND ("timestamp" > '2022-10-27 00:00:00'::timestamp without time zone) AND ("timestamp" <= '2022-10-27 23:59:00'::timestamp without time zone))
Planning Time: 0.273 ms
Execution Time: 0.156 ms

---

Thanks for the tip on the create_default_indexes. I already changed the (hyper)table definition code considering it.

[gustavo-delfosim]

Also, some details about the data, which may or may not be helpful...
One of the tags has data for every 5-minutes, the other one only has one data point per day (which is written at time 00:00:00).

[gustavo-delfosim]

There is one test that I performed with @davidkohn88 which I think is worth sharing, too.

I copied the data in the chunk to a test table (a normal PostgreSQL table, not converted to an hypertable).
I just used a smaller chunk, but I can reproduce the issues with it.

CREATE TABLE variable.signal_data_test (
	tag_id int4 NOT NULL,
	"timestamp" timestamp NOT NULL,
	value float8 NULL,
	updated_at timestamp NULL,
	PRIMARY KEY (tag_id, "timestamp"),
	FOREIGN KEY (tag_id) REFERENCES variable.signal_tag(id) ON DELETE CASCADE ON UPDATE CASCADE
);
CREATE UNIQUE INDEX ON variable.signal_data_test USING btree (tag_id, "timestamp" DESC);
CREATE INDEX  ON variable.signal_data_test USING btree ("timestamp" DESC);

insert into variable.signal_data_test
select
    *
from
    _timescaledb_internal._hyper_2_236_chunk;

Then I queried with both where clauses. In both cases, the planner picked up the composite index.

[akuzm]

Sort (cost=1322.05..1324.89 rows=1138 width=28) (actual time=0.114..0.130 rows=287 loops=1)

So, now the estimate is magically fixed 😄 It doesn't say rows = 1 anymore. If this happens again, I'd recommend looking at EXPLAIN ANALYZE and comparing the estimated and the actual number of rows for the various plan nodes. The wrong row count estimates are the most frequent cause of the wrong choice of the plans. If it's not fixed by running ANALYZE on your table, it's probably some limitation or a bug in Postgres cost estimates, but these normally require the full data to reproduce and debug. Most often these problems happen with joins. For plain SELECTs like this one the estimates are normally OK.

I just used a smaller chunk, but I can reproduce the issues with it. ... Then I queried with both where clauses. In both cases, the planner picked up the composite index.

This mean the issue does not reproduce, right? The composite index is the correct one we want it to choose.

[gustavo-delfosim]

Yeah, it is fixed, but I can't tell how it got fixed. I am pretty sure that I have run ANALYZE and it had no effect in the past.

Unfortunately, I can't reproduce the issue anymore, as I deleted the index to get things working asap since it happened in our production environment.

In the current state, I think I can't provide more information to maybe find a bug or just make sure I had a bad estimate in the table, so feel free to close this issue as you see fit. If I find any similar problem, I will try to collect more evidence and open a new bug report.

---

This mean the issue does not reproduce, right? The composite index is the correct one we want it to choose.

Hmm, actually, no. I meant that the issue can be reproduced in both chunks, i.e., the problem persisted (until I deleted the index and then everything is solved).

[davidkohn88]

Yes, to be clear, I asked him to do this because I've seen issues with this in the past, it seems to pop up intermittently, and I'd never thought to do the test where we copy the data from a chunk into a normal Postgres table with the same schema and run the same query.

To summarize what he did as I understand it: he was able to reproduce a) the bad behavior on the chunk he copied over when querying the hypertable and b) the good behavior on the Postgres table with all of the same indexes etc.

He can't reproduce the behavior now, because he dropped the time only index in order to skirt the problem and solve it quickly on the production table.

@gustavo-delfosim I think you might be able to reproduce the behavior if you create a hypertable with both indexes, and copy the data from the one chunk you already have in the normal Postgres table over to that? Then we could run some more tests for @akuzm ? But it might be harder to reproduce if there's only one chunk, not sure.

[gustavo-delfosim]

@davidkohn88 Yeah, thanks for summarizing, that's exactly what happened.

I can try to reproduce it again with a new table and copying more data into it, but I will need to fine some time to looking into it. I will report back if I am able to reproduce it

[akuzm]

What we can check next time it reproduces, to help investigate the problem:

• reduce the plan to scan purely on one chunk, verify it still doesn't use the index
• run ANALYZE on the chunk, see if it helps
• select * from pg_class for the chunk to look at the tuple/page stats
• perform VACUUM FULL on the chunk, see if it helps
• temporarily disable the wrong index setting indisvalid = f . Compare the plan costs with the wrong and the right index.
• check that we don't use extended statistics, it has known problems with index choice: https://www.postgresql.org/message-id/flat/[email protected]

[github-actions]

Dear Author,

This issue has been automatically marked as stale due to lack of activity. With only the issue description that is currently provided, we do not have enough information to take action. If you have or find the answers we would need, please reach out. Otherwise, this issue will be closed in 30 days. Thank you!

[github-actions]

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!

[sithmein]

I currently struggling with a very similar situation. Also in my case the time-only index is being used instead of the composite index for entity and time. The query plans show the using the "right" index is about three times faster. The first query plan uses the wrong, time-only index. After disabling this index the second query uses the right composite index and is significantly faster.

ha_history=# explain analyze SELECT ltss.time AS tb, ltss.state::float AS state
         FROM ltss
         WHERE entity_id = 'sensor.solaredge_consumption' AND ltss.time > '2023-05-25T22:00:00Z' AND ltss.time < '2023-05-26T22:00:00.0Z'
         ORDER BY tb;
                                                                                    QUERY PLAN                                                                                     
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Result  (cost=0.43..22656.35 rows=25861 width=16) (actual time=0.091..838.597 rows=24201 loops=1)
   ->  Index Scan Backward using _hyper_1_360_chunk_ltss_time_idx on _hyper_1_360_chunk  (cost=0.43..22268.43 rows=25861 width=15) (actual time=0.080..686.043 rows=24201 loops=1)
         Index Cond: (("time" > '2023-05-26 00:00:00+02'::timestamp with time zone) AND ("time" < '2023-05-27 00:00:00+02'::timestamp with time zone))
         Filter: ((entity_id)::text = 'sensor.solaredge_consumption'::text)
         Rows Removed by Filter: 352657
 Planning Time: 1.555 ms
 Execution Time: 907.537 ms
(7 rows)

ha_history=# update pg_index set indisvalid = false where indexrelid = '_timescaledb_internal._hyper_1_360_chunk_ltss_time_idx'::regclass;
UPDATE 1
ha_history=# explain analyze SELECT ltss.time AS tb, ltss.state::float AS state
         FROM ltss
         WHERE entity_id = 'sensor.solaredge_consumption' AND ltss.time > '2023-05-25T22:00:00Z' AND ltss.time < '2023-05-26T22:00:00.0Z'
         ORDER BY tb;
                                                                                                      QUERY PLAN                                                                                                      
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Result  (cost=0.55..23424.05 rows=25859 width=16) (actual time=0.137..286.897 rows=24205 loops=1)
   ->  Index Scan Backward using _hyper_1_360_chunk_ltss_entityid_time_composite_idx on _hyper_1_360_chunk  (cost=0.55..23036.17 rows=25859 width=15) (actual time=0.127..131.570 rows=24205 loops=1)
         Index Cond: (((entity_id)::text = 'sensor.solaredge_consumption'::text) AND ("time" > '2023-05-26 00:00:00+02'::timestamp with time zone) AND ("time" < '2023-05-27 00:00:00+02'::timestamp with time zone))
 Planning Time: 1.664 ms
 Execution Time: 358.608 ms
(5 rows)

Basically none of my queries will use the composite index and all of them have the entity_id as filter condition.
I ran ANALYZE and VACCUUM FULL, nothing helped. Any suggestion? Do you need more information in order to investigate?

[jnidzwetzki]

Hello @sithmein,

Thanks for providing all this information. As you said, the query runs faster when the composite index is used (actual execution time: 286.897 ms (composite index) vs. 838.597 ms (normal index)). However, during query planning, PostgreSQL expects a slightly higher execution time when the composite index is used (23424.05 on entityid_time_composite_idx vs. 22656.35 on ltss_time_idx). Therefore, PostgreSQL selects the simple and not the composite index.

What happens when you run the query directly against the chunk _timescaledb_internal._hyper_1_360 (and not the table ltss)? Does PostgreSQL select the composite index in this case? Could you provide us with the explain analyze output of this query?

[sithmein]

I also tried on the latest chunk with the same results.
Meanwhile I have deleted the offending index therefore I have to create a dump first and import it into another instance. This can take a few days.

[jnidzwetzki]

Hi @sithmein,

Thanks for getting back to us. It would be great if you could repeat this and send us the output of the EXPLAIN (ANALYZE) queries. This would help us to understand the problem much better.

[SHxKM]

@sithmein can you shed some light on how you ended up fixing the issue? It seems like this isn’t close to being resolved. We are experiencing the exact same issue in production and would love to resolve this ASAP. Which index did you end up dropping/re-creating? Only difference is we're using a distributed hypertable..

[jkuri]

Hi, we are facing the exact same issue, on some chunks of hypertable wrong index is used (single column) but we have multicolumn index added. I am testing this on a simple select query, note that this table is huge;

explain analyze select * from competitor_results where competitor_id = 106302 and created_at between '2023-04-01' and '2023-06-01';
                                                                                             QUERY PLAN                                                                                             
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Append  (cost=0.00..1044934.73 rows=1170117 width=168) (actual time=93.403..4657.537 rows=1138932 loops=1)
   ->  Seq Scan on competitor_results  (cost=0.00..0.00 rows=1 width=136) (actual time=0.003..0.003 rows=0 loops=1)
         Filter: ((created_at >= '2023-04-01 00:00:00'::timestamp without time zone) AND (created_at <= '2023-06-01 00:00:00'::timestamp without time zone) AND (competitor_id = 106302))
   ->  Bitmap Heap Scan on _hyper_2_507_chunk  (cost=10770.51..586978.35 rows=634019 width=168) (actual time=93.399..2504.064 rows=626350 loops=1)
         Recheck Cond: ((competitor_id = 106302) AND (created_at >= '2023-04-01 00:00:00'::timestamp without time zone) AND (created_at <= '2023-06-01 00:00:00'::timestamp without time zone))
         Rows Removed by Index Recheck: 14806542
         Heap Blocks: exact=42539 lossy=208208
         ->  Bitmap Index Scan on _hyper_2_507_chunk_competitor_results_hyper_competitor_id_creat  (cost=0.00..10612.00 rows=634019 width=0) (actual time=83.864..83.867 rows=626350 loops=1)
               Index Cond: ((competitor_id = 106302) AND (created_at >= '2023-04-01 00:00:00'::timestamp without time zone) AND (created_at <= '2023-06-01 00:00:00'::timestamp without time zone)
   ->  Bitmap Heap Scan on _hyper_2_510_chunk  (cost=5772.32..457956.38 rows=536097 width=169) (actual time=76.031..2083.065 rows=512582 loops=1)
         Recheck Cond: (competitor_id = 106302)
         Rows Removed by Index Recheck: 12325718
         Filter: ((created_at >= '2023-04-01 00:00:00'::timestamp without time zone) AND (created_at <= '2023-06-01 00:00:00'::timestamp without time zone))
         Heap Blocks: exact=47950 lossy=173593
         ->  Bitmap Index Scan on _hyper_2_510_chunk_competitor_results_hyper_competitor_id_idx  (cost=0.00..5638.30 rows=536097 width=0) (actual time=64.878..64.879 rows=512582 loops=1)
               Index Cond: (competitor_id = 106302)
 Planning time: 13.877 ms
 Execution time: 4699.353 ms

If you check above explain analyze from the first chunk, right index is used and from the second chunk its using single column index. Why is this happening?

I checked the _hyper_2_510_chunk and it includes the index that should be used, also I did run vacuum and vacuum full on that chunk:

\d+ _timescaledb_internal._hyper_2_510_chunk;
                                                            Table "_timescaledb_internal._hyper_2_510_chunk"
          Column           |            Type             | Collation | Nullable |                    Default                     | Storage  | Stats target | Description 
---------------------------+-----------------------------+-----------+----------+------------------------------------------------+----------+--------------+-------------
 id                        | integer                     |           | not null | nextval('competitor_results_id_seq'::regclass) | plain    |              | 
 position                  | integer                     |           |          |                                                | plain    |              | 
 change                    | integer                     |           |          |                                                | plain    |              | 
 search_keyword_url_id     | integer                     |           | not null |                                                | plain    |              | 
 search_keyword_id         | integer                     |           | not null |                                                | plain    |              | 
 competitor_id             | integer                     |           | not null |                                                | plain    |              | 
 search_keyword_result_id  | integer                     |           | not null |                                                | plain    |              | 
 created_at                | timestamp without time zone |           |          |                                                | plain    |              | 
 updated_at                | timestamp without time zone |           |          |                                                | plain    |              | 
 copied_from_id            | integer                     |           |          |                                                | plain    |              | 
 account_id                | integer                     |           |          |                                                | plain    |              | 
 result_url                | text                        |           |          |                                                | extended |              | 
 position_type             | character varying           |           |          |                                                | extended |              | 
 position_organic          | integer                     |           |          |                                                | plain    |              | 
 position_local_pack       | integer                     |           |          |                                                | plain    |              | 
 position_places_image     | integer                     |           |          |                                                | plain    |              | 
 position_featured_snippet | integer                     |           |          |                                                | plain    |              | 
 position_knowledge_panel  | integer                     |           |          |                                                | plain    |              | 
Indexes:
    "_hyper_2_510_chunk_competitor_results_hyper_competitor_id_creat" btree (competitor_id, created_at)
    "_hyper_2_510_chunk_competitor_results_hyper_competitor_id_idx" btree (competitor_id)
    "_hyper_2_510_chunk_competitor_results_hyper_created_at_idx" btree (created_at DESC)
    "_hyper_2_510_chunk_competitor_results_hyper_id_idx" btree (id)
    "_hyper_2_510_chunk_competitor_results_hyper_search_keyword_id_i" btree (search_keyword_id)
    "_hyper_2_510_chunk_competitor_results_hyper_search_keyword_resu" btree (search_keyword_result_id)
    "_hyper_2_510_chunk_competitor_results_hyper_search_keyword_ur_1" btree (search_keyword_url_id)
    "_hyper_2_510_chunk_competitor_results_hyper_search_keyword_url_" btree (search_keyword_url_id, created_at DESC)
Check constraints:
    "constraint_510" CHECK (created_at >= '2023-04-23 00:00:00'::timestamp without time zone AND created_at < '2023-05-23 00:00:00'::timestamp without time zone)
Inherits: competitor_results

Any help or suggestions how to make query plan picking the right index would be highly appreciated.

[jnidzwetzki]

Hello @jkuri,

Thanks for reporting this problem. According to the query plan, two chunks are part of the query and PostgreSQL uses the composite index _hyper_2_507_chunk_competitor_results_hyper_competitor_id_creat for the chunk _hyper_2_507_chunk. For the chunk _hyper_2_510_chunk, the simple index _hyper_2_510_chunk_competitor_results_hyper_competitor_id_idx is chosen.

Which version of TimescaleDB do you use? Does the query plan change if you perform an ANALYZE _timescaledb_internal._hyper_2_510_chunk statement before?

[jkuri]

Hi @jnidzwetzki,

thank you for the quick response. I am testing this on 1.7.5 version of TimescaleDB which is similar to our production server, but we will need to update it soon anyway.

I performed analyze _timescaledb_internal._hyper_2_510_chunk but the query plan didn't changed, its still uses the simple index.

I'd like to ask when I have a chance about the performance issues on that hypertable, why is simple select taking so long to return the result? If I pick a date range for 6 months for example, the simple query takes about a minute to execute, but that is a common case.
This hypertable size is;

 table_size | index_size | toast_size | total_size 
------------+------------+------------+------------
 194 GB     | 335 GB     | 776 kB     | 530 GB

And each chunk is about 10GB in size, is it that too much? Should I choose smaller interval to create new chunks?

[jnidzwetzki]

Hello @jkuri,

Version 1.7.5 of TimescaleDB is a very old version. I recommend upgrading to TimescaleDB 2.11 and checking the query plan and the execution time again. The new TimescaleDB version contains a lot of bug fixes and additional optimizations.

The chunk size has to match your use case and the hardware you are using. On the following two pages of our documentation, you will find several tips on determining an appropriate chunk size (page 1, page 2).

[jkuri]

hi @jnidzwetzki,

okay, we will update the database version and will come back with the results. thanks for your help.

[github-actions]

Dear Author,

This issue has been automatically marked as stale due to lack of activity. With only the issue description that is currently provided, we do not have enough information to take action. If you have or find the answers we would need, please reach out. Otherwise, this issue will be closed in 30 days.

Thank you!

[github-actions]

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!