Rest API is slow

Development
1

Hi,

I’m trying to toggle my lights via the REST API so that I can control the lights with AutoHotkey. It’s working great except for the fact that the response times are very slow (1-7 seconds).

I’m using a Python script to do this:

import time as time
import requests

totalTimeStart = time.time()
token=<redacted>
url = 'http://homeassistant.local:8123/api/services/switch/toggle'
headers = {
    'Authorization': 'Bearer ' + token,
    'content-type': 'application/json'
}
data = '{"entity_id": "switch.kuled_4"}'
responseTimeStart = time.time()
response = requests.post(url, data, headers=headers)
print('response time: ' + str(time.time() - responseTimeStart))
print(response.text)
print('total time: ' + str(time.time() - totalTimeStart))

Physically switching the switches, using z-wave remotes, or calling the service from Home Assistant’s developer tools all have a delay of a fraction of a second, so it’s the rest API that’s taking a long time to respond.

Excluding the amount of time it takes to wait for the response reveals that the python script itself takes thousandths of a second to run at most (as expected), so there’s no issues there either. Anyone know why this is so slow and how to speed it up?

2

Read this How to help us help you - or How to ask a good question

3

Not sure what my post is missing other than perhaps my installation info, which is hassio on a Raspberry Pi 4:

Home Assistant 0.115.6
docker_version 19.03.11
HassOS 4.13

4

where are your logs?

5

What logs do you need? Looking at the Logbook, it shows the lights switching when the response is triggered (as opposed to when the request is sent - as expected). /config/logs also doesn’t contain anything relevant.

6

Let me ask in a different way, have you set your logging level to debug and traced the exact sequence of steps home assistant takes to execute this? Each line in the log is time stamped so you may get a hint as to the slowest link.

1 Like
7

OK, I didn’t realize I had to add a component to get debug level logging, sorry.

Here is an example in which it took 6.8 seconds (this was how long it took to get a response according to Python) to turn a light off via the API. Watching my computer’s clock, I sent the request to turn the light on at 16:29:49 and it turned on at 16:29:50 after which I immediately sent the request to turn it off at 16:29:50 and it finally turned off at 16:29:57

2020-10-31 16:26:49 DEBUG (MainThread) [homeassistant.components.http.view] Serving /api/services/switch/toggle to 192.168.0.137 (auth: True)
2020-10-31 16:26:49 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=toggle, service_data=entity_id=switch.kuled_5>
2020-10-31 16:26:49 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=mqtt, service=publish, service_data=topic=cmnd/tasmota_D9A6D4/POWER, qos=0, retain=False, payload=ON>
2020-10-31 16:26:49 DEBUG (SyncWorker_46) [paho.mqtt.client] Sending PUBLISH (d0, q0, r0, m79), 'b'cmnd/tasmota_D9A6D4/POWER'', ... (2 bytes)
2020-10-31 16:26:49 DEBUG (MainThread) [homeassistant.components.mqtt] Transmitting message on cmnd/tasmota_D9A6D4/POWER: 'ON', mid: 79
2020-10-31 16:26:49 DEBUG (Thread-5) [paho.mqtt.client] Received PUBLISH (d0, q0, r0, m0), 'tele/tasmota_D9A6D4/STATE', ...  (286 bytes)
2020-10-31 16:26:49 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on tele/tasmota_D9A6D4/STATE: b'{"Time":"2020-10-31T22:26:49","Uptime":"1T02:13:04","UptimeSec":94384,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"cc5g","BSSId":"74:DA:88:BC:64:89","Channel":10,"RSSI":100,"Signal":-35,"LinkCount":1,"Downtime":"0T00:07:56"}}'
2020-10-31 16:26:49 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.kuled_5, old_state=<state switch.kuled_5=off; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:20:26.753651-05:00>, new_state=<state switch.kuled_5=on; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:49.642749-05:00>>
2020-10-31 16:26:49 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2941545920] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=switch.kuled_5, old_state=<state switch.kuled_5=off; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:20:26.753651-05:00>, new_state=<state switch.kuled_5=on; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:49.642749-05:00>>}
2020-10-31 16:26:49 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2888724192] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=switch.kuled_5, old_state=<state switch.kuled_5=off; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:20:26.753651-05:00>, new_state=<state switch.kuled_5=on; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:49.642749-05:00>>}
2020-10-31 16:26:50 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.137':5353 (socket 10): <DNSIncoming:{id=0, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[a,in,homeassistant.local.]], answers=[]}> (37 bytes) as [b'\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\rhomeassistant\x05local\x00\x00\x01\x00\x01']
2020-10-31 16:26:50 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.199':5353 (socket 10): <DNSIncoming:{id=0, flags=33792, n_q=0, n_ans=1, n_auth=0, n_add=0, questions=[], answers=[record[a,in-unique,homeassistant.local.]=120/119,192.168.0.199]}> (47 bytes) as [b'\x00\x00\x84\x00\x00\x00\x00\x01\x00\x00\x00\x00\rhomeassistant\x05local\x00\x00\x01\x80\x01\x00\x00\x00x\x00\x04\xc0\xa8\x00\xc7']
2020-10-31 16:26:50 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.137':5353 (socket 10): <DNSIncoming:{id=0, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[quada,in,homeassistant.local.]], answers=[]}> (37 bytes) as [b'\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\rhomeassistant\x05local\x00\x00\x1c\x00\x01']
2020-10-31 16:26:50 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.199':5353 (socket 10): <DNSIncoming:{id=0, flags=33792, n_q=0, n_ans=1, n_auth=0, n_add=0, questions=[], answers=[record[quada,in-unique,homeassistant.local.]=120/119,fe80::821d:1c85:6794:5429]}> (59 bytes) as [b'\x00\x00\x84\x00\x00\x00\x00\x01\x00\x00\x00\x00\rhomeassistant\x05local\x00\x00\x1c\x80\x01\x00\x00\x00x\x00\x10\xfe\x80\x00\x00\x00\x00\x00\x00\x82\x1d\x1c\x85g\x94T)']
2020-10-31 16:26:50 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '172.30.32.1':5353 (socket 10): <DNSIncoming:{id=0, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[a,in,homeassistant.local.]], answers=[]}> (37 bytes) as [b'\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\rhomeassistant\x05local\x00\x00\x01\x00\x01']
2020-10-31 16:26:50 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '172.30.32.1':5353 (socket 10): <DNSIncoming:{id=0, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[quada,in,homeassistant.local.]], answers=[]}> (37 bytes) as [b'\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\rhomeassistant\x05local\x00\x00\x1c\x00\x01']
2020-10-31 16:26:50 DEBUG (Thread-5) [paho.mqtt.client] Received PUBLISH (d0, q0, r0, m0), 'tele/tasmota_D9A6D4/STATE', ...  (286 bytes)
2020-10-31 16:26:50 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on tele/tasmota_D9A6D4/STATE: b'{"Time":"2020-10-31T22:26:50","Uptime":"1T02:13:05","UptimeSec":94385,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"cc5g","BSSId":"74:DA:88:BC:64:89","Channel":10,"RSSI":100,"Signal":-34,"LinkCount":1,"Downtime":"0T00:07:56"}}'
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.1':36621 (socket 10): <DNSIncoming:{id=18077, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[ptr,in,192.168.0.105.in-addr.arpa.]], answers=[]}> (44 bytes) as [b'F\x9d\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03105\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Ignoring duplicate message received from '172.30.32.1':5353 (socket 10) (44 bytes) as [b'F\x9d\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03105\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.1':44947 (socket 10): <DNSIncoming:{id=18078, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[ptr,in,192.168.0.105.in-addr.arpa.]], answers=[]}> (44 bytes) as [b'F\x9e\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03105\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Ignoring duplicate message received from '172.30.32.1':5353 (socket 10) (44 bytes) as [b'F\x9e\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03105\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.1':58379 (socket 10): <DNSIncoming:{id=18079, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[ptr,in,192.168.0.153.in-addr.arpa.]], answers=[]}> (44 bytes) as [b'F\x9f\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03153\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Ignoring duplicate message received from '172.30.32.1':5353 (socket 10) (44 bytes) as [b'F\x9f\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03153\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.1':57979 (socket 10): <DNSIncoming:{id=18080, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[ptr,in,192.168.0.153.in-addr.arpa.]], answers=[]}> (44 bytes) as [b'F\xa0\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03153\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Ignoring duplicate message received from '172.30.32.1':5353 (socket 10) (44 bytes) as [b'F\xa0\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03153\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.1':45832 (socket 10): <DNSIncoming:{id=18081, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[ptr,in,192.168.0.242.in-addr.arpa.]], answers=[]}> (44 bytes) as [b'F\xa1\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03242\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Ignoring duplicate message received from '172.30.32.1':5353 (socket 10) (44 bytes) as [b'F\xa1\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03242\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Received from '192.168.0.1':32978 (socket 10): <DNSIncoming:{id=18082, flags=0, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[question[ptr,in,192.168.0.242.in-addr.arpa.]], answers=[]}> (44 bytes) as [b'F\xa2\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03242\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:51 DEBUG (zeroconf-Engine-264) [zeroconf] Ignoring duplicate message received from '172.30.32.1':5353 (socket 10) (44 bytes) as [b'F\xa2\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x03192\x03168\x010\x03242\x07in-addr\x04arpa\x00\x00\x0c\x00\x01']
2020-10-31 16:26:53 DEBUG (MainThread) [homeassistant.components.ssdp] Scanning
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.components.http.auth] Authenticated 192.168.0.137 for /api/services/switch/toggle using bearer token
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.components.http.view] Serving /api/services/switch/toggle to 192.168.0.137 (auth: True)
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=toggle, service_data=entity_id=switch.kuled_5>
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=mqtt, service=publish, service_data=topic=cmnd/tasmota_D9A6D4/POWER, qos=0, retain=False, payload=OFF>
2020-10-31 16:26:57 DEBUG (SyncWorker_2) [paho.mqtt.client] Sending PUBLISH (d0, q0, r0, m80), 'b'cmnd/tasmota_D9A6D4/POWER'', ... (3 bytes)
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.components.mqtt] Transmitting message on cmnd/tasmota_D9A6D4/POWER: 'OFF', mid: 80
2020-10-31 16:26:57 DEBUG (Thread-5) [paho.mqtt.client] Received PUBLISH (d0, q0, r0, m0), 'tele/tasmota_D9A6D4/STATE', ...  (287 bytes)
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on tele/tasmota_D9A6D4/STATE: b'{"Time":"2020-10-31T22:26:56","Uptime":"1T02:13:11","UptimeSec":94391,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"OFF","Wifi":{"AP":1,"SSId":"cc5g","BSSId":"74:DA:88:BC:64:89","Channel":10,"RSSI":100,"Signal":-33,"LinkCount":1,"Downtime":"0T00:07:56"}}'
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.kuled_5, old_state=<state switch.kuled_5=on; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:49.642749-05:00>, new_state=<state switch.kuled_5=off; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:57.226054-05:00>>
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2941545920] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=switch.kuled_5, old_state=<state switch.kuled_5=on; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:49.642749-05:00>, new_state=<state switch.kuled_5=off; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:57.226054-05:00>>}
2020-10-31 16:26:57 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2888724192] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=switch.kuled_5, old_state=<state switch.kuled_5=on; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:49.642749-05:00>, new_state=<state switch.kuled_5=off; friendly_name=Studio Right Wall Lights @ 2020-10-31T16:26:57.226054-05:00>>}```
1 Like
8

Try your script using the IP address, not homeassistant.local

1 Like
9

Using the IP address brought the response time down to 0.02 seconds. Thanks! Must have been taking a long time to resolve the name then?

10

I am thinking so. You could do some investigation if what is going on with

dig +trace homeassistant.local
1 Like