search

basnijholt / adaptive-lighting

Adaptive Lighting custom component for Home Assistant
https://basnijholt.github.io/adaptive-lighting/
Apache License 2.0
1.77k stars 132 forks source link

Fix autoreset_control_seconds_test on dev HA core #733

Open basnijholt opened 1 year ago

basnijholt commented 1 year ago

Turns out that there is a slowdown in the dev version and somehow the loop takes 0.1 seconds in dev.

basnijholt commented 1 year ago

This line resets the timer: 2023-08-10T00:48:14.1417964Z 2023-08-10 00:47:51.959 DEBUG MainThread custom_components.adaptive_lighting.switch:switch.py:2255 Detected an 'light.turn_on('['light.light_1']')' event with context.id='01H7EEM1MN97HD42ZSBFZ2N5GS' and then 106 ms later 2023-08-10T00:48:14.1451353Z 2023-08-10 00:47:52.065 DEBUG MainThread custom_components.adaptive_lighting.switch:switch.py:2121 Auto resetting 'manual_control' status of 'light.light_1' because it was not manually controlled for 0.1 seconds. this happens.

Somehow on the dev branch there is a slowdown. Locally these steps take 16 ms. ¯_(ツ)_/¯

From failing CI:

2023-08-10T00:48:14.1417964Z 2023-08-10 00:47:51.959 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2255 Detected an 'light.turn_on('['light.light_1']')' event with context.id='01H7EEM1MN97HD42ZSBFZ2N5GS'
2023-08-10T00:48:14.1418912Z 2023-08-10 00:47:51.961 DEBUG    MainThread homeassistant.components.template.light:light.py:352 Optimistically setting brightness to 60
2023-08-10T00:48:14.1419769Z 2023-08-10 00:47:51.963 INFO     MainThread homeassistant.helpers.script.light_1:script.py:1774 light_1: Running template script
2023-08-10T00:48:14.1422655Z 2023-08-10 00:47:51.964 DEBUG    MainThread homeassistant.core:core.py:1048 Bus:Handling <Event state_changed[L]: entity_id=light.light_1, old_state=<state light.light_1=on; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.HS: 'hs'>], color_mode=color_temp, brightness=40, color_temp_kelvin=4830, color_temp=207, hs_color=(26.857, 21.602), rgb_color=(255, 224, 199), xy_color=(0.379, 0.352), friendly_name=light_1, supported_features=0 @ 2023-08-09T17:47:51.363373-07:00>, new_state=<state light.light_1=on; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.HS: 'hs'>], color_mode=color_temp, brightness=60, color_temp_kelvin=4830, color_temp=207, hs_color=(26.857, 21.602), rgb_color=(255, 224, 199), xy_color=(0.379, 0.352), friendly_name=light_1, supported_features=0 @ 2023-08-09T17:47:51.363373-07:00>>
2023-08-10T00:48:14.1426155Z 2023-08-10 00:47:51.966 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2292 Detected a 'light.light_1' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.HS: 'hs'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 60, 'color_temp_kelvin': 4830, 'color_temp': 207, 'hs_color': (26.857, 21.602), 'rgb_color': (255, 224, 199), 'xy_color': (0.379, 0.352), 'friendly_name': 'light_1', 'supported_features': <LightEntityFeature: 0>}' with context.id='01H7EEM1MN97HD42ZSBFZ2N5GS'
2023-08-10T00:48:14.1427930Z 2023-08-10 00:47:51.966 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1344 default: '_update_attrs_and_maybe_adapt_lights' called with context.id='01H7EEM14F:al:MRSW:0tst:01' lights: 'None', transition: '0', force: 'False'
2023-08-10T00:48:14.1431223Z 2023-08-10 00:47:51.967 DEBUG    MainThread homeassistant.core:core.py:1048 Bus:Handling <Event state_changed[L]: entity_id=switch.adaptive_lighting_default, old_state=<state switch.adaptive_lighting_default=on; configuration=, manual_control=['light.light_1'], brightness_pct=100, color_temp_kelvin=4825, color_temp_mired=207, rgb_color=(255, 224.4686359650829, 199.73370548952306), xy_color=(0.379, 0.352), hs_color=(26.786, 21.961), sun_position=0.7746423788917824, force_rgb_color=False, autoreset_time_remaining=light.light_1=0.09527200000000001, icon=mdi:theme-light-dark, friendly_name=Adaptive Lighting: default @ 2023-08-09T17:47:51.409934-07:00>, new_state=<state switch.adaptive_lighting_default=on; configuration=, manual_control=['light.light_1'], brightness_pct=100, color_temp_kelvin=4825, color_temp_mired=207, rgb_color=(255, 224.4686359650829, 199.73370548952306), xy_color=(0.379, 0.352), hs_color=(26.786, 21.961), sun_position=0.7746398998284203, force_rgb_color=False, autoreset_time_remaining=light.light_1=0.095252, icon=mdi:theme-light-dark, friendly_name=Adaptive Lighting: default @ 2023-08-09T17:47:51.409934-07:00>>
2023-08-10T00:48:14.1433574Z 2023-08-10 00:47:51.969 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1402 default: filtered_lights: '['light.light_1', 'light.light_2']'
2023-08-10T00:48:14.1434652Z 2023-08-10 00:47:51.969 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1423 default: 'light.light_1' is being manually controlled, stop adapting, context.id=01H7EEM14F:al:MRSW:0tst:01.
2023-08-10T00:48:14.1435697Z 2023-08-10 00:47:51.969 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1711 is_proactively_adapting_context='False', context_id='01H7EEM14F:al:MRSW:0tst:01'
2023-08-10T00:48:14.1438070Z 2023-08-10 00:47:51.970 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2471 default: State attributes of 'light.light_2' did not change ({'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.HS: 'hs'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 255, 'color_temp_kelvin': 4830, 'color_temp': 207, 'hs_color': (26.857, 21.602), 'rgb_color': (255, 224, 199), 'xy_color': (0.379, 0.352), 'friendly_name': 'light_2', 'supported_features': <LightEntityFeature: 0>}) wrt 'last_service_data' ({'entity_id': 'light.light_2', 'brightness': 255, 'color_temp_kelvin': 4825}) (context.id=01H7EEM14F:al:MRSW:0tst:01)
2023-08-10T00:48:14.1439962Z 2023-08-10 00:47:51.970 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1449 default: Calling _adapt_light from _update_attrs_and_maybe_adapt_lights: 'light.light_2' with transition 0 and context.id=01H7EEM14F:al:MRSW:0tst:01
2023-08-10T00:48:14.1440989Z 2023-08-10 00:47:51.972 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1189 default: Setting color_temp of light light.light_2
2023-08-10T00:48:14.1442161Z 2023-08-10 00:47:51.972 DEBUG    MainThread custom_components.adaptive_lighting.adaptation_utils:adaptation_utils.py:200 Preparing adaptation data for light.light_2 with service data {'entity_id': 'light.light_2', 'brightness': 255, 'color_temp_kelvin': 4825}
2023-08-10T00:48:14.1443611Z 2023-08-10 00:47:51.972 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1314 default: execute_cancellable_adaptation_calls with data: AdaptationData(entity_id=light.light_2, context_id=01H7EEM14F:al:MRSW:0tst:01, sleep_time=0.0, force=False, max_length=1, which=both, initial_sleep=False)
2023-08-10T00:48:14.1445158Z 2023-08-10 00:47:51.973 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1287 default: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.light_2', 'brightness': 255, 'color_temp_kelvin': 4825} with context.id='01H7EEM14F:al:MRSW:0tst:01'
2023-08-10T00:48:14.1446386Z 2023-08-10 00:47:51.973 DEBUG    MainThread homeassistant.core:core.py:1048 Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.light_2, brightness=255, color_temp_kelvin=4825>
2023-08-10T00:48:14.1447469Z 2023-08-10 00:47:51.975 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2255 Detected an 'light.turn_on('['light.light_2']')' event with context.id='01H7EEM14F:al:MRSW:0tst:01'
2023-08-10T00:48:14.1448540Z 2023-08-10 00:47:51.976 DEBUG    MainThread homeassistant.components.template.light:light.py:352 Optimistically setting brightness to 255
2023-08-10T00:48:14.1449478Z 2023-08-10 00:47:51.977 DEBUG    MainThread homeassistant.components.template.light:light.py:359 Optimistically setting color temperature to 207
2023-08-10T00:48:14.1450336Z 2023-08-10 00:47:52.063 INFO     MainThread homeassistant.helpers.script.light_2:script.py:1774 light_2: Running template script
2023-08-10T00:48:14.1451353Z 2023-08-10 00:47:52.065 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2121 Auto resetting 'manual_control' status of 'light.light_1' because it was not manually controlled for 0.1 seconds.

from working version locally:

2023-08-10 00:54:34.288 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2255 Detected an 'light.turn_on('['light.light_1']')' event with context.id='01H7EF0AHFHSPD6S1YAEWT5YTP'
2023-08-10 00:54:34.289 DEBUG    MainThread homeassistant.components.template.light:light.py:352 Optimistically setting brightness to 60
2023-08-10 00:54:34.291 INFO     MainThread homeassistant.helpers.script.light_1:script.py:1774 light_1: Running template script
2023-08-10 00:54:34.292 DEBUG    MainThread homeassistant.core:core.py:1049 Bus:Handling <Event state_changed[L]: entity_id=light.light_1, old_state=<state light.light_1=on; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.HS: 'hs'>], color_mode=color_temp, brightness=40, color_temp_kelvin=4807, color_temp=208, hs_color=(26.842, 21.929), rgb_color=(255, 224, 199), xy_color=(0.379, 0.352), friendly_name=light_1, supported_features=0 @ 2023-08-09T17:54:33.754136-07:00>, new_state=<state light.light_1=on; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.HS: 'hs'>], color_mode=color_temp, brightness=60, color_temp_kelvin=4807, color_temp=208, hs_color=(26.842, 21.929), rgb_color=(255, 224, 199), xy_color=(0.379, 0.352), friendly_name=light_1, supported_features=0 @ 2023-08-09T17:54:33.754136-07:00>>
2023-08-10 00:54:34.294 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2292 Detected a 'light.light_1' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.HS: 'hs'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 60, 'color_temp_kelvin': 4807, 'color_temp': 208, 'hs_color': (26.842, 21.929), 'rgb_color': (255, 224, 199), 'xy_color': (0.379, 0.352), 'friendly_name': 'light_1', 'supported_features': <LightEntityFeature: 0>}' with context.id='01H7EF0AHFHSPD6S1YAEWT5YTP'
2023-08-10 00:54:34.294 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1344 default: '_update_attrs_and_maybe_adapt_lights' called with context.id='01H7EF0A2C:al:MRSW:0tst:01' lights: 'None', transition: '0', force: 'False'
2023-08-10 00:54:34.295 DEBUG    MainThread homeassistant.core:core.py:1049 Bus:Handling <Event state_changed[L]: entity_id=switch.adaptive_lighting_default, old_state=<state switch.adaptive_lighting_default=on; configuration=, manual_control=['light.light_1'], brightness_pct=100, color_temp_kelvin=4785, color_temp_mired=208, rgb_color=(255, 223.64057039142295, 198.2775267047262), xy_color=(0.38, 0.352), hs_color=(26.316, 22.353), sun_position=0.7611837228734024, force_rgb_color=False, autoreset_time_remaining=light.light_1=0.097359, icon=mdi:theme-light-dark, friendly_name=Adaptive Lighting: default @ 2023-08-09T17:54:33.792611-07:00>, new_state=<state switch.adaptive_lighting_default=on; configuration=, manual_control=['light.light_1'], brightness_pct=100, color_temp_kelvin=4785, color_temp_mired=208, rgb_color=(255, 223.64057039142295, 198.2775267047262), xy_color=(0.38, 0.352), hs_color=(26.316, 22.353), sun_position=0.7611813085124169, force_rgb_color=False, autoreset_time_remaining=light.light_1=0.09625900000000001, icon=mdi:theme-light-dark, friendly_name=Adaptive Lighting: default @ 2023-08-09T17:54:33.792611-07:00>>
2023-08-10 00:54:34.296 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1402 default: filtered_lights: '['light.light_1', 'light.light_2']'
2023-08-10 00:54:34.296 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1423 default: 'light.light_1' is being manually controlled, stop adapting, context.id=01H7EF0A2C:al:MRSW:0tst:01.
2023-08-10 00:54:34.296 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1711 is_proactively_adapting_context='False', context_id='01H7EF0A2C:al:MRSW:0tst:01'
2023-08-10 00:54:34.297 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2471 default: State attributes of 'light.light_2' did not change ({'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.HS: 'hs'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 255, 'color_temp_kelvin': 4807, 'color_temp': 208, 'hs_color': (26.842, 21.929), 'rgb_color': (255, 224, 199), 'xy_color': (0.379, 0.352), 'friendly_name': 'light_2', 'supported_features': <LightEntityFeature: 0>}) wrt 'last_service_data' ({'entity_id': 'light.light_2', 'brightness': 255, 'color_temp_kelvin': 4785}) (context.id=01H7EF0A2C:al:MRSW:0tst:01)
2023-08-10 00:54:34.297 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1449 default: Calling _adapt_light from _update_attrs_and_maybe_adapt_lights: 'light.light_2' with transition 0 and context.id=01H7EF0A2C:al:MRSW:0tst:01
2023-08-10 00:54:34.299 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1189 default: Setting color_temp of light light.light_2
2023-08-10 00:54:34.299 DEBUG    MainThread custom_components.adaptive_lighting.adaptation_utils:adaptation_utils.py:200 Preparing adaptation data for light.light_2 with service data {'entity_id': 'light.light_2', 'brightness': 255, 'color_temp_kelvin': 4785}
2023-08-10 00:54:34.299 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1314 default: execute_cancellable_adaptation_calls with data: AdaptationData(entity_id=light.light_2, context_id=01H7EF0A2C:al:MRSW:0tst:01, sleep_time=0.0, force=False, max_length=1, which=both, initial_sleep=False)
2023-08-10 00:54:34.299 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:1287 default: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.light_2', 'brightness': 255, 'color_temp_kelvin': 4785} with context.id='01H7EF0A2C:al:MRSW:0tst:01'
2023-08-10 00:54:34.300 DEBUG    MainThread homeassistant.core:core.py:1049 Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.light_2, brightness=255, color_temp_kelvin=4785>
2023-08-10 00:54:34.301 DEBUG    MainThread custom_components.adaptive_lighting.switch:switch.py:2255 Detected an 'light.turn_on('['light.light_2']')' event with context.id='01H7EF0A2C:al:MRSW:0tst:01'
2023-08-10 00:54:34.302 DEBUG    MainThread homeassistant.components.template.light:light.py:352 Optimistically setting brightness to 255
2023-08-10 00:54:34.302 DEBUG    MainThread homeassistant.components.template.light:light.py:359 Optimistically setting color temperature to 208
2023-08-10 00:54:34.303 INFO     MainThread homeassistant.helpers.script.light_2:script.py:1774 light_2: Running template script
basnijholt commented 1 year ago

@bdraco, sorry to tag you here on a random repo, however, but I thought you might want to know this since you have been working on performance optimizations for a long time now.

I think in the latest dev branch there is some sort of slowdown in comparison with older versions.

In Adaptive Lighting are keeping an async timer that counts down from a delay (0.1s in the test) and each time light.turn_on is called, the timer is reset and starts counting down again.

In this loop https://github.com/basnijholt/adaptive-lighting/blob/5b7ee446295a5ff54dcfc54ba7e34cce0d271237/tests/test_switch.py#L798-L803

we call light.turn_on (resetting the timer) and wait 0.05s. Doing this a couple of times should not exhaust the timer (0.1s).

This works fine in any released version of Home Assistant since 2022.11, however, in the latest dev branch, one iteration of the loop suddenly can take more than 0.1s.

bdraco commented 1 year ago

I can't replicate this behavior. Can you bisect to a specific commit causing it?

basnijholt commented 1 year ago

Unfortunately, I can’t reproduce it locally either (on my Mac). Just happens in CI.

I’ll try to bisect via CI if I can make the failure happen reliably.

basnijholt commented 1 year ago

edit: for some reason, the exact tagged commit works (2023.7.3) but the commits before and after do not.

So still checking what's going on.

basnijholt commented 1 year ago

@bdraco, I ran ≈1000 CI jobs (🤯) trying to pinpoint exactly where the test starts failing.

My hypothesis is now that it happened on 3a06659120aa629e0db290ec9e83e2ad129baaf3 (https://github.com/home-assistant/core/pull/96729).

To test this I ran 5 jobs with that commit and 5 jobs with the parent commit c76fac0633749e8f463f9b6c22a4d47bba5ba1e7.

In that job the former commit fails consistently and the later always passes.

bdraco commented 1 year ago

That would make sense if you are missing some await hass.async_block_till_done()s in your tests

basnijholt commented 1 year ago

This turned into a complete mystery to me.

I am calling hass.async_block_till_done() after every step.

Some how the problem disappears when I add logging statements at some places. I do see the following in the logs:

2023-08-10T21:14:55.5875817Z 2023-08-10 21:14:34.902 WARNING MainThread asyncio:base_events.py:1917 Executing <Task pending name='Task-2402' coro=<async_setup.<locals>.async_handle_light_on_service() running at /home/runner/work/adaptive-lighting/adaptive-lighting/core/homeassistant/components/light/__init__.py:580> wait_for=<Future pending cb=[shield.<locals>._outer_done_callback() at /opt/hostedtoolcache/Python/3.11.4/x64/lib/python3.11/asyncio/tasks.py:898, Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.4/x64/lib/python3.11/asyncio/base_events.py:427> cb=[set.remove(), Task.task_wakeup()] created at /home/runner/work/adaptive-lighting/adaptive-lighting/core/homeassistant/core.py:522> took 0.105 seconds

which is the light.turn_on processing code that seems to take 105 ms.

I will just remove this part of the test because I am also not able to repro locally.

basnijholt commented 1 year ago

So these two messages are in the logs (which take 50-100ms in failure cases):

2023-08-10T23:02:02.4486952Z 2023-08-10 23:01:41.959 DEBUG    MainThread homeassistant.components.template.light:light.py:359 Optimistically setting color temperature to 188
2023-08-10T23:02:02.4487761Z 2023-08-10 23:01:42.050 INFO     MainThread homeassistant.helpers.script.light_2:script.py:1774 light_2: Running template script

Which means that in core/homeassistant/components/template/light.py these lines are responsible:

https://github.com/home-assistant/core/blob/b653d7f68350ec04eef7f9987714c3b1e4d4addd/homeassistant/components/template/light.py#L419C6-L422

th3w1zard1 commented 9 months ago

I feel like I remember this happening back in April. Probably a different scenario, but I could have sworn it was the exact variable name autoreset_control_seconds that I was having issues with in seemingly arbitrary scenarios. Any update, here?