Delayed relay response

[drtinaz]

As a few others have also reported this issue, I thought I would create an issue report here. I am also experiencing a delay in relay response. I am not however using USB comms for the module, I am using modbus rtu over TCP. I notice a 1 to 2 second delay from tapping the relay on/off until the gui changes display. I do not have any delay with the old version of the package. (Full disclosure: I had modified the old version to use tcpip over wifi)

[Lucifer06]

I also noticed that. The delay seems more on the side of the GUI refresh rather than reactivity of the driver. Disabling Node-Red seems to improve a bit, but still find the GUI to be slow.

With internal relays thesis blazing fast, so there must be a way to force the GUI refresh right after RemoteGPIO has finished his work with the relay...

[Lucifer06]

Trying from the Relay menu, I see the same latency, so this si not related with GUI update. May be I need to set something else in D-Bus. Any idea?

[Lucifer06]

I don't think this is related with CPU load. I probably also need to look at timing RemoteGPIO driver to see if I'm releasing the resources straight away

[Lucifer06]

Do you think this is a regression introduced since v3.1? Was 3.0.25 faster ?

[drtinaz]

3.0.25 was the same. The only real changes between 3.0.25 and 3.1 is that setup helper automatically installs each file rather than having to call each one individually in the setup script.

Maybe ask Kevin. He has done some work with relay integration for RPi's so he may have some insight.

[Lucifer06]

Still working after that issue. Here are my findings so far: For relay 3, for example, RemoteGPIO driver is reading /dev/gpio/relay_3/value and then communicates with the Relay unit. There is no noticeable delay in this process. The delay is on the GUI side and on when it reports the new Relay status value. Because of that it prevents to flip again the Relay until the GUI displays the new state.

How is it working? Venus OS is responsible to write 0/1 in the /dev/gpio/relay_1/value You can also write the 0/1 at dbus level and experience the same latency issue with RemoteGPIO but not with the internal relays.

Interestingly, when writing the 0/1 in /dev/gpio/relay_1/value for the internal relay, I see the same long latency for updating the GUI as with RemoteGPIO. So my current theory is that Venus OS is making a particular call for forcing the update of the GUI, so you can then get that feeling the latency is low.

[drtinaz]

Have you mentioned it to @kwindrem ? I wonder if there is anything in guimods that might have this effect?

Edit: FYI, I have seen this issue with the old version but only on a few venus firmware, and not recently.

[kwindrem]

If you are seeing latencies writing to com.victronenergy.system / Relay/n then I think you can rule out GuiMods. The changes it makes are to add the relay overview page and add additional items in the relay menu for configuring the additional relays.

systemcalc (in relaystate.ph) is responsible for taking changes on dbus to the /dev/gpio... but if the delays are also seen with a direct write to /dev/gpio... then I aldo doubt that's the source of delay. Delays there are pretty low down, like at "driver" level.

You might look at top to see if any process is consuming CPU time during these delays.

[Lucifer06]

@kwindrem with additional relays with your repo rpigpio, do you see a latency on updating the GUI? Could you change the state, say multiple times a second if you are frantically hit the ON or OFF button?

[kwindrem]

I'm not using your external relay board but with the GPIO pins on my PI, there is no notcible delay.

I did try pushing buttons in the relay overview as fast as I could but this made no difference.

[Lucifer06]

OK thx. One more question, as I believe I have an idea on the root cause: When switching the Relay to a different position with bus-send, I get the following error; this error is only if the relay have to change state, for ex from on to off in this example, assuming the relay is on. if already off, there is no error:

dbus-send --system --print-reply --dest=com.victronenergy.system /Relay/4/State com.victronenergy.BusItem.SetValue variant:int32:0 Error org.freedesktop.DBus.Python.KeyError: Traceback (most recent call last): File "/usr/lib/python3.8/site-packages/dbus/service.py", line 711, in _message_cb retval = candidate_method(self, *args, **keywords) File "/opt/victronenergy/dbus-systemcalc-py/ext/velib_python/vedbus.py", line 545, in SetValue (self._onchangecallback is not None and self._onchangecallback(self.dbus_object_path, newvalue))): File "/opt/victronenergy/dbus-systemcalc-py/ext/velib_python/vedbus.py", line 140, in _value_changed return self._onchangecallbacks[path](path, newvalue) File "/opt/victronenergy/dbus-systemcalc-py/delegates/relaystate.py", line 123, in _on_relay_state_changed self._settings[dbus_path] = state File "/opt/victronenergy/dbus-systemcalc-py/ext/velib_python/settingsdevice.py", line 115, in setitem result = self._settings[setting].set_value(newvalue) KeyError: '/Relay/4/State'

Do you have the same error with rpigpio? If not then I think I need to deep dive on how my devices are handled, because there is no local HW that creates the /dev/gpio entries, I simulated it. The error, and may be latency as to do with this. And the latency was not seen with RemoteGPIO because I was not using D-Bus at all and my driver was directly talking to the Dingtian unit...

[kwindrem]

I do not see this error with relays added with RpiGpioSetup.

RpiGpioSetup modifies get_settings () in /opt/victronenergy/dbus-system-calc/delegates/relaystate.py to add relays 3-6 for the PI.

When I remove this mod, I get the delayed behavior for all but the first two relays!!

The mod has to do with updating a mirror of the system state for a relay in Settings so that the state is restored after a reboot. Relay changes are logged by localsettings but the log does NOT show any relay without the mod I described above. I suspect there is an unlogged delay in attempting to update a nonexistent setting parameter.

My guess is you need to make the same mods to relaystate.py I did but for all 18 relays.

[Lucifer06]

Also, on a Cerbo with the native Relays,

echo 1 > relay_1/value Takes long time to have the GUI updated. Exactly like I'm experiencing with RemoteGPIO

Is it the same with rpigpio?

[Lucifer06]

Ok I made an interesting test, and I would like to have your opinion:

On a CerboGX, relay_2 is the second internal relay. Relay_3 is the first relay from RemoteGPIO. I linked both relay_2 and relay_3 to my same RemoteGPIO device (gpio103): ln -s /data/RemoteGPIO/sys/class/gpio/gpio103 /dev/gpio/relay_2 ln -s /data/RemoteGPIO/sys/class/gpio/gpio103 /dev/gpio/relay_3

Then playing with the GUI, both relay 2 and 3 are effectively controlling the Dingtian relay via RemoteGPIO driver. The interesting point here is that the GUI is ultra reactive with relay_2 but not with relay_3. In other words, if all relays are off, and I hit the On button of Relay2, I hear the Dingtian box closing right away, and the On buttons turns Green straight away. Couple of seconds later, I see the GUI updating the On button of Relay3. Playing with Relay3 buttons is also slow, like before.

It demonstrates the slowness is not coming from the driver, nor the /dev

Something is happening to make the GUI reactive with Relay2... An idea?

[kwindrem]

It is not the GUI. You can verify this by shutting down the GUI: svc -d /services/start-gui or /service/gui on a PI. then running your tests from dbus-spy changing the relay state in com.victronenergy.service /Relay/n/State.

As I explained above, when systemcalc detects a relay state change, it sends this change to Settings (the localsettings service) to update the mirrored copy in nonvolatile storage so the relay will go back to this state after a reboot. This is what is taking the time and I don't see anything in the logs to indicate where it is exactly.

[Lucifer06]

Kevin, you were right, I had a typo in /opt/victronenergy/dbus-systemcalc-py/delegates/relaystate.py Thanks so much for pointing to the right direction. The relays are now ultra fast! This is fixed in v3.1.6