Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ensure all states have been migrated to use timestamps #134007

Merged
merged 7 commits into from
Dec 26, 2024

Conversation

bdraco
Copy link
Member

@bdraco bdraco commented Dec 25, 2024

Proposed change

If there are any un-migrated states rows, the new optimized queries for finding unused attributes_ids and metadata_ids will not be able to see them because it relies on scanning the index for last_updated_ts. Additionally, these rows could never have been purged because the purge also relies on this column/index. While its unclear how these rows could even exist since the original query was unbounded, ensure they are migrated since the issue report shows that it does happen on a production system in #134002.

fixes #134002

Type of change

  • Dependency upgrade
  • Bugfix (non-breaking change which fixes an issue)
  • New integration (thank you!)
  • New feature (which adds functionality to an existing integration)
  • Deprecation (breaking change to happen in the future)
  • Breaking change (fix/feature causing existing functionality to break)
  • Code quality improvements to existing code or addition of tests

Additional information

  • This PR fixes or closes issue: fixes #
  • This PR is related to issue:
  • Link to documentation pull request:

Checklist

  • The code change is tested and works locally.
  • Local tests pass. Your PR cannot be merged unless tests pass
  • There is no commented out code in this PR.
  • I have followed the development checklist
  • I have followed the perfect PR recommendations
  • The code has been formatted using Ruff (ruff format homeassistant tests)
  • Tests have been added to verify that the new code works.

If user exposed functionality or configuration variables are added/changed:

If the code communicates with devices, web services, or third-party tools:

  • The manifest file has all fields filled out correctly.
    Updated and included derived files by running: python3 -m script.hassfest.
  • New or updated dependencies have been added to requirements_all.txt.
    Updated by running python3 -m script.gen_requirements_all.
  • For the updated dependencies - a link to the changelog, or at minimum a diff between library versions is added to the PR description.

To help with the load of incoming pull requests:

@home-assistant
Copy link

Hey there @home-assistant/core, mind taking a look at this pull request as it has been labeled with an integration (recorder) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of recorder can trigger bot actions by commenting:

  • @home-assistant close Closes the pull request.
  • @home-assistant rename Awesome new title Renames the pull request.
  • @home-assistant reopen Reopen the pull request.
  • @home-assistant unassign recorder Removes the current integration label and assignees on the pull request, add the integration domain after the command.
  • @home-assistant add-label needs-more-information Add a label (needs-more-information, problem in dependency, problem in custom component) to the pull request.
  • @home-assistant remove-label needs-more-information Remove a label (needs-more-information, problem in dependency, problem in custom component) on the pull request.

@bdraco
Copy link
Member Author

bdraco commented Dec 25, 2024

It took less than a second to cleanup the unmigrated rows with the test database provided

2024-12-25 10:01:09.532 DEBUG (MainThread) [homeassistant.loader] Importing platforms for spotify executor=['config_flow'] loop=[] took 0.01s
2024-12-25 10:01:09.532 WARNING (Recorder) [homeassistant.components.recorder.migration] The database is about to upgrade from schema version 47 to 48
2024-12-25 10:01:09.532 WARNING (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 48
2024-12-25 10:01:09.532 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:01:09.532 INFO (Recorder) [sqlalchemy.engine.Engine] UPDATE events set time_fired_ts=strftime("%s",time_fired) + cast(substr(time_fired,-7) AS FLOAT) WHERE time_fired_ts is NULL;
2024-12-25 10:01:09.532 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00004s] ()
2024-12-25 10:01:09.579 INFO (Recorder) [sqlalchemy.engine.Engine] UPDATE states set last_updated_ts=strftime("%s",last_updated) + cast(substr(last_updated,-7) AS FLOAT), last_changed_ts=strftime("%s",last_changed) + cast(substr(last_changed,-7) AS FLOAT)  WHERE last_updated_ts is NULL;
2024-12-25 10:01:09.579 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00006s] ()
2024-12-25 10:01:09.689 INFO (Recorder) [sqlalchemy.engine.Engine] COMMIT
2024-12-25 10:01:09.707 DEBUG (MainThread) [homeassistant.loader] Importing platforms for enphase_envoy executor=['config_flow'] loop=[] took 0.17s
2024-12-25 10:01:09.734 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:01:09.735 INFO (Recorder) [sqlalchemy.engine.Engine] INSERT INTO schema_changes (schema_version, changed) VALUES (?, ?) RETURNING change_id
2024-12-25 10:01:09.735 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00009s] (48, '2024-12-25 20:01:09.735211')
2024-12-25 10:01:09.735 INFO (Recorder) [sqlalchemy.engine.Engine] COMMIT
2024-12-25 10:01:09.735 WARNING (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 48 done
2024-12-25 10:01:09.736 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:01:09.736 INFO (Recorder) [sqlalchemy.engine.Engine] SELECT recorder_runs.run_id AS recorder_runs_run_id, recorder_runs.start AS recorder_runs_start, recorder_runs."end" AS recorder_runs_end, recorder_runs.closed_incorrect AS recorder_runs_closed_incorrect, recorder_runs.created AS recorder_runs_created 
FROM recorder_runs 
WHERE recorder_runs."end" IS NULL
2024-12-25 10:01:09.736 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00004s] ()
2024-12-25 10:01:09.737 WARNING (Recorder) [homeassistant.components.recorder.util] Ended unfinished session (id=2326 from 2024-12-24 16:22:31.699947)

@bdraco
Copy link
Member Author

bdraco commented Dec 25, 2024

same for MariaDB

2024-12-25 10:02:50.930 WARNING (Recorder) [homeassistant.components.recorder.migration] The database is about to upgrade from schema version 47 to 48
2024-12-25 10:02:50.930 WARNING (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 48
2024-12-25 10:02:50.930 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:02:50.930 INFO (Recorder) [sqlalchemy.engine.Engine] UPDATE events set time_fired_ts=IF(time_fired is NULL or UNIX_TIMESTAMP(time_fired) is NULL,0,UNIX_TIMESTAMP(time_fired)) where time_fired_ts is NULL LIMIT 100000;
2024-12-25 10:02:50.930 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00005s] ()
2024-12-25 10:02:50.932 INFO (Recorder) [sqlalchemy.engine.Engine] COMMIT
2024-12-25 10:02:50.934 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:02:50.934 INFO (Recorder) [sqlalchemy.engine.Engine] UPDATE states set last_updated_ts=IF(last_updated is NULL or UNIX_TIMESTAMP(last_updated) is NULL,0,UNIX_TIMESTAMP(last_updated) ), last_changed_ts=UNIX_TIMESTAMP(last_changed) where last_updated_ts is NULL LIMIT 100000;
2024-12-25 10:02:50.934 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00004s] ()
2024-12-25 10:02:50.937 INFO (Recorder) [sqlalchemy.engine.Engine] COMMIT
2024-12-25 10:02:50.938 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:02:50.938 INFO (Recorder) [sqlalchemy.engine.Engine] INSERT INTO schema_changes (schema_version, changed) VALUES (%s, %s) RETURNING schema_changes.change_id
2024-12-25 10:02:50.938 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00008s] (48, datetime.datetime(2024, 12, 25, 20, 2, 50, 938954, tzinfo=datetime.timezone.utc))
2024-12-25 10:02:50.940 INFO (Recorder) [sqlalchemy.engine.Engine] COMMIT
2024-12-25 10:02:50.942 WARNING (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 48 done
2024-12-25 10:02:50.943 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:02:50.943 INFO (Recorder) [sqlalchemy.engine.Engine] SELECT recorder_runs.run_id AS recorder_runs_run_id, recorder_runs.start AS recorder_runs_start, recorder_runs.end AS recorder_runs_end, recorder_runs.closed_incorrect AS recorder_runs_closed_incorrect, recorder_runs.created AS recorder_runs_created 

@bdraco
Copy link
Member Author

bdraco commented Dec 25, 2024

same with PostgreSQL

2024-12-25 10:03:57.106 WARNING (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 48
2024-12-25 10:03:57.107 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:03:57.108 INFO (Recorder) [sqlalchemy.engine.Engine] UPDATE events SET time_fired_ts= (case when time_fired is NULL then 0 else EXTRACT(EPOCH FROM time_fired::timestamptz) end) WHERE event_id IN ( SELECT event_id FROM events where time_fired_ts is NULL LIMIT 100000  );
2024-12-25 10:03:57.108 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00008s] {}
2024-12-25 10:03:57.215 INFO (Recorder) [sqlalchemy.engine.Engine] COMMIT
2024-12-25 10:03:57.216 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:03:57.216 INFO (Recorder) [sqlalchemy.engine.Engine] UPDATE states set last_updated_ts=(case when last_updated is NULL then 0 else EXTRACT(EPOCH FROM last_updated::timestamptz) end), last_changed_ts=EXTRACT(EPOCH FROM last_changed::timestamptz) where state_id IN ( SELECT state_id FROM states where last_updated_ts is NULL LIMIT 100000  );
2024-12-25 10:03:57.216 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00003s] {}
2024-12-25 10:03:57.225 INFO (Recorder) [sqlalchemy.engine.Engine] COMMIT
2024-12-25 10:03:57.226 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)
2024-12-25 10:03:57.227 INFO (Recorder) [sqlalchemy.engine.Engine] INSERT INTO schema_changes (schema_version, changed) VALUES (%(schema_version)s, %(changed)s) RETURNING schema_changes.change_id
2024-12-25 10:03:57.227 INFO (Recorder) [sqlalchemy.engine.Engine] [generated in 0.00005s] {'schema_version': 48, 'changed': datetime.datetime(2024, 12, 25, 20, 3, 57, 227002, tzinfo=datetime.timezone.utc)}
2024-12-25 10:03:57.230 INFO (Recorder) [sqlalchemy.engine.Engine] COMMIT
2024-12-25 10:03:57.232 WARNING (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 48 done
2024-12-25 10:03:57.232 INFO (Recorder) [sqlalchemy.engine.Engine] BEGIN (implicit)

@bdraco bdraco marked this pull request as ready for review December 25, 2024 20:23
@bdraco bdraco requested a review from a team as a code owner December 25, 2024 20:23
@bdraco bdraco marked this pull request as draft December 25, 2024 20:25
@bdraco bdraco marked this pull request as ready for review December 25, 2024 23:04
@bdraco
Copy link
Member Author

bdraco commented Dec 26, 2024

Tested more widely on more production systems. All good

@bdraco bdraco merged commit 942fbde into dev Dec 26, 2024
64 checks passed
@bdraco bdraco deleted the ensure_all_states_migrated branch December 26, 2024 17:48
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Recorder logs error since 2025.1.0b0
2 participants