systemd-hwdb issues excessive number of ioctl calls

[stapelberg]

systemd version / distribution the issue has been seen with systemd 244 on Arch Linux

Also reproducible with systemd 245 on a custom LFS-like system.

Unexpected behaviour you saw

# strace -fc systemd-hwdb update
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97,48    0,439383           1    293180    293180 ioctl
  0,81    0,003657           1      1993           write
[…]

A closer look reveals that read_line_full reads one character at a time and apparently calls isatty, which calls e.g. ioctl(3</usr/lib/udev/hwdb.d/20-vmbus-class.hwdb>, TCGETS, 0x7ffda3b73790) = -1 ENOTTY (Inappropriate ioctl for device).

On in-kernel file systems, the ioctls won’t even cause a perceptible slowdown, but when having the root file system on FUSE, the ioctl calls cause a multi-second delay in system boot.

Steps to reproduce the problem

1. strace -fc systemd-hwdb update

[poettering]

we just use fgetc() in a loop, enclosed in flockfile(). It's a usecase fgetc() was designed for really. We also call isatty(), only once per invocation. Which hence means once per line we read.

Note that systemd-hwdb update isn't something that should run all the time, it should be needed only when the database actually changed, or the database was never built, i.e. during OS upgrades and first boots...

And let me say, running an OS off fuse sounds, uh, like you are asking for trouble in particular when it comes to performance, no?

[stapelberg]

We also call isatty(), only once per invocation.

Are you sure that it’s only called once per invocation? It seems like it might be called once per character. At least that’s what my strace suggests :)

Note that systemd-hwdb update isn't something that should run all the time, it should be needed only when the database actually changed, or the database was never built, i.e. during OS upgrades and first boots...

Yes, I understand. This issue slows down the first boot after creating a new OS image, i.e. when the db is first generated.

And let me say, running an OS off fuse sounds, uh, like you are asking for trouble in particular when it comes to performance, no?

Nah, it’s fine in practice, at least for my use-case.

[poettering]

My straces on test-fileio show isatty() is called once per line...

I mean, we could play games, and before calling isatty() call fstat() and only bother if isatty() if the returned st_mode passes S_ISCHR(), but that's a weird optimization for FUSE only, i.e. encoding that on FUSE ioctls are a heavy round trip while stat is not, but that just sounds awfully specific to some current performance characteristic of today's fuse and nothing that has a future, necessarily...

[stapelberg]

My straces on test-fileio show isatty() is called once per line...

Sorry, you’re right. systemd-hwdb just reads a lot of lines :) The biggest files in terms of lines seem to be: 102591 /usr/lib/udev/hwdb.d/20-OUI.hwdb 95397 /usr/lib/udev/hwdb.d/20-pci-vendor-model.hwdb 60480 /usr/lib/udev/hwdb.d/20-usb-vendor-model.hwdb

I mean, we could play games, and before calling isatty() call fstat() and only bother if isatty() if the returned st_mode passes S_ISCHR(),

Alternatively, we could:

1. Call isatty() once per file descriptor at most, keeping per-file descriptor state somewhere.
2. Make systemd-hwdb use an alternative version of read_line which is meant only for regular files (not stdin) and never calls isatty.

but that's a weird optimization for FUSE only, i.e. encoding that on FUSE ioctls are a heavy round trip while stat is not, but that just sounds awfully specific to some current performance characteristic of today's fuse and nothing that has a future, necessarily...

While the performance issue manifests itself most severely when FUSE is involved, I would be surprised if eliminating ≈275k syscalls didn’t make a dent in systemd-hwdb’s wall-clock time on many machines, particularly slower PCs or embedded devices.

In fact, even when testing on my top-of-the-line i9-9900K, I can clearly measure the difference between calling isatty and not calling it:

% time sudo ./systemd-hwdb update 
0,31s user 0,05s system 93% cpu 0,375 total

with isatty: 0.369s avg (n=5) without isatty: 0.284s avg (n=5)

Hence, I think this is worthwhile regardless of FUSE.

[poettering]

I figure #15417 should fix your issue then? ptal!

[stapelberg]

I figure #15417 should fix your issue then? ptal!

Yes! I can confirm this removes the ioctls and hence system startup delay for me.

Thanks very much for the quick fix!