A discharge story

Estimated reading time: 5 minutes

A few weeks ago, I was at a friend’s, and started up my custom IRC client to get in touch with someone. An hour or so later, my battery was already almost depleted, though I usually get many hours of battery life with this laptop.

I don’t usually go on IRC when traveling with my laptop, that’s why I thought something was wrong about it.

To investigate the issue, I used the powertop utility, here is a screenshot of it with the IRC client running.

From this screenshot we can see that the pty irc-read -n +1 -f out process is waking the CPU a lot (nearly 600 times per second). This prevents it from going into deeper sleep modes, thus consuming more energy overall.

This little program is indeed a part of my IRC client, you can see its source code right here.

To understand what was going wrong, I used strace on one instance of this program, and found out that the tail utility was behaving strangely.

stitch:~$ strace -p 4738
strace: Process 4738 attached
restart_syscall(<... resuming interrupted nanosleep ...>) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=589, ...}) = 0
lseek(3, 0, SEEK_CUR)                   = 589
read(3, "", 1024)                       = 0
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe37c0ba60) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=589, ...}) = 0
lseek(3, 0, SEEK_CUR)                   = 589
read(3, "", 1024)                       = 0
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe37c0ba60) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=589, ...}) = 0
lseek(3, 0, SEEK_CUR)                   = 589
read(3, "", 1024)                       = 0
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe37c0ba60) = 0
…

What this trace reveals is that tail -f works by seeking to where we were in the file since last time and reading what’s new, every second (nanosleep with tv_sec = 1 and tv_nsec = 0). This effectively wakes up the CPU once per second for every IRC channel I’m in, as one irc-read process is running per IRC channel.

I wasn’t happy with tail -f polling for changes every seconds like that since there are better solutions available. That’s why I wrote my own version of tail -f, using the CHICKEN language and the inotify bindings wasamasa wrote a few weeks ago.

Here is the source code of my implementation:

;; tailf.scm
(use inotify utils)

(init!)
(on-exit clean-up!)

(define path (car (command-line-arguments)))
(add-watch! path '(modify))

(with-input-from-file path
  (lambda ()
    (let loop ()
      (display (read-all))
      (flush-output)
      (next-event!)
      (set-file-position! (current-input-port) 0 seek/cur)
      (loop))))

As you can see, it’s a very tiny program. Here I use inotify to wake the program as soon as the watched file is modified, I then seek to where I’m in the file (to avoid reading the end-of-file marker) and read everything that was added from here.

Sadly that wasn’t enough, tail was just a red herring, another process was waking the CPU up a lot more. This program was pty, a little utility from the Ma text editor, that makes it behave like a terminal emulator.

Lets look at his system calls trace:

stitch:~$ strace -p 4668
strace: Process 4668 attached
restart_syscall(<... resuming interrupted nanosleep ...>) = 0
poll([{fd=0, events=POLLIN}, {fd=3, events=POLLOUT}], 2, 100) = 1 ([{fd=3, revents=POLLOUT}])
read(3, 0x7fff4a4f5290, 1023)           = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({tv_sec=0, tv_nsec=10000000}, 0x7fff4a4f51c0) = 0
poll([{fd=0, events=POLLIN}, {fd=3, events=POLLOUT}], 2, 100) = 1 ([{fd=3, revents=POLLOUT}])
read(3, 0x7fff4a4f5290, 1023)           = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({tv_sec=0, tv_nsec=10000000}, 0x7fff4a4f51c0) = 0
poll([{fd=0, events=POLLIN}, {fd=3, events=POLLOUT}], 2, 100) = 1 ([{fd=3, revents=POLLOUT}])
read(3, 0x7fff4a4f5290, 1023)           = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({tv_sec=0, tv_nsec=10000000}, 0x7fff4a4f51c0) = 0
…

Looks oddly familiar, right? Though this one wakes up the CPU every 10 milliseconds! (nanosleep with tv_nsec = 10000000).

It took me a while to understand what was wrong there, I didn’t understand why poll() was returning an event for fd 3, and reading from it was returning EAGAIN… The problem here is a bug of the pty utility! It tries to read from a file descriptor when poll() tells the program that the file descriptor is ready for writing!

I made a little patch to fix this issue and make the program work without non-blocking file descriptors, and all is well now! :D (here is the current code)