MQTT Import time lack

Moderators: grovkillen, Stuntteam, TD-er

Message
Author
Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

MQTT Import time lack

#1 Post by Wiki » 20 Nov 2022, 16:47

Monitoring my small solar project I noticed now and then, that between a published message from the sending devices the correct data arrive in ESPEasy with a - sometimes huge - lack of time.

Are the imported messages somehow queued or buffered? If yes, is there a way to avoid reactions sometimes way far away from reality?

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

User avatar
Ath
Normal user
Posts: 3415
Joined: 10 Jun 2018, 12:06
Location: NL

Re: MQTT Import time lack

#2 Post by Ath » 20 Nov 2022, 18:58

You have reported unexpected rebooting of the ESP with many tasks running this plugin concurrently. Is that a possible cause here?
Reboots can also be caused when large (JSON?) messages are being received by the ESP. You could connect to the serial port of the ESP to see all logging, as the weblog can't be updated during boot, because of the WiFi not yet being started.

Also, if the message can't be delivered, the MQTT server will keep retrying until it is delivered. That's by design.
/Ton (PayPal.me)

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#3 Post by Wiki » 20 Nov 2022, 21:39

No reboots.

The longest JSON is the one you helped me to parse.

Looking at the different monitors I can see, a value is published by one of the other devices. At that time ESPEasy receives something, but the value it receives (resp. processes) is somewhat 60-100 secs in the past. No data loss, some 60-100 secs the (too old) data appear later in ESPEasy. And if the ESP32 is in this "buffering" state it doesn't matter from which source the data are imported, they are just too old.

For me it looks like a FIFO buffer......hard to document and to describe..........and I've found up to no way to reproduce.......

After reboot of the ESP32 everything is back working again.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#4 Post by TD-er » 20 Nov 2022, 21:49

Does ESPEasy disconnect/reconnect with the MQTT broker?

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#5 Post by Wiki » 20 Nov 2022, 23:59

No, no disconnects. And no loss of informations,

When the effect is visible, in ESPEasy I receive the messages with a time discrepance of 60-100 secs. But the data are received. Just too late.

Looking online at the log of ESPEasy it tells me around 60 secs later it has received the data which were sent 60 secs earlier as to be seen in an another mqtt client running in parallel. The data are identified to be received, only too late. And in case the effect happens permanently until I reboot the device. And no matter which other device is publishing the data, all of them are affected.

Like I already said: Looks like a FIFO buffer.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#6 Post by TD-er » 21 Nov 2022, 00:58

60 seconds does sound a bit "too perfect" matching a frequently used default timeout/interval for lots of tasks.
Have to check the source code to see if this even is used, but I do find it a bit suspicious to see this value being mentioned here.

User avatar
Ath
Normal user
Posts: 3415
Joined: 10 Jun 2018, 12:06
Location: NL

Re: MQTT Import time lack

#7 Post by Ath » 21 Nov 2022, 07:35

Any chance that the time of the ESP is off by 60 seconds? There has been work done in the time-sync/NTP code recently, maybe you have a situation where an unexpected offset is introduced.
/Ton (PayPal.me)

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#8 Post by TD-er » 21 Nov 2022, 09:12

That would then only have an effect on the reported timestamp, not a delay in receiving the data.
But it is worth checking out to see what we're looking at.
Is it a real delay in processing, or just misreporting the timestamps?

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#9 Post by Wiki » 21 Nov 2022, 10:19

Erm, I didn't have a look at the system time of the ESP.

I don't know anything about the data structure of the mqtt protocol - if there is a timestamp and if the data are buffered. But if the MQTT import has a look at the timestamp of the messages and interpretes it for import the behaviour of the system makes sense in case of a timeshift.

I try once again to explain, whats happening:
One device is sending a data set into mqtt, we name it "data set 1". This "data set 1" appears instantly in the mqtt monitor running in parallel on my tablet. At the same time (it feels like) ESPEasy imports a data set (somewhat "data set -10") which has been sent some time before. After 60-100 secs this "data set 1" sent by the device appears in MQTT Import.

I don't know if my description is understandable, but I can't describe better. For me the misbehaviour is not reproducable and happens only now and then. And I've noticed it only by accident, the ESP itself is running stable with no hints or hickups.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#10 Post by Wiki » 21 Nov 2022, 10:22

And don't take the 60-100 secs as a concrete measurement. Its was more a feeling.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#11 Post by TD-er » 21 Nov 2022, 10:30

Do you have timing statistics enabled on your node, so you can have a look at the timing stats?
Maybe we can see something there which might take a lot more time than we would like.
Not sure if the MQTT import can take so long to process data that it may cause a queue in messages to process.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#12 Post by Wiki » 21 Nov 2022, 10:44

I only have limited possibilties to monitor. But just right now I have seen in a split screen that there was a time lack between the "log" on the Raspberry (mosquitto_sub -t "#" | grep Watt) and the change of the device in Domoticz of 32 secs. After reboot the time lack went down to around 4 secs. Which is normal I think due to processing time in ESPEasy.

Unfortunately I didn't have a look at the time of the ESP. Seems that the time lack increases during running time. I will continue monitoring if I have the time to and will report, hopefully with more accurate informations.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#13 Post by Wiki » 21 Nov 2022, 10:46

Erm, where could I enable "timing statistics"?

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#14 Post by TD-er » 21 Nov 2022, 10:48

We may have to look at how the MQTT client is being called.
It used to be just 'flushing' data to the broker.
So maybe the MQTT client should be called more often to check its status (flushing data and fetching messages).

You could try sending some 'bogus' data from another task to the broker.
For example sysinfo task running at an interval of 1sec, sending to the MQTT controller.

Maybe this increases the number of interactions per sec for the MQTT client?

Timing stats can be enabled at the Tools->Advanced page (near the bottom).
N.B. those may not be included in all builds.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#15 Post by Wiki » 21 Nov 2022, 10:51

Found the hook for timing stats.

Which information do you need when?

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#16 Post by TD-er » 21 Nov 2022, 11:02

Just have a look at stuff that typically takes > 100 msec (highlighted)
But for significant delays in MQTT processing, we might have to look at other values too.
For example how often are those functions called?
If the import calls per second are really low, then we need to have a look at those.
If they are similar to the nr. of calls to send via the MQTT controller, then we may have some indication those are "synced".

So there is not just a single value to look at.

N.B. every time you reload this timing stats page, the stats are cleared.
Thus better let it run for a few minutes.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#17 Post by Wiki » 21 Nov 2022, 13:18

I did some logging in ESPEasy and in my Raspberry in parallel.

ESPEasy:

Code: Select all

262797: 13:01:17-Watt(2),1
273161: 13:01:27-Watt(-5),1
282785: 13:01:36-Watt(-4),1
292693: 13:01:46-Watt(-5),1
303079: 13:01:56-Watt(-5),1
313656: 13:02:07-Watt(-6),1
324963: 13:02:18-Watt(2),1
335934: 13:02:29-Watt(1),1
345009: 13:02:38-Watt(0),1
353621: 13:02:47-Watt(1),1
363794: 13:02:57-Watt(16),1
374001: 13:03:07-Watt(1),1
385006: 13:03:18-Watt(7),1
395384: 13:03:29-Watt(1),1
404763: 13:03:38-Watt(4),1
412299: 13:03:46-Watt(4),1
423654: 13:03:57-Watt(12),1
432809: 13:04:06-Watt(3),1
446974: 13:04:20-Watt(10),1
Raspi:

Code: Select all

{"Time":"2022-11-21T13:01:01","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":2}}
{"Time":"2022-11-21T13:01:11","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":-5}}
{"Time":"2022-11-21T13:01:21","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":-4}}
{"Time":"2022-11-21T13:01:31","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":-5}}
{"Time":"2022-11-21T13:01:41","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":-5}}
{"Time":"2022-11-21T13:01:51","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":-6}}
{"Time":"2022-11-21T13:02:01","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":2}}
{"Time":"2022-11-21T13:02:11","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":1}}
{"Time":"2022-11-21T13:02:21","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":0}}
{"Time":"2022-11-21T13:02:31","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":1}}
{"Time":"2022-11-21T13:02:41","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":16}}
{"Time":"2022-11-21T13:02:51","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":1}}
{"Time":"2022-11-21T13:03:01","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":7}}
{"Time":"2022-11-21T13:03:11","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":1}}
{"Time":"2022-11-21T13:03:21","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":4}}
{"Time":"2022-11-21T13:03:31","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":4}}
{"Time":"2022-11-21T13:03:41","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":12}}
{"Time":"2022-11-21T13:03:51","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":3}}
{"Time":"2022-11-21T13:04:01","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":10}}
{"Time":"2022-11-21T13:04:11","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":9}}
{"Time":"2022-11-21T13:04:21","SML":{"Verbrauch":23.230,"Einspeisung":1.201,"Watt":11}}
If you have a look at the last lines ESPEasy is already around 19 secs behind.

Timing Stats:
Timing Stats.jpg
Timing Stats.jpg (94.7 KiB) Viewed 35604 times
I hope its helpful.....

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#18 Post by TD-er » 21 Nov 2022, 13:27

You better try to load that timing stats page at the beginning, to clear the stats.
Now there's a lot of recorded calls in it from before the ESP got connected.
For example the calls to WiFi.isConnected() with a false return value.
Now I have no idea whether it may try to reconnect inbetween.

Also you seem to receive 6.7 MQTT messages per second.
No idea what the broker may do when a message is not acknowledged by the client.
This also depends on the QoS level used to send messages to the broker.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#19 Post by Wiki » 21 Nov 2022, 14:03

OK, once again:

ESPEasy:

Code: Select all

1194215: 13:45:20-Watt(-13),1
1208505: 13:45:34-Watt(45),1
1208718: 13:45:34-PowerSet(165),1
1216774: 13:45:42-Watt(37),1
1225015: 13:45:50-Watt(46),1
1231875: 13:45:57-Watt(-3),1
1241571: 13:46:07-Watt(-11),1
1252682: 13:46:18-Watt(-8),1
1262493: 13:46:28-Watt(-4),1
1272235: 13:46:38-Watt(-10),1
1281826: 13:46:47-Watt(-5),1
1290922: 13:46:56-Watt(-10),1
1301993: 13:47:07-Watt(-9),1
1314581: 13:47:20-Watt(-2),1
1323495: 13:47:29-Watt(-2),1
1333333: 13:47:39-Watt(-1),1
1345059: 13:47:50-Watt(-10),1
1356116: 13:48:01-Watt(-15),1
1365417: 13:48:11-Watt(-19),1
1365669: 13:48:11-PowerSet(146),1
1377702: 13:48:23-Watt(-11),1
1388176: 13:48:34-Watt(-17),1
1397995: 13:48:43-Watt(-6),1
1404683: 13:48:50-Watt(-8),1
1415621: 13:49:01-Watt(-10),1
1424171: 13:49:10-Watt(-9),1
1433948: 13:49:19-Watt(-10),1
1444652: 13:49:30-Watt(14),1
1444867: 13:49:30-PowerSet(163),1
1455091: 13:49:40-Watt(21),1
Raspberry:

Code: Select all

{"Time":"2022-11-21T13:45:01","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-13}}
{"Time":"2022-11-21T13:45:11","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":45}}
{"Time":"2022-11-21T13:45:21","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":37}}
{"Time":"2022-11-21T13:45:31","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":46}}
{"Time":"2022-11-21T13:45:41","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-3}}
{"Time":"2022-11-21T13:45:51","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-11}}
{"Time":"2022-11-21T13:46:01","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-8}}
{"Time":"2022-11-21T13:46:11","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-4}}
{"Time":"2022-11-21T13:46:21","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-10}}
{"Time":"2022-11-21T13:46:31","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-5}}
{"Time":"2022-11-21T13:46:41","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-10}}
{"Time":"2022-11-21T13:46:51","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-9}}
{"Time":"2022-11-21T13:47:01","SML":{"Verbrauch":23.239,"Einspeisung":1.214,"Watt":-2}}
{"Time":"2022-11-21T13:47:11","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-2}}
{"Time":"2022-11-21T13:47:21","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-1}}
{"Time":"2022-11-21T13:47:31","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-10}}
{"Time":"2022-11-21T13:47:41","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-15}}
{"Time":"2022-11-21T13:47:51","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-19}}
{"Time":"2022-11-21T13:48:01","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-11}}
{"Time":"2022-11-21T13:48:11","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-17}}
{"Time":"2022-11-21T13:48:21","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-6}}
{"Time":"2022-11-21T13:48:31","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-8}}
{"Time":"2022-11-21T13:48:41","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-10}}
{"Time":"2022-11-21T13:48:51","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-9}}
{"Time":"2022-11-21T13:49:01","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":-10}}
{"Time":"2022-11-21T13:49:11","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":14}}
{"Time":"2022-11-21T13:49:21","SML":{"Verbrauch":23.239,"Einspeisung":1.215,"Watt":21}}
{"Time":"2022-11-21T13:49:31","SML":{"Verbrauch":23.240,"Einspeisung":1.215,"Watt":21}}
{"Time":"2022-11-21T13:49:41","SML":{"Verbrauch":23.240,"Einspeisung":1.215,"Watt":5}}
{"Time":"2022-11-21T13:49:51","SML":{"Verbrauch":23.240,"Einspeisung":1.215,"Watt":0}}
{"Time":"2022-11-21T13:50:01","SML":{"Verbrauch":23.240,"Einspeisung":1.215,"Watt":0}}
{
Timing Stats:
Timing Stats.jpg
Timing Stats.jpg (97.8 KiB) Viewed 35595 times
Does MQTT 6.7/secs mean my overall MQTT traffic? The devices I want to fetch are sending every 5 (Ahoy) and every 10 (Volkszähler) seconds.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#20 Post by TD-er » 21 Nov 2022, 15:03

It means the MQTT client did receive some message at a rate of 6.7x sec.
If your node does subscribe to topic(s) also used by other nodes, then this may become a bottle neck.

Another possible bottle neck is the call to TryOpenFile() at roughly 29x per sec.
The ESP32 is a lot slower with file access, so this may keep the ESP board at 100% load at this rate.

Do you happen to have the rules cache disabled?
No idea why it needs to load the task settings at such an incredible high rate. That's often only needed to get the task name and taskvalue name.
But those should be cached. This cache was added because the ESP32 was having issues with reading files at a much slower rate compared to the ESP8266.
You also see an incredible slow down on the ESP32 regarding event handling when it is slowed down like this.

I think we have to focus on why it needs to open the settings file so often.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#21 Post by Wiki » 21 Nov 2022, 15:17

TD-er wrote: 21 Nov 2022, 13:27 [...]
Also you seem to receive 6.7 MQTT messages per second.
No idea what the broker may do when a message is not acknowledged by the client.
[...]
Erm, it looks like you've pushed me in the right direction together with my feeling, that somewhere the data are queued/spooled/buffered/whatever.

I had a look at the (default) mosquitto.conf. There was an entry persistent=true. On the other side - my tiny ESP32 - the hook "Clean Session" in the controller section wasn't set.

I don't know whatfor I could need the persistance, so I switched it off in the mosquitto configuration, restarted mosquitto and since almost an hour the communication is in almost perfect sync.

Am I right, that this combination might have been the source of my problem?

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#22 Post by Wiki » 21 Nov 2022, 15:18

Rules cache is enabled.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#23 Post by TD-er » 21 Nov 2022, 15:22

Wiki wrote: 21 Nov 2022, 15:17 [...]

Am I right, that this combination might have been the source of my problem?
More like the 'trigger' of your problem.
Still I wonder why your setup needs to read the ExtraTaskSettings so often.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#24 Post by Wiki » 21 Nov 2022, 15:28

More: one of the tasks /four values) is subscribed to domoticz/in with JSON parsing, filtered by idx, in another task two values are subscribed to domoticz/out, filtered by idx, too.

I will change at least the import of topics from domoticz/in and see what happens...

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#25 Post by TD-er » 21 Nov 2022, 15:52

Well, domoticz made a very unfortunate design choice back in the day to have a single topic for all nodes.
This doesn't scale very well.

I will try to look at both the Domoticz code and the MQTT import to see if some functions don't use the cached values, or maybe request something that isn't (yet) cached.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#26 Post by Wiki » 21 Nov 2022, 16:06

Digging a little bit deeper I've seen a huge amount of messages on topic domoticz/out. Häh? Why?

The configuration in Domoticz's MQTT Client gateway for "Prevent Loop" was set to false. No good idea. Set to true lowers:

Incoming MQTT to 1.32/sec
Load Task Settings to 3.9/sec
TryOpenFile to 5.61/sec

Better?

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#27 Post by TD-er » 21 Nov 2022, 16:33

For sure more manageble.
However it still bothers me to see so many calls to LoadTaskSettings.
Those should be next to 0, unless you're writing to some files which clears the cache.
On ESP8266 this is different, as we simply haven't got as much memory available for caching.

So have to check the code for this.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#28 Post by Wiki » 22 Nov 2022, 12:31

Hi,
I think I can reproduce the behaviour of timeshift between sent and received data. Yesterday in the evening I realized that I have to disable the setting "Prevent Loop" in the MQTT client gateway of Domoticz because otherwise publishing the "command":"switchlight" for Domoticz to switch on/off whatever doesn't work. Overnight everything was fine, sync perfectly.

Until: In the device we are talking about here I have one task with four values subscribed to domoticz/in with JSON parsing/filter on idx. Yesterday I disabled the task. I just tried to reenable the task today morning. At the moment I enable the task the timeshift tooks place. Instantly there is a shift of aroung 5-9 secs. I suppose it will increase. Disabling the task results instantly in almost perfect sync between sent/received data, max. shift of 1 sec. For this scenario I monitored the MQTT Import with JSON Filter in second level "SML.Watt" as described in this thread.

MQTT receives stay at aroung 4.5/sec, LoadTaskSettings around 14/sec as documented before.

Summarized what left from my different tries:

- disabling persistance in mosquitto.conf
- enabling "Clean Session" in Domoticz MQTT controller
- disabling the subscription to domoticz/in

And yes, as I have learned now, I have a pretty high MQTT traffic in my network. E.g. Ahoy publishes every 5 secs 43 values in seperated topics, my Tasmota (20) devices are publishing every 60 secs except the Volkszähler (every 10 secs) which are duplicated by Domoticz with disabled "Prevent Loop", my ESPEasies (10) are publishing various data in 15-60 secs interval, duplicated by Domoticz, too.

Hope, this helps.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#29 Post by TD-er » 22 Nov 2022, 12:59

Yesterday Ton already removed an unneeded call to LoadTaskSettings().
So on the next build it should already perform better.
You can test it here: https://github.com/letscontrolit/ESPEas ... 3517744710

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#30 Post by Wiki » 22 Nov 2022, 17:50

First quick checK:

No timeshift anymore, perfectly synchronious send/receive, even with enabled domoticz/in subscription!
Way better performance of Web GUI
Almost no hesitation in publishing data for Domoticz (before it took at least two seconds before the data appeared in Web frontend from Domoticz)
MQTT receive down to 1.3/sec
LoadTaskSettings down to 5.3/sec

The real check will come tomorrow, when sun is shining and Ahoy is publishing.

Thank you guys, feels good, well done

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#31 Post by Wiki » 22 Nov 2022, 17:55

[OT On]
System Info / System Status Web Log Level shows "None"
This is incorrect, I've set it to "Error"
[/OT Off]

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#32 Post by TD-er » 22 Nov 2022, 18:25

Wiki wrote: 22 Nov 2022, 17:55 [OT On]
System Info / System Status Web Log Level shows "None"
This is incorrect, I've set it to "Error"
[/OT Off]
Web log level is dynamic and is based on whether you fetch the logs.
So the shown log level is the actual log level.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#33 Post by Wiki » 23 Nov 2022, 10:42

Overnight I left the task with four subscriptions to domoticz/in on. Now with sunlight and Ahoy publishing its 43 values every 5 secs as well as the four domoticz/in values published (from my Raspberry, its a relict from my first tries to get the project run) there was a timeshift of around 9 secs visible.

The TimingStats of around 14h told me a LoadTaskSettings of 9.2/sec., MQTT receive of 2.3/sec. Refreshing TimingStats and having a look on the stats after 15 minutes it tells me a LoadTaskSettings of 11.88, a MQTT receive of around 4/sec

Disabling the task with the four domoticz/in subsribed topics results - again - in an almost perfect sync of sent/received.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#34 Post by Wiki » 23 Nov 2022, 10:50

TD-er wrote: 22 Nov 2022, 18:25 Web log level is dynamic and is based on whether you fetch the logs.
So the shown log level is the actual log level.
That's cool, never stop learning

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#35 Post by TD-er » 23 Nov 2022, 11:18

Wiki wrote: 23 Nov 2022, 10:50 [...] never stop learning
I won't :)

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#36 Post by Wiki » 23 Nov 2022, 11:35

Additional information:

I've changed the task with the four subscriptions to domoticz/in to import the data directly from source, Resp. I've changed the import from JSON parsing&filtering to lean MQTT Import without any options. At this moment the LoadTaskSettings raise from 12/sec to >20/sec.

For doublecheck I disabled this task and a another one with four subscription without any options and the LoadTaskSettings decreased from 12/sec to 7/sec.

Third check: I do have a "mixed" MQTT Import task, which contains two MQTT subscriptions without options (lean MQTT topics) and two subscriptions to domoticz/out with JSON parsing&filtering which I disabled. The LoadTaskSettings decreased to 0.01/sec (!).

Summarized: for me it looks like that the LoadTaskSettings calls are located in the code section for importing lean MQTT topics due to the fact, that the task with four subscriptions to domoticz/in with JSON parsing&filtering didn't affect the LoadTaskSettings, neither the remaing task with pure JSON parsing&filtering does, but every task with direct import of MQTT topi does.
Last edited by Wiki on 23 Nov 2022, 11:37, edited 1 time in total.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#37 Post by Wiki » 23 Nov 2022, 11:36

TD-er wrote: 23 Nov 2022, 11:18
Wiki wrote: 23 Nov 2022, 10:50 [...] never stop learning
I won't :)
so do I :D

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#38 Post by TD-er » 23 Nov 2022, 12:39

I took a quick look at the code and found this one:
https://github.com/letscontrolit/ESPEas ... 2.cpp#L183

I think this is the culprit for all those calls to LoadTaskSettings().

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#39 Post by TD-er » 23 Nov 2022, 13:25

Just another question.
Do you also use a formula in one of your tasks?

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#40 Post by Wiki » 23 Nov 2022, 13:37

No, no formulas.

Vales are processed in my rules if necessary.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#41 Post by TD-er » 23 Nov 2022, 14:12

Are you using a dallas sensor?

I'm now looking into all corners of the software where there may be use of ExtraTaskSettings.
The Dallas code does seem to use it for fetching stored 1Wire sensor addresses.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#42 Post by Wiki » 23 Nov 2022, 14:42

No. This device is using 4 tasks MQTT Import and 2 tasks Dummy. No further tasks or sensors.

In rules dependig on a five-seconds-event I am publishing seven values to Domoticz, depending on a ten-seconds-event three values to Domoticz (both are triggered by MQTT Import events, 3-4 calculations processed using %v1%&%v2%), every minute one SendToHttp.

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#43 Post by Wiki » 23 Nov 2022, 14:51

If you need some beta testing I would be pleased if I could do this for you. My project is not yet time critical, I can play around as much as I want. Hardware is till close to my laptop, nothing I couldn't influence manually. Time is no question currently. Open for any stupidity ;-).

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#44 Post by Wiki » 23 Nov 2022, 14:59

And btw.: using ESP32_normal_4M316k

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#45 Post by TD-er » 23 Nov 2022, 15:45

Lots of opportunities from my side to let you test stupid code.
https://www.dropbox.com/s/90bbvgr6v99b5 ... y.zip?dl=0
State of the code: It compiles (not yet tested)

I did add some more caching to reduce the number of calls to LoadTaskSettings().

I noticed there still one of those in the parse function to process strings so you can try to replace variables.
Given what you just wrote, I guess that call may still be affecting performance.

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#46 Post by TD-er » 23 Nov 2022, 16:16

This one should address those issues too: https://www.dropbox.com/s/8nyp6on9a3ihb ... 9.zip?dl=0
I found a few calls to MQTT import related code where the LoadTaskSettings() is being called where it isn't needed.

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#47 Post by Wiki » 23 Nov 2022, 16:46

I'll report.....

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#48 Post by Wiki » 23 Nov 2022, 16:49

....tomorrow, due to lack of sun I don't get any messages more to receive.....

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: MQTT Import time lack

#49 Post by TD-er » 23 Nov 2022, 16:49

OK, then you will probably have an even newer build to test :)

Wiki
Normal user
Posts: 413
Joined: 23 Apr 2018, 17:55
Location: Germany

Re: MQTT Import time lack

#50 Post by Wiki » 23 Nov 2022, 17:22

I flashed the second one you've posted.

Hey man, you are kidding me. First of all I had a look at the sent/received sync. ESPEasy now is looking into the future, receive is logged one second before the time the timestamp of the Volkszähler topics show. Pretty fast, I think :mrgreen:

And in the Timing Stats LoadTaskSettings even doesn't appear. Be honest: You've took it out of the statistic list, right?

Seriously:

There seems to be a small timeshift on the Tasmota device. First time I've noticed that, up to now ESPEasy was constantly similar or in the past.

Starting the Timing Stats page for the first time LoadTaskSettings appeared with somewhat like 0.2/sec. If now I want to have an entry there I have to open the Task Settings manually. TryOpenFile shows constantly 0.3/sec.

Seems as if you've put the finger right into the wound.

Looking forward to future testing, sincerely......

Code: Select all

pi@raspberrypi:~ $ man woman
No manual entry for woman
pi@raspberrypi:~ $

Post Reply

Who is online

Users browsing this forum: No registered users and 32 guests