The `recorder.states` table does not have index on `old_state_id` column #44736

ayufan · 2021-01-01T15:40:47Z

The problem

I have serious problems removing data from PSQL with recorder:.

It appears that this is due to amount of records stored, and size of data, it simply takes ages to execute:

hass=# select count(*) from events;
  count  
---------
 3614166
(1 row)

hass=# select count(*) from states;
  count  
---------
 3594602
(1 row)

I looked at indexes of the questioned tables, and they current look following:

hass=# \d states;
                                           Table "public.states"
    Column    |           Type           | Collation | Nullable |                 Default                  
--------------+--------------------------+-----------+----------+------------------------------------------
 state_id     | integer                  |           | not null | nextval('states_state_id_seq'::regclass)
 domain       | character varying(64)    |           |          | 
 entity_id    | character varying(255)   |           |          | 
 state        | character varying(255)   |           |          | 
 attributes   | text                     |           |          | 
 event_id     | integer                  |           |          | 
 last_changed | timestamp with time zone |           |          | 
 last_updated | timestamp with time zone |           |          | 
 created      | timestamp with time zone |           |          | 
 old_state_id | integer                  |           |          | 
Indexes:
    "states_pkey" PRIMARY KEY, btree (state_id)
    "ix_states_entity_id_last_updated" btree (entity_id, last_updated)
    "ix_states_event_id" btree (event_id)
    "ix_states_last_updated" btree (last_updated)
Foreign-key constraints:
    "states_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id)
    "states_old_state_id_fkey" FOREIGN KEY (old_state_id) REFERENCES states(state_id)
Referenced by:
    TABLE "states" CONSTRAINT "states_old_state_id_fkey" FOREIGN KEY (old_state_id) REFERENCES states(state_id)

hass=# \d events;
                                             Table "public.events"
      Column       |           Type           | Collation | Nullable |                 Default                  
-------------------+--------------------------+-----------+----------+------------------------------------------
 event_id          | integer                  |           | not null | nextval('events_event_id_seq'::regclass)
 event_type        | character varying(32)    |           |          | 
 event_data        | text                     |           |          | 
 origin            | character varying(32)    |           |          | 
 time_fired        | timestamp with time zone |           |          | 
 created           | timestamp with time zone |           |          | 
 context_id        | character varying(36)    |           |          | 
 context_user_id   | character varying(36)    |           |          | 
 context_parent_id | character varying(36)    |           |          | 
Indexes:
    "events_pkey" PRIMARY KEY, btree (event_id)
    "ix_events_context_id" btree (context_id)
    "ix_events_context_parent_id" btree (context_parent_id)
    "ix_events_context_user_id" btree (context_user_id)
    "ix_events_event_type_time_fired" btree (event_type, time_fired)
    "ix_events_time_fired" btree (time_fired)
Referenced by:
    TABLE "states" CONSTRAINT "states_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id)

Looking at data structure it appears the following:

states.old_state_id has FK, but lacks an index causing the need to load the whole table on the object removal due to FK
states.event_id and states.old_state_id FK is a constraint validation, but does not have ON DELETE SET NULL set which results in blocking DELETEs from being executed

The above seems to prevent timely removal of data, causing extensive time to run DELETE, second crashing this DELETE due to FK violations.

I run the following commands to remedy and alter DB structure, and after doing this deletes are successfully executed.

create index tmp_ix_states_old_state_id ON states (old_state_id) WHERE old_state_id IS NOT NULL;

alter table states drop constraint "states_event_id_fkey";
alter table states drop constraint "states_old_state_id_fkey";

alter table states add constraint "states_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE SET NULL;
alter table states add constraint "states_old_state_id_fkey" FOREIGN KEY (old_state_id) REFERENCES states(state_id) ON DELETE SET NULL;

Note: This likely affects any other DB than PSQL as well

Environment

Home Assistant Core release with the issue: Home Assistant 2020.12.1
Last working Home Assistant Core release (if known):
Operating environment (OS/Container/Supervised/Core): Ubuntu 20.04 running on armv7l via official Docker Image
Integration causing this issue:
Link to integration documentation on our website:

Problem-relevant `configuration.yaml`

Traceback/Error logs

Additional information

The text was updated successfully, but these errors were encountered:

bdraco · 2021-01-02T08:12:44Z

It looks like the database was created before #43610 and somehow didn't get the SET NULL and CASCADE added on update.

Edit: it looks like we did add an index on old_state_id, however the db schema was never upgraded to add it.

ayufan · 2021-01-02T09:13:45Z

@bdraco

The index is required otherwise in some cases for some DB FK will fail to be created, or in other it will be super slow to delete due to having to perform sequential scan instead of index scan on data removal. We need to check if state_id of object being now deleted is not in old_state_id.

As for the FK, this is great. I will check it.

ayufan · 2021-01-02T09:17:26Z

@bdraco

Interesting. I also checked if my install has _update_states_table_with_foreign_key_options, and it does have. Unsure why it was not migrated.

Edit: Looking at this https://github.com/home-assistant/core/pull/43610/files#diff-b13fb7a9fcbe98090c51f229ca8305a0690ae42a633346b177574ee43b3a31c8R235. I don't really see anything that would set FK constraint to ON CASCADE or SET NULL. It is only present when creating DB from scratch.

bdraco · 2021-01-02T17:42:17Z

Its likely postgresql might have some type of default that prevents _update_states_table_with_foreign_key_options from seeing it needs to be added.

I don't have a working postgresql setup at the moment so its not something I can validate right now. I'll leave the linked PR as a draft and see why _update_states_table_with_foreign_key_options didn't make the change.

It would be helpful to know which version of postgresql you are running.

ayufan · 2021-01-02T17:45:14Z

@bdraco I use 12. If you could help to get some repl shell on HASS instance (in some generic way) I could check myself why it did not work.

ayufan · 2021-01-03T15:41:22Z

@bdraco Thank you for a quick fix :)

sqldiablo · 2021-01-08T17:11:57Z

@bdraco I'm seeing the errors below when starting Home Assistant. I use Microsoft SQL Server for my recorder database. Will the fix in #44757 also address this FK issue in MS SQL?

1/8/2021 12:06:22 PM2021-01-08 17:06:22 ERROR (MainThread) [homeassistant.setup] Setup of recorder is taking longer than 300 seconds. Startup will proceed without waiting any longer
1/8/2021 12:06:22 PM2021-01-08 17:06:22 ERROR (Recorder) [sqlalchemy.pool.impl.QueuePool] Exception during reset or similar
1/8/2021 12:06:22 PMTraceback (most recent call last):
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
1/8/2021 12:06:22 PM self.dialect.do_execute(
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 593, in do_execute
1/8/2021 12:06:22 PM cursor.execute(statement, parameters)
1/8/2021 12:06:22 PMpyodbc.ProgrammingError: ('42000', "[42000] [FreeTDS][SQL Server]Introducing FOREIGN KEY constraint 'FK__states__old_stat__5441852A' on table 'states' may cause cycles or multiple cascade paths. Specify ON DELETE NO ACTION or ON UPDATE NO ACTION, or modify other FOREIGN KEY constraints. (1785) (SQLExecDirectW)")
1/8/2021 12:06:22 PM
1/8/2021 12:06:22 PMDuring handling of the above exception, another exception occurred:
1/8/2021 12:06:22 PM
1/8/2021 12:06:22 PMTraceback (most recent call last):
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 749, in _rollback_impl
1/8/2021 12:06:22 PM self.engine.dialect.do_rollback(self.connection)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 543, in do_rollback
1/8/2021 12:06:22 PM dbapi_connection.rollback()
1/8/2021 12:06:22 PMpyodbc.ProgrammingError: ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')
1/8/2021 12:06:22 PM
1/8/2021 12:06:22 PMThe above exception was the direct cause of the following exception:
1/8/2021 12:06:22 PM
1/8/2021 12:06:22 PMTraceback (most recent call last):
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2087, in _optional_conn_ctx_manager
1/8/2021 12:06:22 PM yield conn
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2095, in _run_visitor
1/8/2021 12:06:22 PM conn._run_visitor(visitorcallable, element, **kwargs)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1656, in _run_visitor
1/8/2021 12:06:22 PM visitorcallable(self.dialect, self, **kwargs).traverse_single(element)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/visitors.py", line 145, in traverse_single
1/8/2021 12:06:22 PM return meth(obj, **kw)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/ddl.py", line 783, in visit_metadata
1/8/2021 12:06:22 PM self.traverse_single(
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/visitors.py", line 145, in traverse_single
1/8/2021 12:06:22 PM return meth(obj, **kw)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/ddl.py", line 827, in visit_table
1/8/2021 12:06:22 PM self.connection.execute(
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1011, in execute
1/8/2021 12:06:22 PM return meth(self, multiparams, params)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/ddl.py", line 72, in _execute_on_connection
1/8/2021 12:06:22 PM return connection._execute_ddl(self, multiparams, params)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1068, in _execute_ddl
1/8/2021 12:06:22 PM ret = self._execute_context(
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1316, in _execute_context
1/8/2021 12:06:22 PM self._handle_dbapi_exception(
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1505, in handle_dbapi_exception
1/8/2021 12:06:22 PM self.autorollback()
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/langhelpers.py", line 82, in exit
1/8/2021 12:06:22 PM compat.raise(value, with_traceback=traceback)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise
1/8/2021 12:06:22 PM raise exception
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1505, in _handle_dbapi_exception
1/8/2021 12:06:22 PM self._autorollback()
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 888, in _autorollback
1/8/2021 12:06:22 PM self._root._rollback_impl()
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 751, in _rollback_impl
1/8/2021 12:06:22 PM self.handle_dbapi_exception(e, None, None, None, None)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1405, in handle_dbapi_exception
1/8/2021 12:06:22 PM util.raise(
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise
1/8/2021 12:06:22 PM raise exception
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 749, in _rollback_impl
1/8/2021 12:06:22 PM self.engine.dialect.do_rollback(self.connection)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 543, in do_rollback
1/8/2021 12:06:22 PM dbapi_connection.rollback()
1/8/2021 12:06:22 PMsqlalchemy.exc.ProgrammingError: (pyodbc.ProgrammingError) ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')
1/8/2021 12:06:22 PM(Background on this error at: http://sqlalche.me/e/13/f405)
1/8/2021 12:06:22 PM
1/8/2021 12:06:22 PMDuring handling of the above exception, another exception occurred:
1/8/2021 12:06:22 PM
1/8/2021 12:06:22 PMTraceback (most recent call last):
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/pool/base.py", line 697, in _finalize_fairy
1/8/2021 12:06:22 PM fairy._reset(pool)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/pool/base.py", line 893, in _reset
1/8/2021 12:06:22 PM pool._dialect.do_rollback(self)
1/8/2021 12:06:22 PM File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 543, in do_rollback
1/8/2021 12:06:22 PM dbapi_connection.rollback()
1/8/2021 12:06:22 PMpyodbc.ProgrammingError: ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')
1/8/2021 12:06:22 PM2021-01-08 17:06:22 ERROR (Recorder) [homeassistant.components.recorder] Error during connection setup: (pyodbc.ProgrammingError) ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')

frenck · 2021-01-08T17:13:06Z

@sqldiablo This issue has been fixed, closed and handled. If you have a new issue, please open up a new issue accordingly. Thanks 👍

sqldiablo · 2021-01-08T17:15:21Z

I was just wanting to know if the fix in the PR targets MS SQL as well, as it looks like it's specifically targeting MySQL and Postgres. If @bdraco lets me know it won't fix the issue in MS SQL as well, then I'll be glad to open a new issue. I just didn't want to create issue spam if my issue is already fixed by the PR.

frenck · 2021-01-08T17:18:21Z

You are now bumping a closed issue, possibly polluting it with unrelated information. Your data is not fully complete, as you are not using an issue template and you are above all pinging and mentioning people (which one should generally not).

Lastly, closed issues are not tracked anymore and notify all participants, possibility unessesarry.

Could you just, please, raise a new issue instead? Thanks 👍

frenck added the integration: recorder label Jan 1, 2021

bdraco mentioned this issue Jan 2, 2021

Add index to old_state_id column for postgres and older databases #44757

Merged

21 tasks

frenck closed this as completed in #44757 Jan 4, 2021

sqldiablo mentioned this issue Jan 8, 2021

Recorder fails during FK creation on states table (MS SQL) #44958

Closed

github-actions bot locked and limited conversation to collaborators Feb 7, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

The `recorder.states` table does not have index on `old_state_id` column #44736

The `recorder.states` table does not have index on `old_state_id` column #44736

ayufan commented Jan 1, 2021 •

edited

bdraco commented Jan 2, 2021 •

edited

ayufan commented Jan 2, 2021 •

edited

ayufan commented Jan 2, 2021 •

edited

bdraco commented Jan 2, 2021

ayufan commented Jan 2, 2021

ayufan commented Jan 3, 2021

sqldiablo commented Jan 8, 2021 •

edited

frenck commented Jan 8, 2021

sqldiablo commented Jan 8, 2021

frenck commented Jan 8, 2021

The recorder.states table does not have index on old_state_id column #44736

The recorder.states table does not have index on old_state_id column #44736

Comments

ayufan commented Jan 1, 2021 • edited

The problem

Environment

Problem-relevant configuration.yaml

Traceback/Error logs

Additional information

bdraco commented Jan 2, 2021 • edited

ayufan commented Jan 2, 2021 • edited

ayufan commented Jan 2, 2021 • edited

bdraco commented Jan 2, 2021

ayufan commented Jan 2, 2021

ayufan commented Jan 3, 2021

sqldiablo commented Jan 8, 2021 • edited

frenck commented Jan 8, 2021

sqldiablo commented Jan 8, 2021

frenck commented Jan 8, 2021

The `recorder.states` table does not have index on `old_state_id` column #44736

The `recorder.states` table does not have index on `old_state_id` column #44736

ayufan commented Jan 1, 2021 •

edited

Problem-relevant `configuration.yaml`

bdraco commented Jan 2, 2021 •

edited

ayufan commented Jan 2, 2021 •

edited

ayufan commented Jan 2, 2021 •

edited

sqldiablo commented Jan 8, 2021 •

edited