Recorder transaction issue on 0.108.x

KiLLeRRaT commented 4 years ago

The problem

After upgrading to from 0.107 to 0.108 (any of those versions) I satrted noticing very high SQL Server CPU usage. Running SP_WHO2 shows blocking transactions. I also found the below errors with deadlocks, as well as COMMIT TRANSACTION without a BEGIN TRANSACTION.

I have a question related to this. Is there a way I can specify SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED for my SQL Connection? That would keep all my reads working (I don't mind about dirty reads for states/events) and they won't be blocked by anything trying to write.

Note that you will find I'm not purging logs in the config. I manually handle my own purging on a nightly job.

Environment

Home Assistant Core release with the issue: 0.108
Last working Home Assistant Core release (if known): 0.107
Operating environment (Home Assistant/Supervised/Docker/venv): Docker on Ubuntu 16.04.6 LTS
Integration causing this issue: Recorder
Link to integration documentation on our website: https://www.home-assistant.io/integrations/recorder/

Problem-relevant `configuration.yaml`

recorder:
    db_url: "mssql+pyodbc://UserName:Password@myserverip/homeassistant?charset=utf8;DRIVER={FreeTDS};Port=1433;"
  #purge_keep_days: 3650
  purge_interval: 0
  include:
    domains:
      - sensor
      - switch
      - binary_sensor
      - cover
      - light
  exclude:
    domains:
      - automation
      - device_tracker
    entities:
#      - switch.agouws_gouws_org_wake_on_lan
      - binary_sensor.lexi_heater_button
      - binary_sensor.lounge_lamp_button
      - binary_sensor.remote_ui
      - binary_sensor.ensuite_towel_rail_button
      - binary_sensor.ensuite_fan_button
      - binary_sensor.entrance_motion
      - binary_sensor.laundry_fan_button
      - binary_sensor.lexi_vent_button

Traceback/Error logs

Logger: homeassistant.components.recorder.util
Source: components/recorder/util.py:79
Integration: recorder (documentation, issues)
First occurred: April 19, 2020, 10:55:12 AM (4 occurrences)
Last logged: April 19, 2020, 10:55:20 AM

Error executing query: (pyodbc.ProgrammingError) ('42000', '[42000] [FreeTDS][SQL Server]Transaction (Process ID 58) was deadlocked on lock | communication buffer resources with another process and has been chosen as the deadlock victim. Rerun the transaction. (1205) (SQLExecDirectW)') [SQL: SELECT TOP 1 states.state_id AS states_state_id, states.domain AS states_domain, states.entity_id AS states_entity_id, states.state AS states_state, states.attributes AS states_attributes, states.event_id AS states_event_id, states.last_changed AS states_last_changed, states.last_updated AS states_last_updated, states.created AS states_created, states.context_id AS states_context_id, states.context_user_id AS states_context_user_id FROM states WHERE states.last_updated >= ? AND states.last_updated < ? AND states.entity_id IN (?) ORDER BY states.last_updated DESC] [parameters: (datetime.datetime(2020, 4, 17, 19, 38, 23, 877000), datetime.datetime(2020, 4, 17, 22, 54, 59, 897000, tzinfo=<UTC>), 'sensor.lexi_white_noise_humidity')] (Background on this error at: http://sqlalche.me/e/f405)
Error executing query: (pyodbc.ProgrammingError) ('42000', '[42000] [FreeTDS][SQL Server]Transaction (Process ID 55) was deadlocked on lock | communication buffer resources with another process and has been chosen as the deadlock victim. Rerun the transaction. (1205) (SQLExecDirectW)') [SQL: SELECT TOP 1 states.state_id AS states_state_id, states.domain AS states_domain, states.entity_id AS states_entity_id, states.state AS states_state, states.attributes AS states_attributes, states.event_id AS states_event_id, states.last_changed AS states_last_changed, states.last_updated AS states_last_updated, states.created AS states_created, states.context_id AS states_context_id, states.context_user_id AS states_context_user_id FROM states WHERE states.last_updated >= ? AND states.last_updated < ? AND states.entity_id IN (?) ORDER BY states.last_updated DESC] [parameters: (datetime.datetime(2020, 4, 17, 19, 38, 23, 877000), datetime.datetime(2020, 4, 17, 22, 54, 59, 897000, tzinfo=<UTC>), 'sensor.lexi_white_noise_temperature')] (Background on this error at: http://sqlalche.me/e/f405)
Error executing query: (pyodbc.ProgrammingError) ('42000', '[42000] [FreeTDS][SQL Server]Transaction (Process ID 59) was deadlocked on lock | communication buffer resources with another process and has been chosen as the deadlock victim. Rerun the transaction. (1205) (SQLExecDirectW)') [SQL: SELECT TOP 1 states.state_id AS states_state_id, states.domain AS states_domain, states.entity_id AS states_entity_id, states.state AS states_state, states.attributes AS states_attributes, states.event_id AS states_event_id, states.last_changed AS states_last_changed, states.last_updated AS states_last_updated, states.created AS states_created, states.context_id AS states_context_id, states.context_user_id AS states_context_user_id FROM states WHERE states.last_updated >= ? AND states.last_updated < ? AND states.entity_id IN (?) ORDER BY states.last_updated DESC] [parameters: (datetime.datetime(2020, 4, 17, 19, 38, 23, 877000), datetime.datetime(2020, 4, 17, 22, 54, 59, 894000, tzinfo=<UTC>), 'sensor.lexi_white_noise_humidity')] (Background on this error at: http://sqlalche.me/e/f405)
Error executing query: (pyodbc.ProgrammingError) ('42000', '[42000] [FreeTDS][SQL Server]Transaction (Process ID 56) was deadlocked on lock | communication buffer resources with another process and has been chosen as the deadlock victim. Rerun the transaction. (1205) (SQLExecDirectW)') [SQL: SELECT TOP 1 states.state_id AS states_state_id, states.domain AS states_domain, states.entity_id AS states_entity_id, states.state AS states_state, states.attributes AS states_attributes, states.event_id AS states_event_id, states.last_changed AS states_last_changed, states.last_updated AS states_last_updated, states.created AS states_created, states.context_id AS states_context_id, states.context_user_id AS states_context_user_id FROM states WHERE states.last_updated >= ? AND states.last_updated < ? AND states.entity_id IN (?) ORDER BY states.last_updated DESC] [parameters: (datetime.datetime(2020, 4, 17, 19, 38, 23, 877000), datetime.datetime(2020, 4, 17, 22, 54, 59, 894000, tzinfo=<UTC>), 'sensor.lexi_white_noise_temperature')] (Background on this error at: http://sqlalche.me/e/f405)

Log Details (ERROR)
Logger: aiohttp.server
Source: components/recorder/util.py:34
First occurred: April 19, 2020, 10:55:29 AM (4 occurrences)
Last logged: April 19, 2020, 10:55:29 AM

Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 755, in _commit_impl
    self.engine.dialect.do_commit(self.connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 541, in do_commit
    dbapi_connection.commit()
pyodbc.ProgrammingError: ('25000', '[25000] [FreeTDS][SQL Server]The COMMIT TRANSACTION request has no corresponding BEGIN TRANSACTION. (3902) (SQLEndTran)')

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/recorder/util.py", line 30, in session_scope
    session.commit()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/session.py", line 1036, in commit
    self.transaction.commit()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/session.py", line 507, in commit
    t[1].commit()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1736, in commit
    self._do_commit()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1767, in _do_commit
    self.connection._commit_impl()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 757, in _commit_impl
    self._handle_dbapi_exception(e, None, None, None, None)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1482, in _handle_dbapi_exception
    sqlalchemy_exception, with_traceback=exc_info[2], from_=e
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/util/compat.py", line 178, in raise_
    raise exception
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 755, in _commit_impl
    self.engine.dialect.do_commit(self.connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 541, in do_commit
    dbapi_connection.commit()
sqlalchemy.exc.ProgrammingError: (pyodbc.ProgrammingError) ('25000', '[25000] [FreeTDS][SQL Server]The COMMIT TRANSACTION request has no corresponding BEGIN TRANSACTION. (3902) (SQLEndTran)')
(Background on this error at: http://sqlalche.me/e/f405)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 733, in _rollback_impl
    self.engine.dialect.do_rollback(self.connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 538, in do_rollback
    dbapi_connection.rollback()
pyodbc.ProgrammingError: ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 733, in _rollback_impl
    self.engine.dialect.do_rollback(self.connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 538, in do_rollback
    dbapi_connection.rollback()
pyodbc.ProgrammingError: ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_protocol.py", line 418, in start
    resp = await task
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_app.py", line 458, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_middlewares.py", line 119, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/real_ip.py", line 39, in real_ip_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 72, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 127, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 123, in handle
    result = await result
  File "/usr/src/homeassistant/homeassistant/components/history/__init__.py", line 348, in get
    significant_changes_only,
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/history/__init__.py", line 95, in get_significant_states
    hass, states, start_time, entity_ids, filters, include_start_time_state
  File "/usr/src/homeassistant/homeassistant/components/history/__init__.py", line 244, in states_to_json
    for state in get_states(hass, start_time, entity_ids, filters=filters):
  File "/usr/src/homeassistant/homeassistant/components/history/__init__.py", line 218, in get_states
    for state in execute(query)
  File "/usr/local/lib/python3.7/contextlib.py", line 119, in __exit__
    next(self.gen)
  File "/usr/src/homeassistant/homeassistant/components/recorder/util.py", line 34, in session_scope
    session.rollback()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/session.py", line 1000, in rollback
    self.transaction.rollback()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/session.py", line 573, in rollback
    util.raise_(rollback_err[1], with_traceback=rollback_err[2])
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/util/compat.py", line 178, in raise_
    raise exception
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/session.py", line 533, in rollback
    t[1].rollback()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1725, in rollback
    self._do_rollback()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1763, in _do_rollback
    self.connection._rollback_impl()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 735, in _rollback_impl
    self._handle_dbapi_exception(e, None, None, None, None)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
    self._autorollback()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/util/langhelpers.py", line 81, in __exit__
    compat.raise_(value, with_traceback=traceback)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/util/compat.py", line 178, in raise_
    raise exception
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
    self._autorollback()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 861, in _autorollback
    self._root._rollback_impl()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 735, in _rollback_impl
    self._handle_dbapi_exception(e, None, None, None, None)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1389, in _handle_dbapi_exception
    from_=e,
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/util/compat.py", line 178, in raise_
    raise exception
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 733, in _rollback_impl
    self.engine.dialect.do_rollback(self.connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 538, in do_rollback
    dbapi_connection.rollback()
sqlalchemy.exc.ProgrammingError: (pyodbc.ProgrammingError) ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')
(Background on this error at: http://sqlalche.me/e/f405)

Log Details (ERROR)
Logger: homeassistant.components.recorder.util
Source: components/recorder/util.py:32
Integration: recorder (documentation, issues)
First occurred: April 19, 2020, 10:55:29 AM (4 occurrences)
Last logged: April 19, 2020, 10:55:29 AM

Error executing query: (pyodbc.ProgrammingError) ('25000', '[25000] [FreeTDS][SQL Server]The COMMIT TRANSACTION request has no corresponding BEGIN TRANSACTION. (3902) (SQLEndTran)') (Background on this error at: http://sqlalche.me/e/f405)

Additional information

codylv7 commented 4 years ago

I am having the same issue, run HA/SQL in Docker containers, just started with 0.108.x

CAB426 commented 4 years ago

I am seeing this issue as well. Run SQL on a separate VM. Also saw this start with 0.108.x.

CAB426 commented 4 years ago

I am having the same issue, run HA/SQL in Docker containers, just started with 0.108.x

I added autocommit=True; to my recorder pyodbc connection string and the errors went away. I am fine with no client side transaction management and allowing transactions to commit automatically but you may not be.

When autocommit is set to True, the database executes a commit automatically after every SQL statement, so transaction management by the client is not possible. Note, those automatic commits are executed by the database itself, not pyodbc, i.e. the database essentially runs every SQL statement within its own transaction. pyodbc Documentation

henripalmroth commented 4 years ago

Got this too. That autocommit sounds good. I need to try that.

On the investigation I also noticed that Google Cast integration have started to update state 7 times per second when watching something from Android TV. That resulted 26000 additional records per hour which might have given some issues for the db as well. 😅 It was updating media location attribute all the time. Now I have excluded that from recorder.

Normally I'm getting in average about 4000 records per hour.

brettjenkins commented 4 years ago

I added autocommit true a few weeks ago and it's been rock solid since, state history loads quickly etc. I'm not too bothered about wrapping stuff up in transactions, I'd rather HASS stays fast.

stale[bot] commented 4 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

home-assistant / core