emonHub publishing values takes time?

emonHub
1

Hi all,
I have been investigating missing readings from my 4x emonTH (25% to 29% missing) and I can see from the emonHub log that at the specific time when these readings would have been submitted, prior/subsequent entries such as these:

2022-04-18 13:08:39,402 DEBUG    MQTT       Publishing: emonhub/rx/5/values 116,35,151,230,32.1,28.700000000000003,36,30.8,26.200000000000003,65.2,810
2022-04-18 13:08:44,311 DEBUG    RFM2Pi     719025 NEW FRAME : OK 5 118 0 35 0 153 0 216 89 65 1 31 1 104 1 52 1 6 1 140 2 42 3 0 0 (-0)
…
2022-04-18 13:14:51,017 DEBUG    MQTT       Publishing: emonhub/rx/26/values 20.5,20.200000000000003,57.900000000000006,2.5,1,-73
2022-04-18 13:14:54,487 DEBUG    RFM2Pi     719161 NEW FRAME : OK 5 118 0 39 0 157 0 216 89 65 1 30 1 105 1 47 1 5 1 140 2 42 3 0 0 (-0)
…
2022-04-18 13:21:01,412 DEBUG    MQTT       Publishing: emonhub/rx/16/values 161014,250.13,-3089,1619,2431,4,104776,255680,400881,28959,19.75,300,300,67,-65
2022-04-18 13:21:04,602 DEBUG    RFM2Pi     719312 NEW FRAME : OK 5 115 0 36 0 151 0 216 89 64 1 29 1 105 1 42 1 3 1 139 2 43 3 0 0 (-0)
…
2022-04-18 13:36:24,982 DEBUG    MQTT       Publishing: emonhub/rx/5/values 116,40,156,230,32,28.3,36.1,28.700000000000003,25.6,65.3,811
2022-04-18 13:36:27,500 DEBUG    RFM2Pi     719664 NEW FRAME : OK 26 205 0 201 0 68 2 25 0 1 0 0 0 (-73)

In each of the above instances, the submission from an emonTH was due after “Publishing:” and before “NEW FRAME”. I can see that it’s not always the same node in either the before or after messages.
Usually, very little time elapses after that final “Publishing:” message in a sequence however it seems that every 6-7 minutes, it takes longer. I wonder if emonHub is allocating more storage or doing a cleanup task?
Spacewise:
/var/opt/emoncms Used: 7.12% Total 9.84 GB Used 717.52 MB Free 8.64 GB

Also, I don’t think it’s anything to do with those occasional readings like 28.700000000000003 as there’s an entry above where it’s not a factor.

I’m on emonHub 11.0.5 but this has been happening for much longer.
I have 1x emonPi (emonpiRelease emonSD-24Jul20), 2x emonTx and 4x emonTH (all from the shop!).

Any ideas?

2

I think there is a strong possibility of RF clashes (@Robert.Wall) and this has been reported elsewhere with TXs.

When you do get a reading from he missing one, is the timestamp close to another device reporting?

3

Hi Brian, thanks for the response.
I had already tried restarting each of the emonTH at 0, 15, 30 & 45 seconds past each minute in case of clashes.
I’ll have a look at the log extracts and see where the emonTx’s are due to post in the grand scheme of things.

4

Quite a lot of devices so clashes are a real possibility especially if one of the TH signal is a bit weak, it will get blatted (tech term).

5

Certainly, having a number of emonTx’s significantly increases the probability of a clash. The emonTx is sending 24 bytes which, together with the overhead, takes approximately 5.4 ms (every 10 s) and an emonTH V2 sends 12 bytes, so 3.4 ms (every 55 s).

It’s possible, if your emonTx’s are mains powered, to have a sketch that “sniffs” the air for an ongoing transmission, this is also possible in the emonTH but impractical, because it will significantly reduce the battery life (I estimate by around 60%). For it to be effective requires each node to be able to hear each other. Even so, if two nodes are exactly in sync, they will never hear each other whilst themselves transmitting, so it helps, but it’s not infallible.

6

Thank both for the above, however I found the data in my original posts very easily by looking at what time a TH was due to report and each one was in a 3-5 second gap in the debug message between an MQTT publish and NEW FRAME of some other node.

There should have been capacity in each of these gaps to receive the TH message so I’m thinking the MQTT post is taking longer on these occasions.

I saw in Learn that the block size is 1kb for longevity so I’m wondering if my 94 feeds are causing this by needing constant file extension. Some of the feeds & input processing are not strictly necessary but I’d rather keep them if they are not the issue.

My Tx’s are powered by AC/AC and one of my TH’s is powered by 5v as it has 5 DS18B20s attached. This is in the same room as the emonPi about 2m with clear line of sight with the best RSSI of the lot (-33) and has 25% missing reads.

7

With 5 temperatures of 2 bytes each in the message, that one will take longer to send its data.
So that you can work it out, the overhead in the transmission is 9 bytes. Look at emonhub.conf for the node you’re interested in, and the “datacodes” line. h = 2 bytes, L or l = 4 bytes. Add those up. The data rate is 49200 bits/s, or 162.6 µs per byte.

If the hang-up is after the message has been received, then I don’t know enough of the finer details of that area to be able to help you.

8

Okay I have established where readings are missing, clearly I need to look at a smaller time frame.
Missing readings in orange, successful in blue. emonPi is node 5, Tx are 10 & 16, TH are 23-26. All the TH have slightly different actual reporting cycles from 59 to 63 seconds.

Combined chart all data
Combined chart all data1932×1216 178 KB

Time to take the dogs for a much-needed walk, will have a think while I’m out!

9

That might be your problem. Think of the emonCMS FINA Feed as a line of boxes moving along a conveyor. If there’s a box going past every 60 s but data falls onto the conveyor every 65 s, every so often a box will move on empty, with no data in it. You need to tweak the timing of any emonTH sending outside the minute frame to be inside. If there’s already data in the box and it hasn’t moved on, it will overlay the data already in there, which is lost. But you won’t have null values in the Feed.

The same applies to any Feed and any timebase - and the boxes move on the Internet minute, or multiples or sub-multiples thereof. (i.e., a 10 s feed happens on the minute and at 10, 20 etc seconds past.

If I remember correctly, the timing is governed by the delay between taking, processing and transmitting one set of readings and starting the next, not the interval between successive starts of the process. If you’ve extended that process by adding sensors, that’s probably where it’s gone wrong.

10

Possibly especially if you send each sensor as a separate topic to be published. If you use the JSON format, all the values from one device go as a single publish so is much quicker.

11

I think it’s doing what you say but not a la JSON.

Here’s an example of the debug for one set of data from my node 10 Tx:

2022-04-22 21:27:22,031 DEBUG    RFM2Pi     867318 NEW FRAME : OK 10 0 0 0 0 0 0 33 253 232 98 153 0 (-69)
2022-04-22 21:27:22,033 DEBUG    RFM2Pi     867318 Timestamp : 1650659242.031057
2022-04-22 21:27:22,033 DEBUG    RFM2Pi     867318 From Node : 10
2022-04-22 21:27:22,034 DEBUG    RFM2Pi     867318    Values : [0, 0, 0, -735, 253.20000000000002, 15.3]
2022-04-22 21:27:22,035 DEBUG    RFM2Pi     867318      RSSI : -69
2022-04-22 21:27:22,035 DEBUG    RFM2Pi     867318 Sent to channel(start)' : ToEmonCMS
2022-04-22 21:27:22,036 DEBUG    RFM2Pi     867318 Sent to channel(end)' : ToEmonCMS
2022-04-22 21:27:22,152 DEBUG    MQTT       Publishing: emon/emontx1/power1 0
2022-04-22 21:27:22,153 DEBUG    MQTT       Publishing: emon/emontx1/power2 0
2022-04-22 21:27:22,155 DEBUG    MQTT       Publishing: emon/emontx1/power3 0
2022-04-22 21:27:22,156 DEBUG    MQTT       Publishing: emon/emontx1/power4 -735
2022-04-22 21:27:22,157 DEBUG    MQTT       Publishing: emon/emontx1/vrms 253.20000000000002
2022-04-22 21:27:22,159 DEBUG    MQTT       Publishing: emon/emontx1/temp1 15.3
2022-04-22 21:27:22,160 DEBUG    MQTT       Publishing: emon/emontx1/rssi -69
2022-04-22 21:27:22,161 INFO     MQTT       Publishing 'node' formatted msg
2022-04-22 21:27:22,162 DEBUG    MQTT       Publishing: emonhub/rx/10/values 0,0,0,-735,253.20000000000002,15.3,-69

My interpretation of the above is that all but the last line is receiving, parsing and preparing the data then in the last line it’s sending it all to MQTT.
This ‘emonhub/rx/node/values’ message I think usually takes around 0.2 seconds, but sometimes it seems that it ties the emonpi up for 3-5 seconds meaning it misses the incoming data I’m going on about.

12

Yes you need to change the emonhub to use JSON so it sends it all on one publish (helps at the other end as well).

I have seen the EmonCMS MQTT input get overloaded and lose messages. Are you sure the issue is with emonhub not receiving/sending and not EmonCMS dropping them?

Also the publishing to emonhub topic is redundant now (I’m pretty sure) as these messages are no longer picked up.

13

Having been a developer in my past, I have typically done the same as everyone else; learn as little as I need to do the priority task of the moment. So to date, I have kept everything in my emonCMS stack as vanilla as possible. Since retiring I have the time to read things properly and fix things because they’re wrong.

I have decided on an approach to deal with this; I’m going to do a fresh install of the latest build on a new SD card (I’ve got a couple of Kingston 64gb ones), import everything and see if it’s the same. There’s a couple of other things @Robert.Wall has suggested too.

I’ll post an update once done.

14

This is the minimal MQTT configuration I use where emonhub receives data (RFM, Serial or whatever) and sends it on to an MQTT Broker as a JSON string for Emoncms to pick up. Note you can have multiple MQTT sections to send data to multiple MQTT Brokers.

[[MQTT2]]
    Type = EmonHubMqttInterfacer
    [[[init_settings]]]
        mqtt_host = 192.168.7.50
        mqtt_port = 1883
        mqtt_user = xxxxx
        mqtt_passwd = xxxxx

    [[[runtimesettings]]]
        subchannels = ToEmonCMS,

        node_format_enable = 0
        nodevar_format_enable = 0
        node_JSON_enable = 1
        node_JSON_basetopic = emon/
15

I’ll give that a go, thanks!

1 Like