Community
OpenEnergyMonitor

Community

Emonhub lag


(Bruce) #1

Hi all,

Sorry to bang the drum again but I’m really puzzled here. emoncms is showing the correct data but with a lag of about two minutes. I’m sitting here watching my DNO meter blinking away like crazy while my kettle is boiling and emoncms’ mysolarpv app says I’m using 42W! ~Two minutes later I’m pouring the milk and apparently I’m using 2104W…

Looking in emonhub’s log file, the data arrives at the right time and it claims it is being published ToEmonCMS at the right time, but it doesn’t show up.

I’ve tried redis-cli flushall. Where else should I be looking?

Thanks,
Bruce


(Paul) #2

I doubt the delay is in emonhub, it’s most likely a delay between the broker and emoncms. Where are you seeing the delays other than in the apps? Have you checked the inputs page? are all the update times green and in single digits?

You could try subscribing to the emon topic via the command-line if you ssh in to the Pi, this should show the data immediately after emonhub publishes it.

mosquitto_sub -v -u 'emonpi' -P 'emonpimqtt2016' -t 'emon/#'

If the inputs page is all green and there is still a delay to the apps module, it might be the buffered-write if you are using an emonSD/emonPi, try looking at a “realtime” visualisation via the emoncms extra -> visualisation -> realtime menu’s.


(Bruce) #3

Hi Paul

Thanks for your reply. All the inputs and feeds are green, the times are always under 10s, but the data are wrong.

The realtime vis shows a similar lag. Is it normal for it to display nothing if you click “5 min” or “1 min”?

Jul 04 00:07:04 emonpi emonhub.py[16549]: 2018-07-04 00:07:04,954 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 24 18 16 42 106 96 32 40 32 48 4 24 64 83 15 224 33 0 0 9 32 (-93)
Jul 04 00:07:05 emonpi emonhub.py[16549]: 2018-07-04 00:07:05,066 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 20 22 168 48 9 32 32 64 4 2 100 24 64 83 15 224 33 0 0 9 32 (-99)
Jul 04 00:07:05 emonpi emonhub.py[16549]: 2018-07-04 00:07:05,174 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 0 29 64 128 13 70 1 125 3 148 192 130 73 14 0 68 192 26 136 2 80 (-92)
Jul 04 00:07:08 emonpi emonhub.py[16549]: 2018-07-04 00:07:08,208 DEBUG    RFM2Pi     650 NEW FRAME : OK 5 120 0 0 0 120 0 180 92 196 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 (-0)
Jul 04 00:07:08 emonpi emonhub.py[16549]: 2018-07-04 00:07:08,216 DEBUG    RFM2Pi     650 Timestamp : 1530659228.21
Jul 04 00:07:08 emonpi emonhub.py[16549]: 2018-07-04 00:07:08,220 DEBUG    RFM2Pi     650 From Node : 5
Jul 04 00:07:08 emonpi emonhub.py[16549]: 2018-07-04 00:07:08,224 DEBUG    RFM2Pi     650    Values : [120, 0, 120, 237.32, 19.6, 0, 0, 0, 0, 0, 0]
Jul 04 00:07:08 emonpi emonhub.py[16549]: 2018-07-04 00:07:08,228 DEBUG    RFM2Pi     650 Sent to channel(start)' : ToEmonCMS
Jul 04 00:07:08 emonpi emonhub.py[16549]: 2018-07-04 00:07:08,231 DEBUG    RFM2Pi     650 Sent to channel(end)' : ToEmonCMS
Jul 04 00:07:08 emonpi emonhub.py[16549]: 2018-07-04 00:07:08,344 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 29 85 162 80 64 16 35 229 0 53 161 192 64 106 235 83 38 190 240 30 121 (-93)
Jul 04 00:07:09 emonpi emonhub.py[16549]: 2018-07-04 00:07:09,057 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 16 13 0 96 8 27 0 162 14 0 0 32 6 106 235 83 38 190 240 30 121 (-91)
Jul 04 00:07:09 emonpi emonhub.py[16549]: 2018-07-04 00:07:09,168 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 10 224 56 64 19 231 98 165 224 169 250 32 193 166 1 64 2 8 98 200 0 (-94)
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,344 DEBUG    MQTT       Publishing: emon/emonpi/power1 66
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,350 DEBUG    MQTT       Publishing: emon/emonpi/power2 0
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,355 DEBUG    MQTT       Publishing: emon/emonpi/power1pluspower2 66
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,357 DEBUG    MQTT       Publishing: emon/emonpi/vrms 234.62
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,359 DEBUG    MQTT       Publishing: emon/emonpi/t1 19.6
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,362 DEBUG    MQTT       Publishing: emon/emonpi/t2 0
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,365 DEBUG    MQTT       Publishing: emon/emonpi/t3 0
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,368 DEBUG    MQTT       Publishing: emon/emonpi/t4 0
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,370 DEBUG    MQTT       Publishing: emon/emonpi/t5 0
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,372 DEBUG    MQTT       Publishing: emon/emonpi/t6 0
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,377 DEBUG    MQTT       Publishing: emon/emonpi/pulsecount 0
Jul 04 00:07:12 emonpi emonhub.py[16549]: 2018-07-04 00:07:12,379 INFO     MQTT       Publishing: emonhub/rx/5/values 66,0,66,234.62,19.6,0,0,0,0,0,0
Jul 04 00:07:13 emonpi emonhub.py[16549]: 2018-07-04 00:07:13,197 DEBUG    RFM2Pi     651 NEW FRAME : OK 5 121 0 0 0 121 0 167 92 196 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 (-0)
Jul 04 00:07:13 emonpi emonhub.py[16549]: 2018-07-04 00:07:13,202 DEBUG    RFM2Pi     651 Timestamp : 1530659233.2
Jul 04 00:07:13 emonpi emonhub.py[16549]: 2018-07-04 00:07:13,203 DEBUG    RFM2Pi     651 From Node : 5
Jul 04 00:07:13 emonpi emonhub.py[16549]: 2018-07-04 00:07:13,204 DEBUG    RFM2Pi     651    Values : [121, 0, 121, 237.19, 19.6, 0, 0, 0, 0, 0, 0]
Jul 04 00:07:13 emonpi emonhub.py[16549]: 2018-07-04 00:07:13,205 DEBUG    RFM2Pi     651 Sent to channel(start)' : ToEmonCMS
Jul 04 00:07:13 emonpi emonhub.py[16549]: 2018-07-04 00:07:13,205 DEBUG    RFM2Pi     651 Sent to channel(end)' : ToEmonCMS

I cannot begin to imagine why emonhub is logging a frame where the first value is 120 and then it publishes to MQTT the value 66!

Bruce


(Greebo) #4

Can you add more log to your post? when do those values from here:

Jul 04 00:07:08 emonpi emonhub.py[16549]: 2018-07-04 00:07:08,224 DEBUG    RFM2Pi     650    Values : [120, 0, 120, 237.32, 19.6, 0, 0, 0, 0, 0, 0]

get published?


(Bruce) #5

I might have found the answer.

Previously, emonhub.py had a tight loop which was simply checking the state of the interfacer threads. It had a short sleep (0.2s) at the end which meant that emonhub consumed lots of CPU time simply checking whether the config file had been edited. I changed the sleep to 60s and everything was tickety-boo. It looks like the loop has been changed to also be a “native message queue implementation” and changing the sleep back to 0.2s makes the apps keep up with the logged frames again.

Unfortunately emonhub now consumes 20-30% of the CPU on my Pi again.

Can anyone explain why this change was made? I can’t immediately see why there needs to be a thread shuffling the data around which couldn’t be solved just by adding some locks. I’d be happy to do the work necessary to do this if someone can explain this new requirement.

Thanks for your time helping me to solve this specific issue and thanks to all of you for your hard work creating this system :slight_smile: