rPi 3B+ getting hot. Redis high CPU usage. (emonSD-13Jun18 dev. specific)

Here is the thread to record the redis CPU issue.

. I’ve tested on two separate rPi 3B+ devices. Same issue on both.
. Issue apparent upon fresh install, no changes, no updates.
. I’m connected over ethernet.
. Makes no difference running emonBase update as of today.
. SHHing in early during the boot process it can be observed the moment when the issue becomes apparent.

Server Information
Emoncms Version low-write 9.8.31 : 2018.06.21
Modules Administration : App v1.1.1 : Backup v1.1.4 : EmonHub Config v1.0.0 : Dashboard v1.3.0 : EventProcesses : Feed : Graph v1.2.0 : Input : postprocess : CoreProcess : Schedule : setup : sync : Time : User : Visualisation : WiFi v1.3.0
Buffer loading…
Writer Daemon is running with sleep 60s
Server OS Linux 4.14.34-v7+
Host emonpi emonpi (127.0.1.1)
Date 2018-08-17 09:14:00 UTC
Uptime 09:14:00 up 13 min, 1 user, load average: 0.36, 0.44, 0.30
HTTP Server Apache/2.4.25 (Raspbian) HTTP/1.1 CGI/1.1 80
MySQL Version 5.5.5-10.1.23-MariaDB-9+deb9u1
Host localhost (127.0.0.1)
Date 2018-08-17 09:14:00 (UTC 00:00‌​)
Stats Uptime: 698 Threads: 3 Questions: 716 Slow queries: 0 Opens: 44 Flush tables: 1 Open tables: 38 Queries per second avg: 1.025
Redis Version 3.2.6
Host localhost:6379 (127.0.0.1)
Size 0 keys (702.70K)
Uptime 0 days
MQTT Version 1.4.10
Host localhost:1883 (127.0.0.1)
Pi Model Raspberry Pi 3 Model B+ Rev 1.3 - 1 GB (Sony UK)
SoC Broadcom BCM2835
Serial num. 6090B06B
Temperature CPU: 54.23°C - GPU: 53.7’C
Release emonSD-13Jun18
File-system Current: read-only - Set root file-system temporarily to read-write, (default read-only)
Memory RAM Used: 29.14% Total: 976.74 MB Used: 284.57 MB Free: 692.17 MB
Disk Mount Stats
/ Used: 71.78% Total: 3.33 GB Used: 2.39 GB Free: 797.04 MB
/boot Used: 37.69% Total: 59.95 MB Used: 22.59 MB Free: 37.35 MB
/home/pi/data Used: 3.53% Total: 3.46 GB Used: 125.15 MB Free: 3.16 GB
PHP Version 7.0.27-0+deb9u1 (Zend Version 3.0.0)
Modules apache2handler : calendar v7.0.27-0+deb9u1 : Core v7.0.27-0+deb9u1 : ctype v7.0.27-0+deb9u1 : curl v7.0.27-0+deb9u1 : date v7.0.27-0+deb9u1 : dom v20031129 : exif v7.0.27-0+deb9u1 : fileinfo v1.0.5 : filter v7.0.27-0+deb9u1 : ftp v7.0.27-0+deb9u1 : gd v7.0.27-0+deb9u1 : gettext v7.0.27-0+deb9u1 : hash v1.0 : iconv v7.0.27-0+deb9u1 : igbinary v2.0.1 : json v1.4.0 : libxml v7.0.27-0+deb9u1 : mcrypt v7.0.27-0+deb9u1 : mosquitto v0.4.0 : mysqli v7.0.27-0+deb9u1 : mysqlnd vmysqlnd 5.0.12-dev - 20150407 - $Id: b5c5906d452ec590732a93b051f3827e02749b83 $ : openssl v7.0.27-0+deb9u1 : pcre v7.0.27-0+deb9u1 : PDO v7.0.27-0+deb9u1 : pdo_mysql v7.0.27-0+deb9u1 : Phar v2.0.2 : posix v7.0.27-0+deb9u1 : readline v7.0.27-0+deb9u1 : redis v3.1.1 : Reflection v7.0.27-0+deb9u1 : session v7.0.27-0+deb9u1 : shmop v7.0.27-0+deb9u1 : SimpleXML v7.0.27-0+deb9u1 : sockets v7.0.27-0+deb9u1 : SPL v7.0.27-0+deb9u1 : standard v7.0.27-0+deb9u1 : sysvmsg v7.0.27-0+deb9u1 : sysvsem v7.0.27-0+deb9u1 : sysvshm v7.0.27-0+deb9u1 : tokenizer v7.0.27-0+deb9u1 : wddx v7.0.27-0+deb9u1 : xml v7.0.27-0+deb9u1 : xmlreader v7.0.27-0+deb9u1 : xmlwriter v7.0.27-0+deb9u1 : xsl v7.0.27-0+deb9u1 : Zend OPcache v7.0.27-0+deb9u1 : zlib v7.0.27-0+deb9u1

That last line might be a hint? Looks like redis is trying to fill/load/read the buffer and not having much success

What’s particularly weird is that on my screen it displays as this:


the clipboard again:

Server Information
Emoncms Version low-write 9.8.31 : 2018.06.21
Modules Administration : App v1.1.1 : Backup v1.1.4 : EmonHub Config v1.0.0 : Dashboard v1.3.0 : EventProcesses : Feed : Graph v1.2.0 : Input : postprocess : CoreProcess : Schedule : setup : sync : Time : User : Visualisation : WiFi v1.3.0
Buffer loading…
Writer Daemon is running with sleep 60s
Server OS Linux 4.14.34-v7+
Host emonpi emonpi (127.0.1.1)
Date 2018-08-18 05:28:15 UTC
Uptime 05:28:15 up 13:18, 0 users, load average: 0.56, 0.55, 0.58
HTTP Server Apache/2.4.25 (Raspbian) HTTP/1.1 CGI/1.1 80
MySQL Version 5.5.5-10.1.23-MariaDB-9+deb9u1
Host localhost (127.0.0.1)
Date 2018-08-18 05:28:15 (UTC 00:00‌​)
Stats Uptime: 47885 Threads: 2 Questions: 141 Slow queries: 0 Opens: 44 Flush tables: 1 Open tables: 38 Queries per second avg: 0.002
Redis Version 3.2.6
Host localhost:6379 (127.0.0.1)
Size 0 keys (704.80K)
Uptime 0 days
MQTT Version 1.4.10
Host localhost:1883 (127.0.0.1)
Pi Model Raspberry Pi 3 Model B+ Rev 1.3 - 1 GB (Sony UK)
SoC Broadcom BCM2835
Serial num. 3000F93D
Temperature CPU: 65.53°C - GPU: 65.5’C
Release emonSD-13Jun18
File-system Current: read-only - Set root file-system temporarily to read-write, (default read-only)
Memory RAM Used: 29.35% Total: 976.74 MB Used: 286.71 MB Free: 690.03 MB
Disk Mount Stats
/ Used: 86.33% Total: 3.33 GB Used: 2.87 GB Free: 301.07 MB
/home/pi/data Used: 3.54% Total: 3.46 GB Used: 125.38 MB Free: 3.16 GB
/boot Used: 42.70% Total: 59.95 MB Used: 25.59 MB Free: 34.35 MB
PHP Version 7.0.27-0+deb9u1 (Zend Version 3.0.0)
Modules apache2handler : calendar v7.0.27-0+deb9u1 : Core v7.0.27-0+deb9u1 : ctype v7.0.27-0+deb9u1 : curl v7.0.27-0+deb9u1 : date v7.0.27-0+deb9u1 : dom v20031129 : exif v7.0.27-0+deb9u1 : fileinfo v1.0.5 : filter v7.0.27-0+deb9u1 : ftp v7.0.27-0+deb9u1 : gd v7.0.27-0+deb9u1 : gettext v7.0.27-0+deb9u1 : hash v1.0 : iconv v7.0.27-0+deb9u1 : igbinary v2.0.1 : json v1.4.0 : libxml v7.0.27-0+deb9u1 : mcrypt v7.0.27-0+deb9u1 : mosquitto v0.4.0 : mysqli v7.0.27-0+deb9u1 : mysqlnd vmysqlnd 5.0.12-dev - 20150407 - $Id: b5c5906d452ec590732a93b051f3827e02749b83 $ : openssl v7.0.27-0+deb9u1 : pcre v7.0.27-0+deb9u1 : PDO v7.0.27-0+deb9u1 : pdo_mysql v7.0.27-0+deb9u1 : Phar v2.0.2 : posix v7.0.27-0+deb9u1 : readline v7.0.27-0+deb9u1 : redis v3.1.1 : Reflection v7.0.27-0+deb9u1 : session v7.0.27-0+deb9u1 : shmop v7.0.27-0+deb9u1 : SimpleXML v7.0.27-0+deb9u1 : sockets v7.0.27-0+deb9u1 : SPL v7.0.27-0+deb9u1 : standard v7.0.27-0+deb9u1 : sysvmsg v7.0.27-0+deb9u1 : sysvsem v7.0.27-0+deb9u1 : sysvshm v7.0.27-0+deb9u1 : tokenizer v7.0.27-0+deb9u1 : wddx v7.0.27-0+deb9u1 : xml v7.0.27-0+deb9u1 : xmlreader v7.0.27-0+deb9u1 : xmlwriter v7.0.27-0+deb9u1 : xsl v7.0.27-0+deb9u1 : Zend OPcache v7.0.27-0+deb9u1 : zlib v7.0.27-0+deb9u1

Client Information
HTTP Browser Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:61.0) Gecko/20100101 Firefox/61.0
Screen Resolution 1440 x 900
Window Size 1425 x 799

I’ve checked on an older Pi running Oct2017, it’s the same, the clipboard behaviour has been inherited from there. redis CPU usage is about 1.3%. Unlikely that Buffer : loading is the problem.

Are you saying that the screenshot and the clipboard text in that post are from the same “view” at the same time?

If so, then I suggest you remove the text version and just put the screenshot there, one thing worse than no information is incorrect information :slight_smile:

2 Likes

Absolutely, 100% correct! if only that was more widely understood, accepted and accommodated, life would be sooooo much easier.

1 Like

What’s in the way of myself, and others here probably, making and sticking to correct information is impetuousness.
I’ll might make more mistakes… I’ll try into the future to keep it accurate :slight_smile:

My previous post though was accurate. Both the screenshot and clipboard are taken from the same view seconds apart on a rPi3B+ that’s been running for a while on the Jun2018 image. This could be put down as a separate bug as it’s repeatable behaviour. The behaviour was inherited from the Oct2017 image.

The comments about correct info are in no way aimed at you Dan (or others that take info at face value) I would perceive you as the victim of the mis-information rather than the perpetrator.

This is not the first time that it has been noticed that the buffer shows as “loading” whilst debugging other issues, this is the first time it has been reported that there are inconsistencies between the page and the clipboard version.

I wonder how much time has been lost pondering on why the buffer is “loading” rather than pursuing the real issue unhindered by that mis-information.

What is really frustrating for me personally is the fact I objected to the way the copy to clipboard was done at the time. The data is collected independently for each method (screen or copy) so there could potentially be vast differences, unless you open the server info dropdown and manually go through checking each and every word, you do not know if what you (the user) are offering as fact is indeed so. There is also 2 lots of code to maintain.

Regarding the issue at hand…

What I find more interesting is the fact you have 0 keys and 0 running time for Redis, the server time suggests it’s not just been rebooted, but it does differ to the previous server info so I guess you are rebooting and restarting stuff. How long has it been since you tried to restart redis or rebooted?

30% CPU load when it’s not actually doing anything (ie no keys etc) might suggest it’s sruggling to get started, perhaps that high load is it trying to connect or create a log file or something else preventing it getting up and running.

What do you see if you try to restart it from the command line?

sudo systemctl restart redis-server

have you checked the redis logs and emoncms logs?

What are your Redis settings in emoncms/settings.php?

have you tried flushing redis (very long shot but worth ruling out)

I also notice the redis php extension module is 3.1.1, that’s quite dated. The current version is 4.1.1, but there were “potentially” breaking changes made in v4 (see Possible breaking api changes in php-redis · Issue #836 · emoncms/emoncms · GitHub) so I’m still running v3.1.6. I doubt this is the cause (guesswork) but worth a mention.

[edit] Oh! And another long shot, are there any redis files in /var/lib ?

sudo ls -la /var/lib/redis/*

[edit2] Also was it doing this before you started the SMA inverter/pvoutput stuff? Or have you since retested on a vanilla image? It’s just that you mentioned editing the rc.local file and that is also where the redis-server (and other) logfiles are created and then the services restarted. Can you confirm there is a logfile for redis created during startup?

sudo ls -la /var/log/redis

[edit3] Issue opened about the difference in reported info

1 Like

@pb66, In the first post it mentions:

and based on the Server Information, its a “fresh install” of emonSD-13Jun18.

In the other thread that this post started in, I’m pretty sure dan mentioned he’d been able to reproduce it from a freshly imaged SD Card, so I have been assuming when he says “fresh install” above, that he really means “SD Card with a freshly written image booted up for the first time”.

@danbates, can you confirm when you say “no changes, no updates”, you mean exactly:

  • Write emonSD-13Jun18 image to SD Card on another machine
  • Insert SD Card in Pi3
  • Power up Pi3
  • Login to Pi3 with ssh
  • run top
  • observe redis-server process consuming ~25% CPU

and absolutely nothing else?

I can confirm that. Using etcher to write the image on mac osx el capitan.
I neglected to mention it was the experimental stretch image in the original post as this followed from another thread.

@pb66 I’ll have a look at your notes soon. Glad you beat me to it on opening a github. @glyn.hudson I’m sure you’ve got input. If you need help testing let me know.

I’ve edited the thread title to include the emonSD image name, for any future explorers.

@pb66 and to add onto the list of things to test, is whether something changes when redis has something to process, i.e. when emoncms is receiving inputs.

  1. redis logs…

  2. emonCMS logs…

  3. redis settings in emoncms/settings.php…
    logs and settings.zip (24.0 KB)
    see 12:35pm on 19th August for seconds leading up to observed redis CPU use increase.

  4. sudo systemctl restart redis-server
    does nothing

  5. Flushing redis.
    nothing again.

  6. redis version
    is 3.2.6 after update emonPi update button, no change

  7. redis files in /var/lib/redis/*
    permission error, can’t view 'em.

  8. sudo ls -la /var/log/redis
    total 8
    drwxr-xr-x 2 redis redis 60 Aug 19 12:34 .
    drwxr-xr-x 11 root root 500 Aug 19 12:34 …
    -rw-rw-rw- 1 redis redis 6384 Aug 19 13:04 redis-server.log

and 9. give it inputs to process.
no change.

Not even with sudo ls -la /var/lib/redis ?

This is in syslog:

Aug 19 12:34:29 emonpi systemd[1]: [/lib/systemd/system/redis-server.service:14] Unknown lvalue 'RunTimeDirectory' in section 'Service'
Aug 19 12:34:29 emonpi systemd[1]: Starting Advanced key-value store...

RunTimeDirectory sounds important, it looks like its value couldn’t be loaded from the config?
There’s no errors in the redis-server.log indicating there’s an issue though, but probably worth checking anyway.

I just found a bug report on Debian bug reports which says:

Followed by (in closing the bug report):

And then only a few months ago on the same page, it was reopened again:

So, is it worth changing the case of “RunTimeDirectory” to “RuntimeDirectory” in /lib/systemd/system/redis-server.service (should be on line 14) and see if there’s any change?

[Edit] worth noting that the actual fix in the bug report linked above is

[Edit #2] I just checked the man-page for systemd.exec and the RuntimeDirectory directive is used to create runtime folders under a root folder as defined in the following table, so likely there are runtime folders that are expected to exist but do not.
Table from man-page:

Locations for system for users
RuntimeDirectory= /run $XDG_RUNTIME_DIR

Got it. I’d like to know how that command works.

[email protected](ro):~$ sudo ls -la /var/lib/redis
total 12
drwxr-x---  2 redis redis 4096 May 17 13:41 .
drwxr-xr-x 44 root  root  4096 May 17 12:52 ..
-rw-rw----  1 redis redis   76 May 17 13:41 dump.rdb

. Correcting typo on line 14, reboot, no change with issue.
. Directory /run and /run/redis contents below… Not sure what I’m looking for.

[email protected](rw):/$ cd run
[email protected](rw):run$ ls
agetty.reload  dbus                dnsmasq         log            network     rpcbind.lock     sshd        udev
apache2        dhclient.wlan0.pid  emonhub.pid     lwrfd.pid      ntpd.pid    rpcbind.sock     sshd.pid    user
avahi-daemon   dhcpcd              emonPiLCD.pid   mosquitto.pid  plymouth    rpc_pipefs       sysconfig   utmp
console-setup  dhcpcd.pid          feedwriter.pid  motd.dynamic   redis       rsyslogd.pid     systemd     wpa_supplicant
crond.pid      dhcpcd.sock         initctl         mount          resolvconf  sendsigs.omit.d  thd.socket  wpa_supplicant.wlan0.pid
crond.reboot   dhcpcd.unpriv.sock  lock            mysqld         rpcbind     shm              tmpfiles.d  xtables.lock
[email protected](rw):run$ 
[email protected](rw):run$ cd redis
[email protected](rw):redis$ ls
redis-server.pid
[email protected](rw):redis$

More usefully is actually understanding why “sudo ls -la /var/lib/redis/*doesn’t work. See this post of mine here.
In previous distributions that file would have been deleted as part of the “making read-only”. It was recently discovered (in that thread I just linked to) that there was an error in the build guide which leaves that file behind causing other issues (as per that other thread). Try removing it using:

sudo rm /var/lib/redis/dump.rdb

Ok, looks like once the folder was there, all it created in that folder was the .pid file (which is normally used to track what PID the process is running under) so it probably didn’t have any consequences beyond logging an error in syslog on service startup.

See how you go removing the dump.rdb file from /var/lib/redis.

Removing seemed to happen OK. No change with redis.

[email protected](ro):~$ sudo ls -la /var/lib/redis
total 8
drwxr-x---  2 redis redis 4096 Aug 20 06:56 .
drwxr-xr-x 44 root  root  4096 May 17 12:52 ..

I notice on the redis website we’ve got a newer old version 3 to try out.