This morning (07:02) the triggers which run on minute base experient some issues and I got log entries such as this:
[2023-10-11 07:02:17,915] [ HABApp.Worker] WARNING | 9/10 threads have been in use and execution of weatherRule.handle_event_trigger took too long: 5.93s
[2023-10-11 07:02:17,923] [ HABApp.Worker] WARNING | 9/10 threads have been in use and execution of weatherRule.handle_event_trigger took too long: 115.16s
[2023-10-11 07:02:17,972] [ HABApp.Worker] WARNING | ncalls tottime percall cumtime percall filename:lineno(function)
[2023-10-11 07:02:17,985] [ HABApp.Worker] WARNING | 1 0.000 0.000 5.927 5.927 /habapp/config/lib/personal/migration_helper.py:129(handle_event_trigger)
[2023-10-11 07:02:17,987] [ HABApp.Worker] WARNING | 1 0.000 0.000 5.927 5.927 /habapp/config/rules/weather.py:95(execute)
[2023-10-11 07:02:17,988] [ HABApp.Worker] WARNING | 10 0.002 0.000 5.851 0.585 /habapp/config/lib/requests/sessions.py:502(request)
[2023-10-11 07:02:17,988] [ HABApp.Worker] WARNING | 9 0.000 0.000 5.528 0.614 /habapp/config/lib/influxdb/client.py:437(query)
[2023-10-11 07:02:17,989] [ HABApp.Worker] WARNING | 9 0.001 0.000 5.526 0.614 /habapp/config/lib/influxdb/client.py:272(request)
[2023-10-11 07:02:17,990] [ HABApp.Worker] WARNING | 1 0.000 0.000 5.475 5.475 /habapp/config/rules/weather.py:47(rain_cumulation)
[2023-10-11 07:02:17,991] [ HABApp.Worker] WARNING | 1 0.000 0.000 5.475 5.475 /habapp/config/rules/weather.py:67(<listcomp>)
[2023-10-11 07:02:17,991] [ HABApp.Worker] WARNING | 7 0.001 0.000 5.474 0.782 /habapp/config/lib/personal/persistent_data.py:50(get_delta_since)
[2023-10-11 07:02:17,991] [ HABApp.Worker] WARNING | 10 0.002 0.000 5.407 0.541 /habapp/config/lib/requests/sessions.py:673(send)
[2023-10-11 07:02:17,992] [ HABApp.Worker] WARNING | 126 0.001 0.000 4.169 0.033 {method 'readline' of '_io.BufferedReader' objects}
[2023-10-11 07:02:17,992] [ HABApp.Worker] WARNING | 16 0.000 0.000 4.168 0.260 /usr/local/lib/python3.11/socket.py:692(readinto)
[2023-10-11 07:02:18,003] [ HABApp.Worker] WARNING | 16 4.167 0.260 4.167 0.260 {method 'recv_into' of '_socket.socket' objects}
[2023-10-11 07:02:18,004] [ HABApp.Worker] WARNING | 10 0.001 0.000 3.031 0.303 /habapp/config/lib/requests/adapters.py:434(send)
[2023-10-11 07:02:18,004] [ HABApp.Worker] WARNING | 10 0.001 0.000 2.842 0.284 /habapp/config/lib/urllib3/connectionpool.py:595(urlopen)
[2023-10-11 07:02:18,004] [ HABApp.Worker] WARNING | 10 0.019 0.002 2.696 0.270 /habapp/config/lib/urllib3/connectionpool.py:380(_make_request)
[2023-10-11 07:02:18,004] [ HABApp.Worker] WARNING | 28 0.001 0.000 2.324 0.083 /habapp/config/lib/requests/models.py:887(content)
[2023-10-11 07:02:18,004] [ HABApp.Worker] WARNING | 112 0.000 0.000 2.323 0.021 {method 'join' of 'bytes' objects}
[2023-10-11 07:02:18,004] [ HABApp.Worker] WARNING | 20 0.000 0.000 2.323 0.116 /habapp/config/lib/requests/models.py:812(generate)
[2023-10-11 07:02:18,005] [ HABApp.Worker] WARNING | 20 0.000 0.000 2.322 0.116 /habapp/config/lib/urllib3/response.py:918(stream)
[2023-10-11 07:02:18,005] [ HABApp.Worker] WARNING | 18 0.003 0.000 2.321 0.129 /habapp/config/lib/urllib3/response.py:1036(read_chunked)
[2023-10-11 07:02:18,005] [ HABApp.Worker] WARNING | 18 0.000 0.000 2.251 0.125 /habapp/config/lib/urllib3/response.py:1000(_update_chunk_length)
[2023-10-11 07:02:18,005] [ HABApp.Worker] WARNING | 10 0.003 0.000 2.113 0.211 /habapp/config/lib/urllib3/connection.py:435(getresponse)
[2023-10-11 07:02:18,005] [ HABApp.Worker] WARNING | 10 0.001 0.000 2.104 0.210 /usr/local/lib/python3.11/http/client.py:1334(getresponse)
[2023-10-11 07:02:18,005] [ HABApp.Worker] WARNING | 10 0.001 0.000 2.093 0.209 /usr/local/lib/python3.11/http/client.py:311(begin)
[2023-10-11 07:02:18,005] [ HABApp.Worker] WARNING | 10 0.001 0.000 1.919 0.192 /usr/local/lib/python3.11/http/client.py:278(_read_status)
[2023-10-11 07:02:18,005] [ HABApp.Worker] WARNING | 10 0.001 0.000 0.563 0.056 /habapp/config/lib/urllib3/connection.py:319(request)
[2023-10-11 07:02:18,006] [ HABApp.Worker] WARNING | 10 0.001 0.000 0.482 0.048 /usr/local/lib/python3.11/http/client.py:1270(endheaders)
[2023-10-11 07:02:18,006] [ HABApp.Worker] WARNING | 10 0.000 0.000 0.481 0.048 /usr/local/lib/python3.11/http/client.py:1032(_send_output)
[2023-10-11 07:02:18,006] [ HABApp.Worker] WARNING | 10 0.006 0.001 0.481 0.048 /usr/local/lib/python3.11/http/client.py:971(send)
[2023-10-11 07:02:18,006] [ HABApp.Worker] WARNING | 1 0.000 0.000 0.448 0.448 /habapp/config/rules/weather.py:74(wup_ws_update)
[2023-10-11 07:02:18,006] [ HABApp.Worker] WARNING | 2 0.000 0.000 0.404 0.202 /habapp/config/lib/urllib3/connection.py:242(connect)
[2023-10-11 07:02:18,006] [ HABApp.Worker] WARNING | 2 0.000 0.000 0.404 0.202 /habapp/config/lib/urllib3/connection.py:197(_new_conn)
[2023-10-11 07:02:18,006] [ HABApp.Worker] WARNING | 2 0.000 0.000 0.404 0.202 /habapp/config/lib/urllib3/util/connection.py:27(create_connection)
[2023-10-11 07:02:18,006] [ HABApp.Worker] WARNING | 1 0.000 0.000 0.391 0.391 /habapp/config/lib/requests/api.py:118(put)
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 1 0.000 0.000 0.391 0.391 /habapp/config/lib/requests/api.py:14(request)
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 2 0.239 0.120 0.239 0.120 {method 'connect' of '_socket.socket' objects}
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 71 0.104 0.001 0.233 0.003 /habapp/config/lib/urllib3/util/url.py:227(_encode_invalid_chars)
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 30 0.037 0.001 0.213 0.007 /habapp/config/lib/urllib3/util/url.py:369(parse_url)
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 10 0.004 0.000 0.177 0.018 /habapp/config/lib/requests/sessions.py:751(merge_environment_settings)
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 10 0.000 0.000 0.170 0.017 /habapp/config/lib/requests/utils.py:824(get_environ_proxies)
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 20 0.156 0.008 0.167 0.008 /usr/local/lib/python3.11/urllib/request.py:2499(getproxies_environment)
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 2 0.000 0.000 0.164 0.082 /usr/local/lib/python3.11/socket.py:945(getaddrinfo)
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 2 0.163 0.082 0.163 0.082 {built-in method _socket.getaddrinfo}
[2023-10-11 07:02:18,007] [ HABApp.Worker] WARNING | 10 0.000 0.000 0.160 0.016 /habapp/config/lib/requests/adapters.py:331(get_connection)
[2023-10-11 07:02:18,008] [ HABApp.Worker] WARNING | 10 0.001 0.000 0.158 0.016 /habapp/config/lib/urllib3/poolmanager.py:356(connection_from_url)
[2023-10-11 07:02:18,008] [ HABApp.Worker] WARNING | 80 0.149 0.002 0.151 0.002 /usr/local/lib/python3.11/email/message.py:489(get)
[2023-10-11 07:02:18,008] [ HABApp.Worker] WARNING | 10 0.001 0.000 0.144 0.014 /habapp/config/lib/requests/sessions.py:459(prepare_request)
[2023-10-11 07:02:18,013] [ HABApp.Worker] WARNING | 71 0.123 0.002 0.125 0.002 {method 'subn' of 're.Pattern' objects}
[2023-10-11 07:02:18,013] [ HABApp.Worker] WARNING | 10 0.121 0.012 0.121 0.012 /habapp/config/lib/requests/models.py:258(__init__)
[2023-10-11 07:02:18,014] [ HABApp.Worker] WARNING | 70 0.002 0.000 0.078 0.001 /habapp/config/lib/requests/sessions.py:61(merge_setting)
[2023-10-11 07:02:18,014] [ HABApp.Worker] WARNING | 71 0.057 0.001 0.075 0.001 <frozen _collections_abc>:941(update)
Looking at the events log I do not see any stalling:
[2023-10-11 07:02:15,195] [ HABApp.EventBus] INFO | GarageTemp: <ItemStateUpdatedEvent name: GarageTemp, value: 20.4>
[2023-10-11 07:02:15,195] [ HABApp.EventBus] INFO | GarageHumid: <ItemStateUpdatedEvent name: GarageHumid, value: 56>
[2023-10-11 07:02:17,143] [ HABApp.EventBus] INFO | chromecast:chromecast:2b9f1ec4a8d24cdf0f0abc0fec019468: <ThingStatusInfoEvent name: chromecast:chromecast:2b9f1ec4a8d24cdf0f0abc0fec019468, status: ONLINE, detail: NONE>
[2023-10-11 07:02:17,145] [ HABApp.EventBus] INFO | chromecast:chromecast:9dad6897e581ff1cd0d08309b3a333fe: <ThingStatusInfoEvent name: chromecast:chromecast:9dad6897e581ff1cd0d08309b3a333fe, status: ONLINE, detail: NONE>
[2023-10-11 07:02:17,147] [ HABApp.EventBus] INFO | chrome_cast_test_volume: <ItemStateUpdatedEvent name: chrome_cast_test_volume, value: 50.0%>
[2023-10-11 07:02:17,148] [ HABApp.EventBus] INFO | GoogleChromCastVol: <ItemStateUpdatedEvent name: GoogleChromCastVol, value: 50.0%>
[2023-10-11 07:02:17,148] [ HABApp.EventBus] INFO | iPhoneSLUPingOK: <ItemStateUpdatedEvent name: iPhoneSLUPingOK, value: OFF>
[2023-10-11 07:02:17,149] [ HABApp.EventBus] INFO | SMACVP1: <ItemStateUpdatedEvent name: SMACVP1, value: 244.4>
[2023-10-11 07:02:17,150] [ HABApp.EventBus] INFO | SMACVP1: <ItemStateChangedEvent name: SMACVP1, value: 244.4, old_value: 244.2>
[2023-10-11 07:02:17,151] [ HABApp.EventBus] INFO | SMACVP2: <ItemStateUpdatedEvent name: SMACVP2, value: 243.8>
[2023-10-11 07:02:17,151] [ HABApp.EventBus] INFO | SMACVP2: <ItemStateChangedEvent name: SMACVP2, value: 243.8, old_value: 243.9>
[2023-10-11 07:02:17,151] [ HABApp.EventBus] INFO | SMACVP3: <ItemStateUpdatedEvent name: SMACVP3, value: 244.8>
[2023-10-11 07:02:17,152] [ HABApp.EventBus] INFO | gpstracker:tracker:SL: <ThingStatusInfoEvent name: gpstracker:tracker:SL, status: ONLINE, detail: NONE>
[2023-10-11 07:02:17,153] [ HABApp.EventBus] INFO | PVSolarEnergy: <ItemStateUpdatedEvent name: PVSolarEnergy, value: 0>
[2023-10-11 07:02:17,158] [ HABApp.EventBus] INFO | PVSolarEnergyDay: <ItemStateUpdatedEvent name: PVSolarEnergyDay, value: 0>
[2023-10-11 07:02:17,159] [ HABApp.EventBus] INFO | PVSolarEnergyTotal: <ItemStateUpdatedEvent name: PVSolarEnergyTotal, value: 15.453529>
[2023-10-11 07:02:17,161] [ HABApp.EventBus] INFO | PVSolarEnergyYear: <ItemStateUpdatedEvent name: PVSolarEnergyYear, value: 2.25379225>
[2023-10-11 07:02:17,163] [ HABApp.EventBus] INFO | PVSolarHz: <ItemStateUpdatedEvent name: PVSolarHz, value: 0>
[2023-10-11 07:02:17,164] [ HABApp.EventBus] INFO | PVSolarACA: <ItemStateUpdatedEvent name: PVSolarACA, value: 0>
[2023-10-11 07:02:17,164] [ HABApp.EventBus] INFO | PVSolarDCA: <ItemStateUpdatedEvent name: PVSolarDCA, value: 0>
[2023-10-11 07:02:17,165] [ HABApp.EventBus] INFO | PVSolarACV: <ItemStateUpdatedEvent name: PVSolarACV, value: 0>
[2023-10-11 07:02:17,166] [ HABApp.EventBus] INFO | PVSolarDCV: <ItemStateUpdatedEvent name: PVSolarDCV, value: 294.4>
[2023-10-11 07:02:17,166] [ HABApp.EventBus] INFO | PVSolarDCV: <ItemStateChangedEvent name: PVSolarDCV, value: 294.4, old_value: 294.1>
[2023-10-11 07:02:17,167] [ HABApp.EventBus] INFO | PVGridLoad: <ItemStateUpdatedEvent name: PVGridLoad, value: 380.99>
[2023-10-11 07:02:17,167] [ HABApp.EventBus] INFO | PVGridLoad: <ItemStateChangedEvent name: PVGridLoad, value: 380.99, old_value: 381.9>
[2023-10-11 07:02:17,168] [ HABApp.EventBus] INFO | PVHouseLoad: <ItemStateUpdatedEvent name: PVHouseLoad, value: -380.99>
[2023-10-11 07:02:17,169] [ HABApp.EventBus] INFO | PVHouseLoad: <ItemStateChangedEvent name: PVHouseLoad, value: -380.99, old_value: -381.9>
[2023-10-11 07:02:17,170] [ HABApp.EventBus] INFO | gpstracker:tracker:IL: <ThingStatusInfoEvent name: gpstracker:tracker:IL, status: ONLINE, detail: NONE>
[2023-10-11 07:02:17,879] [ HABApp.EventBus] INFO | CWLIceSts: <ItemStateUpdatedEvent name: CWLIceSts, value: 1>
[2023-10-11 07:02:18,892] [ HABApp.EventBus] INFO | CWLStep1Vol: <ItemCommandEvent name: CWLStep1Vol, value: 80>
[2023-10-11 07:02:18,894] [ HABApp.EventBus] INFO | CWLStep1Vol: <ItemStatePredictedEvent name: CWLStep1Vol, value: 80>
[2023-10-11 07:02:18,895] [ HABApp.EventBus] INFO | CWLStep1Vol: <ItemStateUpdatedEvent name: CWLStep1Vol, value: 80>
[2023-10-11 07:02:19,737] [ HABApp.EventBus] INFO | GarageHeating: <ItemCommandEvent name: GarageHeating, value: OFF>
[2023-10-11 07:02:19,738] [ HABApp.EventBus] INFO | GarageHeating: <ItemStatePredictedEvent name: GarageHeating, value: OFF>
[2023-10-11 07:02:19,739] [ HABApp.EventBus] INFO | GarageHeating: <ItemStateUpdatedEvent name: GarageHeating, value: OFF>
[2023-10-11 07:02:19,754] [ HABApp.EventBus] INFO | HABApp_Ping: <ItemStateUpdatedEvent name: HABApp_Ping, value: 1873.7>
[2023-10-11 07:02:19,942] [ HABApp.EventBus] INFO | HABApp_Ping: <ItemStateChangedEvent name: HABApp_Ping, value: 1873.7, old_value: 12.7>
[2023-10-11 07:02:20,741] [ HABApp.EventBus] INFO | GarageHeating: <ItemCommandEvent name: GarageHeating, value: OFF>
[2023-10-11 07:02:20,742] [ HABApp.EventBus] INFO | GarageHeating: <ItemStatePredictedEvent name: GarageHeating, value: OFF>
[2023-10-11 07:02:20,742] [ HABApp.EventBus] INFO | GarageHeating: <ItemStateUpdatedEvent name: GarageHeating, value: OFF>
Looking at the HABApp_Ping there is a significant spike:
I think that at that time no event processing was done. The whole issue lasted for about 2-3 minutes without any other indicating log entries.
Any Idea what the root cause for this issue could be?
Increasing the thread pool an optional solution?
As PM I could send the whole log file, containing the start of the instance up to now.