Voltage measurement and low heap

Simsala · August 12, 2018, 8:24pm

Unfortunately, I have had errors in the voltage measurement since version 02_03_12. It shows a mass of supposed voltage drops, which, however, are not visible in comparison systems.

The update to this version was done on 9.8.2018:

SD initialized.
8/09/18 13:48:51z Real Time Clock is running. Unix time 1533822531 
8/09/18 13:48:51z Version 02_03_12
8/09/18 13:48:51z Updater: Installing update files for version 02_03_12
8/09/18 13:48:51z Updater: Installing GRAPH.JS
8/09/18 13:48:51z Updater: Installing INDEX.HTM
8/09/18 13:48:52z Updater: Installing TABLES.TXT
8/09/18 13:48:52z Updater: Installing CNFSTYLE.CSS
8/09/18 13:48:52z Updater: Installing EDIT.HTM
8/09/18 13:48:52z Updater: Installing GRAPH.HTM
8/09/18 13:48:53z Updater: Installation complete.
8/09/18 13:48:53z Reset reason: Software/System restart
8/09/18 13:48:53z Trace:  1:2, 1:2[4], 1:3, 1:4, 1:5[19], 1:6, 1:1[4], 9:0, 9:1, 8:4, 8:6, 8:8, 9:3, 9:4, 9:5, 9:9, 1:2, 1:2, 1:3, 1:4, 1:5[19], 1:6, 1:1, 9:0, 8:4, 8:6, 8:8, 1:2, 1:2[1], 1:3, 1:4, 1:5[5]
8/09/18 13:48:53z ESP8266 ChipID: 7283597
8/09/18 13:48:53z Local time zone: 0
8/09/18 13:48:53z device name: IotaWatt, version: 3
8/09/18 13:48:55z MDNS responder started
8/09/18 13:48:55z You can now connect to http://IotaWatt.local
8/09/18 13:48:55z HTTP server started
8/09/18 13:48:55z dataLog: service started.
8/09/18 13:48:56z dataLog: Last log entry 8/9/18 13:48:25 
8/09/18 13:48:56z statService: started.
8/09/18 13:48:56z timeSync: service started.
8/09/18 13:48:56z WiFi connected. SSID: rexoweb, IP: 192.168.11.117
8/09/18 13:48:56z Updater: service started. Auto-update class is ALPHA
8/09/18 13:48:56z historyLog: service started.
8/09/18 13:48:56z historyLog: Last log entry 8/9/18 13:48:00 
8/09/18 13:48:56z timeSync: adjusting RTC by -2
8/09/18 13:48:58z Updater: Auto-update is current for class ALPHA.
8/09/18 13:49:00z EmonService: started. url:my.rexometer.de:80,node:IotaWatt,interval:10, encrypted POST
8/09/18 13:49:01z EmonService: Start posting at 8/9/18 13:48:00

Exactly at this time (local time approx. 16:00 o’clock) the problems begin:

Furthermore, I have reboots due to low heap, I haven’t had that yet. Usually the heap was in the range of 25000, currently at about 12000 and no values are sent to emoncms. Update: As I write this another low heap message came up and there was a reboot and values are sent again.

SD initialized.
8/09/18 20:23:43z Real Time Clock is running. Unix time 1533846223 
8/09/18 20:23:43z Power failure detected.
8/09/18 20:23:43z Version 02_03_12
8/09/18 20:23:43z Reset reason: External System
8/09/18 20:23:43z Trace:  99:0[233], 57:157[249], 92:46[203], 143:119[223], 235:173[198], 215:106[127], 158:3[236], 3:128[223], 202:116[250], 192:168[34], 249:73[162], 168:236[191], 199:251[2], 151:78[45], 251:88[30], 214:108[124], 229:43[4], 207:147[250], 237:202[150], 177:163[12], 100:217[86], 165:93[125], 237:123[50], 218:183[177], 31:162[147], 145:227[237], 222:33[38], 252:65[252], 243:144[59], 100:182[99], 169:191[169], 192:174[73]
8/09/18 20:23:43z ESP8266 ChipID: 7283597
8/09/18 20:23:43z Local time zone: 0
8/09/18 20:23:43z device name: IotaWatt, version: 3
8/09/18 20:23:46z Connecting with WiFiManager.
8/09/18 20:23:51z MDNS responder started
8/09/18 20:23:51z You can now connect to http://IotaWatt.local
8/09/18 20:23:51z HTTP server started
8/09/18 20:23:51z dataLog: service started.
8/09/18 20:23:51z dataLog: Last log entry 8/9/18 20:23:25 
8/09/18 20:23:52z statService: started.
8/09/18 20:23:52z timeSync: service started.
8/09/18 20:23:52z WiFi connected. SSID: rexoweb, IP: 192.168.11.117
8/09/18 20:23:52z Updater: service started. Auto-update class is ALPHA
8/09/18 20:23:52z historyLog: service started.
8/09/18 20:23:52z historyLog: Last log entry 8/9/18 20:23:00 
8/09/18 20:23:55z Updater: Auto-update is current for class ALPHA.
8/09/18 20:23:56z EmonService: started. url:my.rexometer.de:80,node:IotaWatt,interval:10, encrypted POST
8/09/18 20:23:57z EmonService: Start posting at 8/9/18 20:23:10 
8/12/18 06:22:08z Heap memory has degraded below safe minimum, restarting.

** Restart **

SD initialized.
8/12/18 06:22:10z Real Time Clock is running. Unix time 1534054930 
8/12/18 06:22:10z Version 02_03_12
8/12/18 06:22:10z Reset reason: Software/System restart
8/12/18 06:22:10z Trace:  18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:4, 18:5, 1:6, 1:3, 1:4, 1:5[21]
8/12/18 06:22:10z ESP8266 ChipID: 7283597
8/12/18 06:22:10z Local time zone: 0
8/12/18 06:22:10z device name: IotaWatt, version: 3
8/12/18 06:22:11z MDNS responder started
8/12/18 06:22:11z You can now connect to http://IotaWatt.local
8/12/18 06:22:11z HTTP server started
8/12/18 06:22:11z dataLog: service started.
8/12/18 06:22:12z dataLog: Last log entry 8/12/18 06:22:05 
8/12/18 06:22:12z statService: started.
8/12/18 06:22:12z timeSync: service started.
8/12/18 06:22:12z WiFi connected. SSID: rexoweb, IP: 192.168.11.117
8/12/18 06:22:12z Updater: service started. Auto-update class is ALPHA
8/12/18 06:22:12z historyLog: service started.
8/12/18 06:22:12z historyLog: Last log entry 8/12/18 06:22:00 
8/12/18 06:22:14z Updater: Auto-update is current for class ALPHA.
8/12/18 06:22:16z EmonService: started. url:my.rexometer.de:80,node:IotaWatt,interval:10, encrypted POST
8/12/18 06:22:17z EmonService: Start posting at 8/12/18 06:21:40 
8/12/18 20:03:50z Heap memory has degraded below safe minimum, restarting.

** Restart **

SD initialized.
8/12/18 20:03:52z Real Time Clock is running. Unix time 1534104232 
8/12/18 20:03:52z Version 02_03_12
8/12/18 20:03:52z Reset reason: Software/System restart
8/12/18 20:03:52z Trace:  18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:4, 18:5, 1:6, 1:3, 1:4, 1:5[21]
8/12/18 20:03:52z ESP8266 ChipID: 7283597
8/12/18 20:03:52z Local time zone: 0
8/12/18 20:03:52z device name: IotaWatt, version: 3
8/12/18 20:03:55z Connecting with WiFiManager.
8/12/18 20:04:00z MDNS responder started
8/12/18 20:04:00z You can now connect to http://IotaWatt.local
8/12/18 20:04:00z HTTP server started
8/12/18 20:04:00z dataLog: service started.
8/12/18 20:04:00z dataLog: Last log entry 8/12/18 20:03:45 
8/12/18 20:04:01z statService: started.
8/12/18 20:04:01z timeSync: service started.
8/12/18 20:04:01z WiFi connected. SSID: rexoweb, IP: 192.168.11.117
8/12/18 20:04:01z Updater: service started. Auto-update class is ALPHA
8/12/18 20:04:01z historyLog: service started.
8/12/18 20:04:01z historyLog: Last log entry 8/12/18 20:03:00 
8/12/18 20:04:03z Updater: Auto-update is current for class ALPHA.
8/12/18 20:04:05z EmonService: started. url:my.rexometer.de:80,node:IotaWatt,interval:10, encrypted POST
8/12/18 20:04:06z EmonService: Start posting at 8/12/18 18:59:20

Strangeness with voltage measurement and low heap seem to be connected:

The reboot was at 22:04 local time (20:04 UTC)

overeasy · August 12, 2018, 9:18pm

Thanks for posting this promptly. I was beginning to have confidence in this new release. I’ve taken a cursory look at it and will spend some time this evening trying to figure out what’s going on. It has been in the field for three days now, and this is the first serious report I’ve had.

There are some changes to the voltage sampling error detection and recovery code in this release that were made to deal with another user that was having “hanging” problems as his unit looped for very long periods trying to get viable samples.

It’s curious why it only happens on some systems and only at select times. I can’t see how the sampling routines could be at fault - they have been relatively unaltered for months. I believe it is related to interrupts happening at very low levels due to communications issues. The symptoms seem to be on WiFi stressed units. Is this the unit with WiFi issues?

Right now my suspicion is that low level IP issues are interrupting the sampling routines and causing them to retry to get viable sample sets. At the same time, the new LwIP2 may be eating up heap during this activity. I’ll delve into this further to try and make sense of it.

The good news is that these voltage measurements are not used in the power calculations. I’m curious if you see any impact on power calculations during these periods.

The changes to time update are working but I’ve also found some problems with more frequent correction swings of several seconds. I’ve been working on that as well. I’m learning that I can’t fix everything without tripping up on the law of unintended consequences. Thanks for doing this ALPHA work, it is helping immensely.

I’ll take a different approach to the poor voltage sampling and not report zero. Better to just fall back on the voltage measurements taken during power sampling which I was doing until a few months ago.

Simsala · August 13, 2018, 6:42am

No, this is not the unit with the WiFi issues. It is installed at my home and showed no problems before.

The power calculation seems to be only slightly affected by it.

The axis on the lefthand side shows voltage and on the right side power.