Issue getting output from e4rat, and a workaround

cubethethird · 2016-04-02 03:02:59

I've spent some time getting e4rat working, which can optimize the placement of boot files on an HDD. I build a custom kernel, and installed audit correctly to use it. The problem was, I wasn't getting any output. Logs would show "Saved list to file" then some cryptic characters. Seemed there was an issue with the output location. To work around this, I modified the source code from the repository.

As a workaround, I hard-coded the output directory, replacing (in e4rat-collect.cc and e4rat-preload.cc):

Config::get<std::string>("startup_log_file").c_str()

with

/var/lib/e4rat/startup.log

This solved the issue. What I'm wondering though (as my C++ is fairly rusty) if the issue I'm experiencing with it as is is an issue with the code, the compiler, or something on my system.

kozaki · 2016-07-14 21:45:15

@cubethethird I enjoyed reading your recent blog paper called Reducing boot times on [rotational hdd] Arch Linux, as I find it a welcome update to the neat paper on Arch wiki [1] and forum thread [2].

Short version:

Has anyone used e4rat successfully on an lvm2 set-up?

Last edited by kozaki (2016-07-14 21:51:48)

kozaki · 2016-07-14 21:52:03

Some more details:

Allow me to expose why e4rat hdd's access time stuff is interesting in my case.

I got a tiny Atom laptop that I like to use over a bigger and (moderately) faster Chromebook. I also do like to hack stuff over buy-a-new-bigger-blabla stuff, and this little shit's 5400 rpm spinning hdd is doing well. Investing 70-80 EUR in a >= sized SSD is not on my agenda.
It has multi-boot to 4-5 different OSes, so going hibernate/suspend isn't always possible.
running e4rat might allow the netbook to load i3-wm and my most used applications 20-30 sec faster than it does atm.

Maybe you get it I had failed to build e4rat ever since I got Arch freshly re-installed on the tiny laptop, six months ago.

Now carefully following cubethethird' steps as well as takeshibaconsuzu's [3] I
- compiled stock Arch kernel with AUDIT=y
- built audit with 'staticlibs'
- built e4rat and got it running upon rebooting.

Day one

uname -rms
  Linux 4.6.3-1-audit i686

journalctl -b | grep -i e4rat

juil. 13 18:05:24 gwenael kernel: Kernel command line: BOOT_IMAGE=../vmlinuz-linux-audit1 root=/dev/mapper/vg1-sys1b rw resume=UUID=b43bc921-65cb-4b55-9f7d-34b06d5dac14 audit=1 init=/usr/bin/e4rat-collect zswap.enabled=1 zswap.             max_pool_percent=25 zswap.compressor=lz4 systemd.restore_state=0 initrd=../initramfs-linux-audit1.img
juil. 13 18:06:16 gwenael audit: EXECVE argc=4 a0="grep" a1="--color" a2="-i" a3="e4rat"
juil. 13 18:07:15 gwenael audit: EXECVE argc=4 a0="grep" a1="--color" a2="-i" a3="e4rat"

zgrep -i audit /proc/config.gz

CONFIG_LOCALVERSION="-audit"
CONFIG_AUDIT=y
CONFIG_HAVE_ARCH_AUDITSYSCALL=y
CONFIG_AUDITSYSCALL=y
CONFIG_AUDIT_WATCH=y
CONFIG_AUDIT_TREE=y
CONFIG_AUDIT_GENERIC=y
# CONFIG_AUDIT_ARCH_COMPAT_GENERIC is not set

Another day, another result

sudo journalctl -xb|grep e4rat                                                   
                                                                                 
  juil. 11 23:24:49 gwenael kernel: Kernel command line: BOOT_IMAGE=../vmlinuz-linux-audit    root=/dev/mapper/vg1-sys1b rw resume=UUID=b43bc921-65cb-4b55-9f7d-34b06d5dac14 audit=1 init=/sbin/e4rat-collect zswap.enabled=1 zswap.max_pool_percent=25 zswap.compressor=lz4 systemd.restore_state=0 initrd=../initramfs-linux-audit.img
  juil. 11 23:26:31 gwenael audit: EXECVE argc=9 a0="ls" a1="-p" a2="--color=auto" a3="--group-directories-first" a4="-l" a5="-G" a6="-h" a7="-p" a8="/var/lib/e4rat/"
  juil. 11 23:26:31 gwenael audit: PATH item=0 name="/var/lib/e4rat/" inode=428533 dev=fe:01  mode=040755 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL

Another day...

journalctl -b|grep -i e4rat

juil. 14 19:52:06 gwenael kernel: Kernel command line: BOOT_IMAGE=../vmlinuz-linux-audit1 root=/dev/mapper/vg1-sys1b ro resume=UUID=b43bc921-65cb-4b55-9f7d-34b06d5dac14 audit=1 init=/usr/bin/e4rat-collect systemd.restore_state=0 initrd=../ initramfs-linux-audit1.img

No doubt it is running:

(07:52  jeu. juil. 14) ~ $ ps aux|grep e4rat
root         1  4.3  0.2   5744  4464 ?        Ss   19:51   0:02 /usr/bin/e4rat-collect
kozaki    1040  0.0  0.1   4752  2272 pts/0    S+   19:52   0:00 grep --color e4rat

(07:53  jeu. juil. 14) ~ $ ps aux|grep e4rat
root         1  1.8  0.2   5744  4464 ?        Ss   19:51   0:02 /usr/bin/e4rat-collect
kozaki    1202  0.0  0.1   4752  2224 pts/0    S+   19:53   0:00 grep --color e4rat

I kept /etc/e4rat.conf default. Actually I once set log level = 31 and could see it "collecting" on screen for a good minute while booting. Also I once set it to log on physical partition /boot, but na.

verbose  31
startup_log_file /boot/e4rat_startup.log

And there's one thing that kept unchanged across all my attempts:

ll /var/lib/e4rat/
total 0
-rw-r--r-- 1 root 0 juil. 12 01:38 startup.log

My laptop drive layout:

sda
|_ sda1 /boot ext4
|_ sda2 swap
|_ sda3 pv1 » vg1 » lv1 (Arch), lv2 (Arch testing) ... and so on.

Some references

[1]: https://wiki.archlinux.org/index.php/E4rat
[2]: https://bbs.archlinux.org/viewtopic.php?id=115976
[3]: https://aur.archlinux.org/packages/e4rat/
Gentoo wiki page has gone away (with the last hdd users?)

cubethethird · 2016-07-14 22:05:46

I don't expect this was missed, but did you create the /boot/e4rat_startup.log file, with full write permissions before running it?

kozaki · 2016-07-14 23:00:36

@cubethethird well I did try having chmoded 666 startup.log. And with the default directory empty.
I'll chmod 666 /boot/startup.log and try again.
So you think it's e4rat unable to write on a lvm volume.

EDIT:
Running e4rat-collect manually it says: « sh: lsof, command not found. » And yeah, it's not installed. Will follow up.

EDIT2:

Installed lsof. Rebooted. e4rat-collect did run without a doubt (ps aux|grep e4rat is clear on that.

process won't stop after 2+ min. Have to kill it manually. Then it saves nothing.

sudo e4rat-collect -k
[sudo] password for kozaki:
Cannot read pid from file /dev/.e4rat-collect.pid: No such file or directory
Cannot dump log messages: /dev/kmsg: Bad file descriptor
Discard 1 unwritten log message(s).

Like in
- https://bbs.archlinux.org/viewtopic.php … 3#p1431003
- https://dug.net.pl/tekst/218/e4rat__czy … _dla_ext4/ (my Polish is a bit passed though)

While manually all run fine; stopping the process does fill the 'startup.log' file:

03  ven. juil. 15 ~ $ sudo e4rat-collect -o /boot/e4rat_startup.log
Press 'Ctrl-C' to stop collecting files
^C  208 file(s) collected
Save file list to /boot/e4rat_startup.log
             
ll /boot/*log
-rw-rw-rw- 1 root 16K juil. 15 02:07 e4rat_startup.log

EDIT ~~That's a hell lot of trouble for a tool. More than I was expecting even for an unmaintaned since one year utility working at the low filesystem level, especially after cubethethird and takeshibaconsuzu succesfully make it work as intended.~~ (I live in France and was shocked at the time writing, sorry about that)

What's good is that e4rat-collect does collect when run manually. What coukd cause it to not collect when running at boot time?

Last edited by kozaki (2016-07-15 11:34:20)

kozaki · 2016-07-18 00:51:46

Guys, I hope I'll be able to find what forbids init=/sbin/e4rat-collect to write his log file. For now I re-partitionned the laptop hdd with a clean, no lvm layout but that doesn't change the issue. Output is the same than in #5.

EDIT
@cubethethird I forgot to emphasize I did try with chmod 777 /var/lib/e4rat (bo-ho!) and 666 /var/lib/e4rat/startup.log.

Eventually I killed X and started

~ $ sudo e4rat-collect -o $HOME/e4rat.log

which collected a fair amount (~84 KiB). I then went to 'rescue' and could run `e4rat-realloc $HOME/e4rat.log`.
Then I tought, hey, let's start in rescue from boot and launch it from there at least

~ # sudo e4rat-collect -o /var/log/e4rat_startup.log && systemctl start graphical.target

File is empty 8-@

Meanwhile (e4rat is just a big part here, won't select the right daemons for me) I went for manual optimization and CLI login is down to 19 seconds (from 32 sec last Satruday).
e4rat would add some sugar, but ha!

Last edited by kozaki (2016-07-18 22:58:37)

kozaki · 2016-07-21 20:35:56

Now collecting *and* storing.
e4rat didn't finish to build on my x86_64 station despite all the work from swiftgeek and his PKGBUILD commentators. But e4rat-lite did:

$ ll /var/lib/e4rat-lite/
total 104K
-rw-r--r-- 1 root 101K 21 juil. 22:15 startup.log

ShyPixie's version <https://github.com/ShyPixie/e4rat-lite>

I tested the build does work, but haven't yet found the time to make a PKGBUILD of it.

cubethethird · 2016-07-21 22:20:14

That's great to hear! Did it just work as-is, or did you need to modify/tweak anything?

kozaki · 2016-07-22 18:23:58

Starting with ShyPixie repo it worked straight out of the box with 'AUDIT=y' kernel and patched 'audit' here. In fact I had ~2k of movable files:

There's quite some diffs between his code and plain e4rat-0.2.3; all but seven as a matter of fact (singleton.hh, signals.hh, fileptr.hh, fileptr.cc, fiemap.hh, eventcatcher.hh, defrag.hh and buddycache.hh).

e4rat-lite from AUR archive links to a repo that disappeared so I can't compare these two.

Although it didn't work in this location, your article was the one who got me work out this $%@# e4rat incompatibility. Thank you for that @cuberthird!

Now it look as if IO access is *not* the bottleneck on my low-profile laptop, errr

cubethethird · 2016-07-22 18:52:26

Glad we found a resolution. Let me know if you end up making a new AUR package for this. If not I may do it myself when I get the time.

kozaki · 2016-07-24 01:39:37

Yeap, I may do the PKGBUILD the week that's coming, otherwise it'll be all yours.

Now it look as if IO access is *not* the bottleneck on my low-profile laptop, errr

Wrong impression! First realloc somehow was screwed, most probably the remaining amount of fragments was too high. I re-run it and this time (still with default e.g. 'defrag_mode'), got down to a few fragments:

Next step was to try e4rat-lite-preload a few times (it's supposed to reduce the IO wait by errr, preloading the wanted ~1100 files in RAM). Had a few serious applications to test that.

Before any optimization process, the tiny Atom monocore on Seagate Momentus 5400 took ~32" to cli and 40" to gui:

Now it's ~18 to cli and 20" to gui *ready*:

Long journey but I learned quite a bit in the process (e.g. on daemons, shell init, auditing the hardware bottlenecks, compiling). And Terminator-Dell mini now has LibreOffice loaded on cold boot in 35" from grub; or tmux + ranger in 20". Holy cow, how handy!
For GUI I achieved my goal; though I'd love to improve things a bit further for CLI sessions, but ain't Arjan van de Ven, Linux developer at Intel [1]

@cubethethird your paper was the initiator of this welcomed learning session. Now if you go back optimizing yours --which ain't that low pro and boots slower -- you may try to load your session a bit: I'm certain you'll appreciate that 'preload' powaa!

EDIT: +++ note:
[1]: http://lwn.net/Articles/299483/

Last edited by kozaki (2016-07-24 02:13:22)

cubethethird · 2016-07-24 01:50:26

Glad to see some good results. I'm definitely interested in re-exploring this with this alternate version of the package, especially since I've already done a lot of the ground work. I'll of course update my own post accordingly and provide new benchmarks. I'm pretty busy these days so I'll wait until either I have the time to submit to the AUR or wait for you to do it, whichever comes first.

cubethethird · 2016-07-28 02:15:45

Alright I've just pushed the package to the AUR under e4rat-lite-git. I based it on the original e4rat-lite PKGBUILD from the archives with some modifications. It will likely need some work, but for now it seems to be fine.

petejones · 2016-08-27 22:01:53

Edit: answered my own question.

Last edited by petejones (2016-08-27 22:13:19)

Arch Linux

#1 2016-04-02 03:02:59

Issue getting output from e4rat, and a workaround

#2 2016-07-14 21:45:15

Re: Issue getting output from e4rat, and a workaround

#3 2016-07-14 21:52:03

Re: Issue getting output from e4rat, and a workaround

#4 2016-07-14 22:05:46

Re: Issue getting output from e4rat, and a workaround

#5 2016-07-14 23:00:36

Re: Issue getting output from e4rat, and a workaround

#6 2016-07-18 00:51:46

Re: Issue getting output from e4rat, and a workaround

#7 2016-07-21 20:35:56

Re: Issue getting output from e4rat, and a workaround

#8 2016-07-21 22:20:14

Re: Issue getting output from e4rat, and a workaround

#9 2016-07-22 18:23:58

Re: Issue getting output from e4rat, and a workaround

#10 2016-07-22 18:52:26

Re: Issue getting output from e4rat, and a workaround

#11 2016-07-24 01:39:37

Re: Issue getting output from e4rat, and a workaround

#12 2016-07-24 01:50:26

Re: Issue getting output from e4rat, and a workaround

#13 2016-07-28 02:15:45

Re: Issue getting output from e4rat, and a workaround

#14 2016-08-27 22:01:53

Re: Issue getting output from e4rat, and a workaround

Board footer