ramlog on Raspberry Pi

Contents

  1. Ramlog Summary
  2. Initial experience with ramlog
  3. Zero reads
  4. Memory Leak
  5. rc.local
  6. Failure to start

Ramlog Summary

When installed, ramlog is one of the first processes to start as the system boots. It

  1. Allocates memory for use as a ram disk (amount controlled by TMPFS_RAMFS_SIZE in /etc/default/ramlog)
  2. Copies the content of /var/log into the ram disk
  3. Creates /var/log.hdd as a hard link to /var/log
  4. Mounts the ram disk over /var/log

The hard link /var/log.hdd provides one with visibility of the data in /var/log which is flushed to disk (and therefore that which will remain in the event of power failure or kernel panic!).

ramlog is "restarted" daily by cron.daily. The "restart" is not actually a restart, but rather a flushing to disk (SD card in the case of the Pi) of all updates to /var/log which have occurred in the previous 24 hours.

Warning, as alluded to above, in the event of a system crash, or malicious activity bringing the system down, it is likely that the very information you would need to diagnose the situation will be lost. All the logging you would otherwise want to examine will have disappeared as the system memory faded.

Initial experience with ramlog

The following table shows the impact on (SD card) filesystem writes of installing ramlog on our Raspberry Pi.

Our Pi acts as a data logger and fairly idle web server. The output below comes from SAR, so we obviously have SAR running (and logging to /var/log/sysstat) on the Pi, and the Pi has an attached device which spools XML to the pi (again into /var/log) every roughly 6 seconds, contributing roughly 0.2 writes per second (wtps below).

The data below comes from sar -b, and the data fields shown are
tps - Total number of I/O requests to the SD card per second
rtps - Total number of read requests per second issued to the SD card
wtps - Total number of write requests per second issued to the SD card
bread/s - Total number of blocks read from the SD card per second
bwrtn/s - Total number of blocks written to the SD card per second

Before ramlog installedAfter ramlog installed
00:00:01          tps      rtps      wtps   bread/s   bwrtn/s
00:05:01         0.60      0.00      0.60      0.00      7.94
00:15:02         0.55      0.00      0.55      0.00      6.60
00:25:01         0.56      0.00      0.56      0.00      6.68
00:35:01         0.52      0.00      0.52      0.00      5.80
00:45:01         0.55      0.00      0.55      0.00      6.13
00:55:01         0.53      0.00      0.53      0.00      5.90
01:05:01         0.54      0.00      0.54      0.00      6.06
01:15:01         0.54      0.00      0.54      0.00      5.99
01:25:01         0.55      0.00      0.55      0.00      6.15
01:35:01         0.54      0.00      0.54      0.00      6.23
01:45:01         0.57      0.00      0.57      0.00      6.34
01:55:01         0.54      0.00      0.54      0.00      5.98
02:05:01         0.53      0.00      0.53      0.00      5.99
02:15:01         0.56      0.00      0.56      0.00      6.76
02:25:01         0.58      0.00      0.58      0.00      6.86
02:35:01         0.54      0.00      0.54      0.00      5.99
02:45:02         0.56      0.00      0.56      0.00      6.34
02:55:01         0.53      0.00      0.53      0.00      5.90
03:05:01         0.55      0.00      0.55      0.00      6.19
03:15:01         0.55      0.00      0.55      0.00      6.12
03:25:02         0.58      0.00      0.58      0.00      6.56
03:35:01         0.52      0.00      0.52      0.00      5.88
03:45:01         0.55      0.00      0.55      0.00      6.09
03:55:01         0.57      0.00      0.57      0.00      6.43
04:05:01         0.57      0.00      0.57      0.00      6.47
04:15:01         0.55      0.00      0.55      0.00      6.89
04:25:01         0.60      0.00      0.60      0.00      7.21
04:35:01         0.57      0.00      0.57      0.00      6.32
04:45:01         0.60      0.00      0.60      0.00      6.73
04:55:01         0.54      0.00      0.54      0.00      6.02
05:05:01         0.55      0.00      0.55      0.00      6.11
05:15:01         0.56      0.00      0.56      0.00      6.28
05:25:01         0.56      0.00      0.56      0.00      6.32
05:35:01         0.55      0.00      0.55      0.00      6.22
05:45:01         0.61      0.00      0.61      0.00      6.96
05:55:01         0.55      0.00      0.55      0.00      6.07
06:05:02         0.54      0.00      0.54      0.00      6.15
06:15:01         0.60      0.00      0.60      0.00      7.37
06:25:01         0.60      0.00      0.60      0.00      7.16
06:35:01         0.72      0.00      0.72      0.01     13.06
06:45:01         0.56      0.00      0.56      0.00      6.28
06:55:01         0.54      0.00      0.54      0.00      5.95
07:05:01         0.54      0.00      0.54      0.00      6.02
07:15:01         0.57      0.00      0.57      0.00      6.46
07:25:01         0.55      0.00      0.55      0.00      6.26
07:35:01         0.53      0.00      0.53      0.00      5.95
07:45:01         0.56      0.00      0.56      0.00      6.24
07:55:01         0.61      0.00      0.61      0.00      7.00
08:05:01         0.58      0.00      0.58      0.00      6.58
08:15:01         0.56      0.00      0.56      0.00      6.87
08:25:01         0.59      0.00      0.59      0.00      7.24
08:35:01         0.58      0.00      0.58      0.00      6.58
08:45:02         0.55      0.00      0.55      0.00      6.18
08:55:01         0.52      0.00      0.52      0.00      5.72
09:05:01         0.54      0.00      0.54      0.00      6.01
09:15:01         0.89      0.28      0.61     55.31      9.50
09:25:01         3.24      1.59      1.65     40.25    110.32
Average:         0.62      0.03      0.58      1.72      8.42
 
00:00:01          tps      rtps      wtps   bread/s   bwrtn/s
00:05:01         0.06      0.01      0.06      0.21      0.80
00:15:01         0.03      0.00      0.03      0.00      0.41
00:25:01         0.03      0.00      0.03      0.00      0.49
00:35:01         0.03      0.00      0.03      0.00      0.51
00:45:01         0.03      0.00      0.03      0.00      0.41
00:55:01         0.01      0.00      0.01      0.00      0.21
01:05:01         0.01      0.00      0.01      0.00      0.21
01:15:01         0.03      0.00      0.03      0.00      0.41
01:25:01         0.03      0.00      0.03      0.00      0.49
01:35:01         0.03      0.00      0.03      0.00      0.51
01:45:01         0.03      0.00      0.03      0.00      0.41
01:55:01         0.01      0.00      0.01      0.00      0.21
02:05:02         0.01      0.00      0.01      0.00      0.21
02:15:01         0.03      0.00      0.03      0.00      0.41
02:25:01         0.03      0.00      0.03      0.00      0.49
02:35:01         0.03      0.00      0.03      0.00      0.51
02:45:01         0.03      0.00      0.03      0.00      0.41
02:55:01         0.01      0.00      0.01      0.00      0.21
03:05:01         0.01      0.00      0.01      0.00      0.21
03:15:01         0.03      0.00      0.03      0.00      0.41
03:25:01         0.03      0.00      0.03      0.00      0.49
03:35:01         0.01      0.00      0.01      0.00      0.21
03:45:01         0.03      0.00      0.03      0.00      0.41
03:55:01         0.01      0.00      0.01      0.00      0.21
04:05:01         0.01      0.00      0.01      0.00      0.22
04:15:01         0.03      0.00      0.03      0.00      0.41
04:25:01         0.03      0.00      0.03      0.00      0.49
04:35:01         0.03      0.00      0.03      0.00      0.51
04:45:01         0.03      0.00      0.03      0.00      0.41
04:55:01         0.01      0.00      0.01      0.00      0.21
05:05:01         0.01      0.00      0.01      0.00      0.21
05:15:01         0.03      0.00      0.03      0.00      0.41
05:25:01         0.03      0.00      0.03      0.00      0.48
05:35:01         0.03      0.00      0.03      0.00      0.51
05:45:02         0.03      0.00      0.03      0.00      0.41
05:55:01         0.01      0.00      0.01      0.00      0.21
06:05:01         0.01      0.00      0.01      0.00      0.21
06:15:01         0.03      0.00      0.03      0.00      0.41
06:25:02         0.04      0.01      0.03      0.25      0.49
06:35:01         9.79      9.48      0.31    107.84     38.75
06:45:02         0.03      0.00      0.03      0.00      0.41
06:55:01         0.03      0.00      0.03      0.00      0.41
07:05:01         0.01      0.00      0.01      0.00      0.21
07:15:01         0.03      0.00      0.03      0.00      0.41
07:25:01         0.03      0.00      0.03      0.00      0.48
07:35:02         0.03      0.00      0.03      0.00      0.49
07:45:01         0.03      0.00      0.03      0.00      0.41
07:55:01         0.01      0.00      0.01      0.00      0.20
08:05:01         0.01      0.00      0.01      0.00      0.21
08:15:01         0.03      0.00      0.03      0.00      0.41
08:25:01         0.03      0.00      0.03      0.00      0.49
08:35:01         0.03      0.00      0.03      0.00      0.49
Average:         0.21      0.19      0.03      2.11      1.13

Interestingly, the second set of sar output shown above, the "with ramlog" installed output, shows a burst of I/O activity in the 6:25 - 6:35 window. On checking /var/log/ramlog, the line
Apr 01 06:25:41 Restarting ramlog = saving logs to hdd:                  [ OK ]
shows the I/O activity was the daily sync of /var/log to /var/log.hdd. This was confirmed by observing the latest update date/times of all files in /var/log.hdd, and the record of cron.daily's run in /var/log/syslog (well actually /var/log/syslog.1 as logrotate, running under cron.daily, happened to have rotated syslog, and the cron.daily entry was the last record in the rotated file).

So, for our Pi with it's current usage, ramlog has removed 95% of the SD card writes which occur when the device in operating in a steady state. The /var/log writes to the SD card are all aggregated up into a few large writes when cron.daily runs, rather than thousands of small writes throughout the day. So I think I'm happy with ramlog as an SD card life extending measure.

As the ramlog which everyone refers to at http://www.tremende.com/ramlog/download/ramlog_2.0.0_all.deb was not there when I wanted it, I got our copy from https://raw.github.com/swirepe/personalscripts/master/pi/ramlog_2.0.0_all.deb, and I include it here too, in case that link also breaks.

Zero reads

Reviewing the sar output a few weeks later, I noticed that after the pi had been booted up for a couple of days, it never performed any SD card reads.

Unix/Linux operating systems use "all" spare memory as file cache. So any if there is unused memory available when a file is read (or written), the file contents are kept in memory. Subsequent reads from that file then do not require a filesystem I/O, as the file content is provided (very quickly) from (file cache) memory.

I put the "all" in quotes, as Unix/Linux systems will always keeps a small amount of memory unused so that they are able to deal promptly with memory requests without having to pause and figure out which file data (or other cache) to age out of memory, or which "dirty" memory has to be flushed to the filesystem (even worse, as it would then have to wait for the I/Os to complete before being about to satisfy the memory request).

When I logged onto the pi and "did stuff", then that resulted in SD card reads, but after a couple of days normal day to day operation, it had got everything it needed into file cache, and needed to perform no reads at all.

Possible Leak

If you have visited this page before, and were interested in whether I found a memory leak associated with ramlog,..,.

The leak I had was caused by a process of mine which read a number of files which were subsequently deleted. As the process still had a handle on the files, the files were not "visible", but were still taking up space in the filesystem managed by ramlog, so it appeared that there was a memory leak in ramlog. Once the process in question ended or was killed, the memory associated with the deleted files reappeared.

So there was no memory leak in ramlog.

rc.local

After a domestic power outage, one of our Raspberry Pi's (running ramlog) did not re-appear on the network. I think this was due to the time associated with our network infrasture restarting compared to that of the Pi restarting, and the Pi then not trying to obtain an IP address after the network hardware got it's act together. However, as I power cycled the Pi to get it going again, it's logs went, so I don't know.

So that I am able to check the logs after a repeat of a similar situation in the future, I have now added the following lines to /etc/init.d/rc.local

(
  sleep 300
  /etc/init.d/ramlog restart
  sleep 300
  /etc/init.d/ramlog restart
  sleep 3600
  /etc/init.d/ramlog restart
) &
  

This will mean that the /var/log filesystem will get flushed to the SD card 5, 10 and 70 minutes after the Pi boots. So long as the Pi is up for at least five minutes, there will now be boot information written to the SD card for subsequent inspection.

Failure to Start

After powering the house (and therefore Raspberry Pi) down one day, ramlog did not restart when the pi restarted. This was due to rsyslog having started before ramlog attempted to start,..,. which meant that /var/log was already in use and so ramlog could not do its job. So, after trying just rebooting to see whether that addressed the situation, I tried adding

# X-Start-Before: $syslog
  
and then
# X-Start-Before: rsyslog
  
to the "INIT INFO" section in /etc/init.d/ramlog, but neither of these seemed to do the trick of pursuading the pi to start ramlog before rsyslog.

In the end my solution was to add

sleep 2
  
to /etc/init.d/rsyslog just after it's "INIT INFO" section, and that did the trick.