weewx version 4 can't keep up in time

[Lucas Heijst]

Tom,

For more than a year my weewx Modbus Energy Monitor driver/service (mben) runned without any problems.

The archive interval was set to 60 seconds and the report interval was set to 5 minutes.

Configuration: raspberry PI 3B+, raspbian stretch, weewx 3.9.1, python 2.

After I upgraded to weewx 4.0.0b16 with python 3 mben  can't run on time anymore.

In an earlier message I already mentioned the numerous debug log messages the modbus section produced with 'logging'..

These messages were suppressed in a way you suggested.

The 4.0.0b16 logging below show that mben can't keep up in time even when the archive period is set to 300 seconds.

The last log message says:

Mar 25 07:08:00 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:45:00 -03 (1585129500) to database 'weewx_mben31'

So in one hour the program is already 23 minutes behind.

The only difference in the mben code is the logging which was set to module logging instead of syslog for weewx 4.0.0b16.

I can't tell why mben is so much slower in 4.0.0b16. Maybe the logging, maybe something else.

I went back today to weewx 3.9.2, python 2 and 60 s archive interval and syslog debug messages (instead of logging) and everything is back to normal.

I know, you are not familiar with my mben driver/service and the pymodbus package and also I don't expect a solution. 

This message is for your information only.

Luc

====

Mar 25 06:07:01 pi31 mben[484] INFO __main__: Starting up weewx version 4.0.0b16

Mar 25 06:07:01 pi31 mben[484] INFO weewx.engine: Clock error is -0.16 seconds (positive is fast)

Mar 25 06:07:01 pi31 mben[484] INFO weewx.engine: Using binding 'wx_binding' to database 'weewx_mben31'

Mar 25 06:07:01 pi31 mben[484] INFO weewx.manager: Starting backfill of daily summaries

Mar 25 06:07:01 pi31 mben[484] INFO weewx.engine: Starting main packet loop.

Mar 25 06:07:02 pi31 cmon[485] INFO weewx.manager: Processed 142 records to backfill 1 day summaries in 0.35 seconds

Mar 25 06:07:02 pi31 cmon[485] INFO weewx.engine: Starting main packet loop.

Mar 25 06:07:02 pi31 cmon[485] DEBUG weewx.wxservices: DatabaseError '(1054, "Unknown column 'rain' in 'field list'")'

Mar 25 06:08:01 pi31 CRON[823]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:08:03 pi31 mben[484] INFO user.modbusenergy: PTot: 395.4 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.5 kWh

Mar 25 06:09:01 pi31 CRON[959]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:09:02 pi31 mben[484] INFO user.modbusenergy: PTot: 396.0 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.5 kWh

Mar 25 06:10:01 pi31 CRON[1103]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:10:02 pi31 mben[484] INFO user.modbusenergy: PTot: 396.1 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.5 kWh

Mar 25 06:10:23 pi31 cmon[485] INFO weewx.manager: Added record 2020-03-25 06:10:00 -03 (1585127400) to database 'cmon31'

Mar 25 06:10:23 pi31 cmon[485] INFO weewx.manager: Added record 2020-03-25 06:10:00 -03 (1585127400) to daily summary in 'cmon31'

Mar 25 06:10:23 pi31 cmon[485] DEBUG weewx.reportengine: Running reports for latest time in the database.

Mar 25 06:10:23 pi31 cmon[485] DEBUG weewx.reportengine: Running report 'cmon31'

Mar 25 06:10:23 pi31 cmon[485] DEBUG weewx.reportengine: Found configuration file /home/weewx/skins/cmon31/skin.conf for report 'cmon31'

Mar 25 06:10:23 pi31 cmon[485] DEBUG weewx.cheetahgenerator: Using search list ['weewx.cheetahgenerator.Almanac', 'weewx.cheetahgenerator.Station', 'weewx.cheetahgenerator.Current', 'weewx.cheetahgenerator.Stats', 'weewx.cheetahgenerator.UnitInfo', 'weewx.cheetahgenerator.Extras']

Mar 25 06:10:23 pi31 cmon[485] DEBUG weewx.manager: Daily summary version is 2.0

Mar 25 06:10:24 pi31 cmon[485] INFO weewx.cheetahgenerator: Generated 1 files for report cmon31 in 0.24 seconds

Mar 25 06:10:24 pi31 cmon[485] DEBUG weewx.manager: Daily summary version is 2.0

Mar 25 06:10:30 pi31 cmon[485] INFO weewx.imagegenerator: Generated 5 images for report cmon31 in 6.10 seconds

Mar 25 06:10:30 pi31 cmon[485] DEBUG weewx.reportengine: Running report 'FTP'

Mar 25 06:10:30 pi31 cmon[485] DEBUG weewx.reportengine: Found configuration file /home/weewx/skins/Ftp/skin.conf for report 'FTP'

Mar 25 06:10:30 pi31 cmon[485] DEBUG weeutil.ftpupload: Attempting connection to ftp.lucdesign.nl

Mar 25 06:10:31 pi31 cmon[485] DEBUG weeutil.ftpupload: Connected to ftp.lucdesign.nl

Mar 25 06:10:38 pi31 cmon[485] DEBUG weeutil.ftpupload: Uploaded file /_weewx/webcam3_v.jpg

Mar 25 06:10:43 pi31 cmon[485] DEBUG weeutil.ftpupload: Uploaded file /_weewx/webcam3_l.jpg

Mar 25 06:10:45 pi31 cmon[485] INFO weewx.reportengine: ftpgenerator: Ftp'd 2 files in 14.65 seconds

Mar 25 06:10:45 pi31 cmon[485] DEBUG weewx.reportengine: Report 'RSYNC' not enabled. Skipping.

Mar 25 06:11:01 pi31 CRON[1235]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:11:01 pi31 mben[484] INFO user.modbusenergy: PTot: 397.9 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:11:58 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:10:00 -03 (1585127400) to database 'weewx_mben31'

Mar 25 06:11:58 pi31 systemd[1]: Starting Daily apt upgrade and clean activities...

Mar 25 06:11:58 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:10:00 -03 (1585127400) to daily summary in 'weewx_mben31'

Mar 25 06:11:59 pi31 mben[484] INFO weewx.cheetahgenerator: Generated 1 files for report mben31 in 0.49 seconds

Mar 25 06:12:00 pi31 systemd[1]: apt-daily-upgrade.service: Succeeded.

Mar 25 06:12:00 pi31 systemd[1]: Started Daily apt upgrade and clean activities.

Mar 25 06:12:01 pi31 CRON[1413]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:12:17 pi31 mben[484] INFO weewx.imagegenerator: Generated 88 images for report mben31 in 17.97 seconds

Mar 25 06:13:00 pi31 mben[484] INFO user.modbusenergy: PTot: 398.0 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:13:02 pi31 CRON[1533]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:13:59 pi31 mben[484] INFO user.modbusenergy: PTot: 398.0 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:14:01 pi31 CRON[1655]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:14:59 pi31 mben[484] INFO user.modbusenergy: PTot: 392.9 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:15:01 pi31 CRON[1791]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:15:11 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:15:11 -03 (1585127711) to database 'mbendevices31'

Mar 25 06:15:11 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:15:11 -03 (1585127711) to daily summary in 'mbendevices31'

Mar 25 06:15:24 pi31 cmon[485] INFO weewx.manager: Added record 2020-03-25 06:15:24 -03 (1585127724) to database 'cmon31'

Mar 25 06:15:24 pi31 cmon[485] INFO weewx.manager: Added record 2020-03-25 06:15:24 -03 (1585127724) to daily summary in 'cmon31'

Mar 25 06:15:24 pi31 cmon[485] INFO weewx.manager: Added record 2020-03-25 06:15:00 -03 (1585127700) to database 'cmon31'

Mar 25 06:15:25 pi31 cmon[485] INFO weewx.manager: Added record 2020-03-25 06:15:00 -03 (1585127700) to daily summary in 'cmon31'

Mar 25 06:15:25 pi31 cmon[485] DEBUG weewx.reportengine: Running reports for latest time in the database.

Mar 25 06:15:25 pi31 cmon[485] DEBUG weewx.reportengine: Running report 'cmon31'

Mar 25 06:15:25 pi31 cmon[485] DEBUG weewx.reportengine: Found configuration file /home/weewx/skins/cmon31/skin.conf for report 'cmon31'

Mar 25 06:15:25 pi31 cmon[485] DEBUG weewx.cheetahgenerator: Using search list ['weewx.cheetahgenerator.Almanac', 'weewx.cheetahgenerator.Station', 'weewx.cheetahgenerator.Current', 'weewx.cheetahgenerator.Stats', 'weewx.cheetahgenerator.UnitInfo', 'weewx.cheetahgenerator.Extras']

Mar 25 06:15:25 pi31 cmon[485] DEBUG weewx.manager: Daily summary version is 2.0

Mar 25 06:15:25 pi31 cmon[485] INFO weewx.cheetahgenerator: Generated 1 files for report cmon31 in 0.22 seconds

Mar 25 06:15:25 pi31 cmon[485] DEBUG weewx.manager: Daily summary version is 2.0

Mar 25 06:15:25 pi31 cmon[485] INFO weewx.imagegenerator: Generated 0 images for report cmon31 in 0.13 seconds

Mar 25 06:15:25 pi31 cmon[485] DEBUG weewx.reportengine: Running report 'FTP'

Mar 25 06:15:25 pi31 cmon[485] DEBUG weewx.reportengine: Found configuration file /home/weewx/skins/Ftp/skin.conf for report 'FTP'

Mar 25 06:15:25 pi31 cmon[485] DEBUG weeutil.ftpupload: Attempting connection to ftp.lucdesign.nl

Mar 25 06:15:28 pi31 cmon[485] DEBUG weeutil.ftpupload: Connected to ftp.lucdesign.nl

Mar 25 06:15:37 pi31 cmon[485] DEBUG weeutil.ftpupload: Uploaded file /_weewx/webcam3_v.jpg

Mar 25 06:15:41 pi31 cmon[485] DEBUG weeutil.ftpupload: Uploaded file /_weewx/webcam3_l.jpg

Mar 25 06:15:41 pi31 cmon[485] INFO weewx.reportengine: ftpgenerator: Ftp'd 2 files in 16.03 seconds

Mar 25 06:15:41 pi31 cmon[485] DEBUG weewx.reportengine: Report 'RSYNC' not enabled. Skipping.

Mar 25 06:15:59 pi31 mben[484] INFO user.modbusenergy: PTot: 506.7 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:16:01 pi31 CRON[1946]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:16:58 pi31 mben[484] INFO user.modbusenergy: PTot: 492.4 W,  ETot: 4987.3 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:17:01 pi31 CRON[2080]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:17:01 pi31 CRON[2079]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)

Mar 25 06:17:57 pi31 mben[484] INFO user.modbusenergy: PTot: 486.8 W,  ETot: 4987.4 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:18:01 pi31 CRON[2218]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:18:56 pi31 mben[484] INFO user.modbusenergy: PTot: 494.0 W,  ETot: 4987.4 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:19:01 pi31 CRON[2348]: (root) CMD (/home/weewx/util/init.d/webcam.debian 1> /var/log/webcam.txt 2> /var/log/webcam.err)

Mar 25 06:19:56 pi31 mben[484] INFO user.modbusenergy: PTot: 503.8 W,  ETot: 4987.4 kWh,  ETotEbsBer=68052.6 kWh

Mar 25 06:19:56 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:15:00 -03 (1585127700) to database 'weewx_mben31'

Mar 25 06:19:57 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:15:00 -03 (1585127700) to daily summary in 'weewx_mben31'

...

Mar 25 06:27:56 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:20:00 -03 (1585128000) to database 'weewx_mben31'

Mar 25 06:27:56 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:20:00 -03 (1585128000) to daily summary in 'weewx_mben31'

...

Mar 25 06:35:56 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:25:00 -03 (1585128300) to database 'weewx_mben31'

Mar 25 06:35:57 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:25:00 -03 (1585128300) to daily summary in 'weewx_mben31'

...

Mar 25 06:43:55 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:30:00 -03 (1585128600) to database 'weewx_mben31'

Mar 25 06:43:56 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:30:00 -03 (1585128600) to daily summary in 'weewx_mben31'

...

Mar 25 06:51:56 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:35:00 -03 (1585128900) to database 'weewx_mben31'

Mar 25 06:51:56 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:35:00 -03 (1585128900) to daily summary in 'weewx_mben31'

..

Mar 25 06:59:56 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:40:00 -03 (1585129200) to database 'weewx_mben31'

Mar 25 06:59:57 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:40:00 -03 (1585129200) to daily summary in 'weewx_mben31'

...

Mar 25 07:08:00 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:45:00 -03 (1585129500) to database 'weewx_mben31'

Mar 25 07:08:01 pi31 mben[484] INFO weewx.manager: Added record 2020-03-25 06:45:00 -03 (1585129500) to daily summary in 'weewx_mben31'

.====

[Vince Skahan]

Sounds like something is blocking waiting for i/o to complete perhaps (???)

[Lucas Heijst]

Vince,

Not sure. See the attached cpu data graph.

The empty parts in the graph are a result of the linux system looping (see: crash log)

Luc

[Vince Skahan]

On Wednesday, March 25, 2020 at 12:06:30 PM UTC-7, Lucas Heijst wrote:

Not sure. See the attached cpu data graph.

The empty parts in the graph are a result of the linux system looping (see: crash log)

The log showed the oom_killer which is more likely your problem.   You must have a memory leak somewhere.

I'd probably suggest the usual steps.  Run just the simulator and verify weewx is ok.  Then add things one by one and try to see which one is the culprit.

You can grab my 'mem' extension from https://github.com/vinceskahan/vds-weewx-v3-mem-extension if you need a lightweight thing to watch weewx memory usage.  It's a bit lighter weight than cmon/pmon/etc. I think.

 

[Lucas Heijst]

Vince,

I think the fact that weewx can't keep up in time to handle the 1-minute archive data is the reason that the memory is filled.. 

Each archive record contains 90 real values (doubles) and these values are stored in memory (I suppose) as long as they are not written to the database.

One hour before the low-memory crash weewx was 90 1-minute archive records behind.

Luc

[gjr80]

On Thursday, 26 March 2020 13:21:55 UTC+10, Lucas Heijst wrote:

I think the fact that weewx can't keep up in time to handle the 1-minute archive data is the reason that the memory is filled.

I think you are being a little harsh here Luc. From what i can read of the log extracts you are running a rather complex setup (two instances of WeeWX and at least three databases). I can think of a number of scenarios that could cause the symptoms you are seeing and none involve WeeWX not 'keeping up'.

 

Each archive record contains 90 real values (doubles) and these values are stored in memory (I suppose) as long as they are not written to the database.

One hour before the low-memory crash weewx was 90 1-minute archive records behind.

Might help to have a little more info if you want any meaningful advice other than maybe this or maybe that.

Are you running with software archive record generation? If so then WeeWX does not store any archive records (other than at most two, the last one that is being processed and the current one that is being accumulated). WeeWX accumulates loop packets and as soon as WeeWX receives a loop packet that belongs in the next archive period WeeWX synthesises an archive record and emits a NEW_ARCHIVE_RECORD event which causes that archive record to be archived and otherwise processed by the WeeWX services. The loop packet from the next archive period (and subsequent loop packets) are accumulated to create the next archive record. And the process repeats. So on a system with a driver that normally emits loop packets every 4 seconds, but for some reason these loop packets are being blocked within the driver and released much less frequently, WeeWX will only emit an archive record once it has received a loop packet timestamped in the next archive period. So what you can see happening is archive records being emitted and saved to database but at intervals much longer than the archive interval, in many cases the interval between these archive records being emitted increases as more and more loop packets are delayed. Ultimately an out of memory error can occur, if things haven't ground to a halt beforehand.

How about providing some config details? A debug log from startup would show almost everything needed to gicve us a more complete picture of your setup. What about your driver, does it interrogate hardware in its own thread or in the WeeWX thread? If it is not in its own thread it is possible that it is blocking and causing delays. What happens when you run WeeWX directly, do you see loop packets appearing, does the difference in successive loop packet timestamps align with the frequency they appear on the console? (ie if the loop packets are timestamped every four seconds do they appear on the console every fours seconds or every 15 seconds, 30 seconds, 60 seconds?) If there is a discrepancy that is a sure sign that something is blocking. How about posting a copy of the driver?

Hard to say a great deal without more logs, more config details and more driver details.

Gary

[Lucas Heijst]

Thanks Gary,

In no means I wanted to be hars, sorry about that. I am Dutch and we usualy say things with less diplomacy than others. 

Currently I am gathering the information you asked for.

The good news is that the following combination seems to work OK:

-----

RPI 3B+

weewx version 4.0.0b16

Python 2.7.13

Platform Linux-4.19.66-v7+-armv7l-with-debian-9.11 (latest version of raspbian jessie)

-----

The weewx programs modbusenergy.py, tfrc.py and cmon.py (used with weewx 3.9.2) were not modified so far.

The difference between version 3.9.2 and 4.0.0.b16 for the data in /var/log/syslog is the debug logging which will not be suppressed with setting ‘debug = 0’ for the program messages generated with:

def logmsg(dst, msg):

    syslog.syslog(dst, 'ModbusEnergy: %s' % msg)

I will let this configuration run for 24 hours and then modify the three user.py files to use logging:

log = logging.getLogger(__name__) instead of syslog.

I will keep you informed.

Luc

[Lucas Heijst]

Gary,

The programs modbusenergy.py, tfrc.py and cmon.py are modified to use module logging instead of syslog.

Everything still works OK.

Program modbusenergy has a memory leak of 80 KB per 24 h (nothing new), so the memory will be full after 7.5 days.

It looks like the program starts and stops a program twice per second, because each time I perform 'ps aux' the count is higher (2 counts per second).

Currently the counter has reach a maximum of 32316 and does't increase anymore.

I have too little knowledge of linux and python to debug the memory leak, so as a work-around my system is rebooted each 5th day.

Luc

[Vince Skahan]

On Friday, March 27, 2020 at 11:47:34 AM UTC-7, Lucas Heijst wrote

Program modbusenergy has a memory leak of 80 KB per 24 h (nothing new), so the memory will be full after 7.5 days.

It looks like the program starts and stops a program twice per second, because each time I perform 'ps aux' the count is higher (2 counts per second).

Currently the counter has reach a maximum of 32316 and does't increase anymore.

I have too little knowledge of linux and python to debug the memory leak, so as a work-around my system is rebooted each 5th day.

I'd reiterate my earlier suggestion......

- disable everything except one thing

- run it and get that stable

- add one thing at a time

- get 'that' stable

- then add the next thing

- and so on

Alternately.....

- start with your as-is

- disable one thing at a time

- see if that fixes things for a few days

- if not, disable the next thing

- and so on (ie, same as above, just by subtracting services)

From your skeletal description it certainly sounds like modbusenergy might be your problem.  Can you disable that first for a few days and see if things stabilize ?

You should never have to reboot a Linux system for stability reasons.   My ancient 128 MB RAM Seagate dockstar running my primary weewx has been up for 3.3 years, although I reset weewx occasionally when I update versions that of course.

[Lucas Heijst]

Vince,

As I stated earlier, I have no knowledge how to get program modbusenergy stable. 

I only can monitor the difference in memory leak with different settings.

Restarting a program doesn't change the used memory.

Luc

[Vince Skahan]

On Friday, March 27, 2020 at 12:45:22 PM UTC-7, Lucas Heijst wrote:

Vince,

As I stated earlier, I have no knowledge how to get program modbusenergy stable. 

I only can monitor the difference in memory leak with different settings.

Restarting a program doesn't change the used memory.

Disable it.   We need to see which of the many things you are running is the unstable thing. 

[Lucas Heijst]

Vince,

These are the steps I will do:

1. Stop mben, this will also stop cmon. Tfrc runs and the web photos are taken starting at 06:00 tomorrow morning.

2. When they are stable I will move cmon to tfrc.

3. When tfrc, web photo and cmon are stable I will start the mben driver but stop the mben service which handles the data of the mben driver.

Luc

[Lucas Heijst]

Vince,

I found one source of a memory leak: the webcam cronjob.

In the webcam.debian file a number of variables were used like:

WEBCAM_ID=4

CAMERA=picamera$WEBCAM_ID

DATETIME=$(date +"%Y-%m-%d %H:%M:%S")

EPOCH=$(date +"%s")

...

The memory which is used by these variables is not automatically freed after the cronjob task ends.

You need to unset them like:

unset WEBCAM_ID

unset CAMERA

unset DATETIME

unset EPOCH

...

Now the memory leak of the cronjob is minimal.

Luc

[Lucas Heijst]

Vice,

The memory leaks are caused by the weewx reporting (currently weewx 4.0.0b17)

I have posted this in a seperate thread.

Luc