[systemd-devel] Journal file disk usage on frequently rebooted systems ... again

[Jens Schmidt]

I’m still slightly haunted by journal file disk space usage on a
system with frequent reboots.  Even after systemd issues #32248
and #32153, where I have assured @FabienRCT myself that journald
does everything right.

Here is a journal file that nicely shows my remaining doubts.
User 2001 is used on my laptop by some funny Citrix log daemon
which usually has very little to do.  (All file and directory
names shortened by me.)

    [~]$ cd /var/log/journal/e9

    [e9]$ ls -l /var/log/journal/e9/user-2001 at 02-00-00.journal
    -rw-r-----+ 1 root systemd-journal 8388608 Apr 12 10:23 /var/log/journal/e9/user-2001 at 02-00-00.journal
    [e9]$ du -k /var/log/journal/e9/user-2001 at 02-00-00.journal
    3568    /var/log/journal/e9/user-2001 at 02-00-00.journal
    [e9]$ journalctl --file /var/log/journal/e9/user-2001 at 02-00-00.journal --disk-usage
    Archived and active journals take up 3.4M in the file system.

So it really does not take up 8MiB, but only 3.4MiB, understood
that.  But when checking the messages contained in that 3.4MiB,
this still seems to be an awful lot of disk space:

    [e9]$ journalctl --file /var/log/journal/e9/user-2001 at 02-00-00.journal | cat
    Apr 11 10:21:59 sappc1 citrix-ctxlogd[1467]: Log writer thread starting.
    Apr 11 10:21:59 sappc1 citrix-ctxlogd[1467]: logSessionMax: 200
    Apr 11 10:21:59 sappc1 citrix-ctxlogd[1467]: Started.
    Apr 11 10:24:30 sappc1 citrix-ctxlogd[1467]: Session starting for pid 3810.
    Apr 11 10:24:30 sappc1 citrix-ctxlogd[1467]: Session closing for pid 3810.
    Apr 11 10:24:30 sappc1 citrix-ctxlogd[1467]: Session starting for pid 3810.
    Apr 11 10:24:30 sappc1 citrix-ctxlogd[1467]: Process 3810 has named itself "citrix-wfica".
    Apr 11 18:58:26 sappc1 citrix-ctxlogd[1467]: Session closing for pid 3810.
    Apr 11 18:59:41 sappc1 citrix-ctxlogd[1467]: Cleaning up.
    Apr 11 18:59:41 sappc1 citrix-ctxlogd[1467]: Log writer thread stopping.
    Apr 11 18:59:41 sappc1 citrix-ctxlogd[1467]: 3215 total bytes written from 2 sessions.
    Apr 11 18:59:41 sappc1 citrix-ctxlogd[1467]: Stopped.

    [e9]$ journalctl --file /var/log/journal/e9/user-2001 at 02-00-00.journal | wc
         12     107     856

3.4MiB just to store 856 characters?

Another way to see the issue is by rotating quickly twice, which should
create a nearly empty journal file ("most-recent-archived-journal-file"):

    [~]$ sudo journalctl --rotate; sudo journalctl --rotate
    [~]$ mrajfn=$( ls -tr /var/log/journal/e9/system\@*.journal | tail -1 )
    [~]$ ls -l "$mrajfn"
    -rw-r-----+ 1 root systemd-journal 8388608 Apr 26 21:05 /var/log/journal/e9/system at 74-00-00.journal
    [~]$ du -k "$mrajfn"
    3564    /var/log/journal/e9/system at 74-00-00.journal
    [~]$ journalctl --file "$mrajfn" --disk-usage 
    Archived and active journals take up 3.4M in the file system.
    [~]$ journalctl --file "$mrajfn" | cat
    Apr 26 21:05:19 sappc1 systemd-journald[970]: System Journal (/var/log/journal/e9) is 42.5M, max 997.9M, 955.3M free.
    Apr 26 21:05:19 sappc1 systemd-journald[970]: Received client request to rotate journal, rotating.
    Apr 26 21:05:19 sappc1 systemd-journald[970]: Deleted empty archived journal /var/log/journal/e9/user-2001 at 74e2eb147e6241888314bf382fe28591-0000000000000000-0000000000000000.journal (3.4M).
    Apr 26 21:05:19 sappc1 systemd-journald[970]: Vacuuming done, freed 3.4M of archived journals from /var/log/journal/e9.

So there seems to be a constant minimum overhead of 3.4MiB per
journal file that does not go away even by truncation.

Where does that overhead come from?  Could it be reduced?  What
am I missing here?

Thanks!