core: Slow running queries in HA 2023.6.1 with Postgres

The problem

Postgres 13.9 with a large database

After updating from 2023.5.3 to 2023.6.1, I noticed the following query running every 5 minutes. It takes about 90 seconds to complete and spikes the CPU during that time.

SELECT statistics_short_term.metadata_id, statistics_short_term.start_ts, statistics_short_term.mean, statistics_short_term.min, statistics_short_term.max, statistics_short_term.last_reset_ts, statistics_short_term.state, statistics_short_term.sum 
FROM statistics_short_term JOIN (
  SELECT statistics_short_term.metadata_id AS metadata_id, max(statistics_short_term.start_ts) AS start_max 
  FROM statistics_short_term 
  WHERE statistics_short_term.metadata_id IN (32, 206, 46, 200, 127, 125, 129, 117, 112, 80, 203, 111, 132, 115, 16, 143, 113, 34, 156, 41, 67, 130, 109, 68, 108, 66, 103, 21, 96, 40, 153, 114, 49, 42, 144, 28, 107, 151, 116, 33, 75, 48, 102, 73, 100, 138, 72, 98, 81, 133, 202, 36, 74, 29, 207, 145, 128, 159, 70, 94, 131, 142, 25, 69, 95, 99, 184, 47, 30, 15, 154, 126, 35, 157, 26, 86, 158, 60, 38, 71, 152, 148, 105, 22, 97, 155, 27, 201, 186, 196) 
  GROUP BY statistics_short_term.metadata_id
) AS anon_1 ON statistics_short_term.metadata_id = anon_1.metadata_id AND statistics_short_term.start_ts = anon_1.start_max

After trying to break down the query, I noticed the following simple query can take 1-2 seconds to run:

SELECT statistics_short_term.metadata_id AS metadata_id, 
max(statistics_short_term.start_ts) AS start_max 
FROM statistics_short_term 
WHERE statistics_short_term.metadata_id IN (32) 
GROUP BY statistics_short_term.metadata_id

Explain analyze:

"GroupAggregate  (cost=0.56..129573.43 rows=145 width=12) (actual time=962.568..962.570 rows=1 loops=1)"
"  Group Key: metadata_id"
"  ->  Index Only Scan using ix_statistics_short_term_statistic_id_start_ts on statistics_short_term  (cost=0.56..128757.89 rows=162818 width=12) (actual time=2.218..893.909 rows=170531 loops=1)"
"        Index Cond: (metadata_id = 32)"
"        Heap Fetches: 41957"
"Planning Time: 0.235 ms"
"JIT:"
"  Functions: 4"
"  Options: Inlining false, Optimization false, Expressions true, Deforming true"
"  Timing: Generation 1.275 ms, Inlining 0.000 ms, Optimization 0.586 ms, Emission 14.579 ms, Total 16.440 ms"
"Execution Time: 964.048 ms"

Modifying the query to the following runs quickly:

SELECT statistics_short_term.metadata_id AS metadata_id, 
statistics_short_term.start_ts AS start_max 
FROM statistics_short_term 
WHERE statistics_short_term.metadata_id = 32
ORDER BY statistics_short_term.start_ts DESC
LIMIT 1

Explain analyze:

"Limit  (cost=0.56..1.35 rows=1 width=12) (actual time=0.303..0.304 rows=1 loops=1)"
"  ->  Index Only Scan Backward using ix_statistics_short_term_statistic_id_start_ts on statistics_short_term  (cost=0.56..128757.89 rows=162818 width=12) (actual time=0.301..0.301 rows=1 loops=1)"
"        Index Cond: (metadata_id = 32)"
"        Heap Fetches: 1"
"Planning Time: 0.263 ms"
"Execution Time: 0.344 ms"

I downgraded back to 2023.5.3 and noticed that the same query is running, but with a smaller list of metadata_ids, so it completes in about 15 seconds, which is why I never noticed it before.

Also, possibly unrelated, but I noticed this query running during startup that was also taking a long time (about a minute). It returns no rows.

SELECT events.event_id 
FROM events 
WHERE events.context_id_bin IS NULL 
 LIMIT 1

Explain analyze:

"Limit  (cost=0.00..0.88 rows=1 width=4) (actual time=63302.874..63302.878 rows=0 loops=1)"
"  ->  Seq Scan on events  (cost=0.00..455507.73 rows=519938 width=4) (actual time=63124.419..63124.420 rows=0 loops=1)"
"        Filter: (context_id_bin IS NULL)"
"        Rows Removed by Filter: 12031207"
"Planning Time: 0.354 ms"
"Execution Time: 63303.022 ms"

ix_events_context_id_bin is present but doesn’t appear to be used

I’m not that knowledgable about how indexes work in Postgres but it seems like these queries are not using them.

What version of Home Assistant Core has the issue?

core-2023.6.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

No response

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

About this issue

  • Original URL
  • State: closed
  • Created a year ago
  • Comments: 41 (38 by maintainers)

Commits related to this issue

Most upvoted comments

https://github.com/home-assistant/core/pull/100535 should solve the primary issue and its also much faster for all dbms

Would you mind opening a new issue for the slow startup query? This one is going to close out when the linked PR merges so I don’t want that issue to get forgotten about.

Sure: #100536