agame wrote:thanks for the insight, increasing to 15 appears to have solved my problem.
It does have me a bit intrigued how to correlate a queue of a particular size with a real-world time lag? Is there any rule of thumb for what might contribute a significant lag? I guess playing with a light switch by trial-and-error would show that but harder to know with temperature readings.
So I think the queued log message might be misconstrued as indicating there is lag/delay in the processing. Months back, I needed to do some performance debugging and I found that ShellyMQTT can take a message from the MQTTConnector queue (over the Indigo inter-plugin communication layer) and process that message by updating various Indigo components in some ridiculously small amount of time. If I remember correctly it was in the sub-millisecond range.
So let's say Shelly MQTT can fully dequeue and process a message in 1 millisecond. Here is the MQTT message log (using mosquito_sub on my terminal) with the timestamp of when my computer received this batch of messages from the broker.
- Code: Select all
> mosquitto_sub -h 192.168.1.7 -t "shellies/#" -F "%U %t %p"
1613395907.631712000 shellies/ShellyBulbDuo-D0CF64/light/0 on
1613395907.634397000 shellies/ShellyBulbDuo-D0CF64/light/0/status {"ison":true,"source":"mqtt","has_timer":false,"timer_started":0,"timer_duration":0,"timer_remaining":0,"brightness":100,"white":0,"temp":2700}
1613395907.634452000 shellies/ShellyBulbDuo-D0CF64/light/0/power 9.00
1613395907.634496000 shellies/ShellyBulbDuo-D0CF64/light/0/energy 64393
So my Shelly Duo published 4 messages in an update with the first being at 1613395907.631712000 and the last being at 1613395907.634496000 - these are Unix timestamps with enough decimals to reach the nanosecond range. These 4 messages were published in a span of 0.002784 seconds. You can even see that some messages were published with 0.00004 seconds in between.
They way Joe has programmed his plugin to show these "queue has x" messages is - as soon as the queue is filled above a threshold, the message is logged. There is nothing wrong with this, but we just have to understand what it really means in this case.
For the sake of argument, let's say that a Shelly device can publish messages at a rate that is 10x faster than what ShellyMQTT can dequeue and process them (proof is above). So this means that when you have a really active device, like your Shelly 1 with 3 sensors, it will publish a huge amount of individual messages on those separate topics. It looks like this could be up to 17 individual messages based on their API. This essentially means that 15-16 messages will be received while ShellyMQTT is still potentially processing the first or second message.
Here is where we now have 15/16 messages queued, and the log entry appears.If we look at the big picture, that queue will be empty in another 16 milliseconds.
Basically, ignore or adjust the threshold (25-50 is probably safe depending on how "chatty" your devices are) of that log message UNLESS that queue number is growing continuously. That is what I believe that message was designed for - to indicate that we are queueing messages but not consuming them with a Shims device or another Indigo plugin (ShellyMQTT).
I hope that provides some insight and/or satisfies you rather than blindly changing a number to make a message go away. If anything, it was a fun exercise for me this morning
-Aaron