Subject: ‘fdatasync’ on cached narinfo files is too expensive

From: Ludovic Courtès <[email-masked]>
Date: Mon, 07 Apr 2025 12:20:26 +0200

Hello,

As Christopher Baines reported on IRC, calling ‘fdatasync’ on each
cached narinfo under /var/guix/substitute/cache can be unreasonably
expensive on spinning disks.

On bayfront, when tracing ‘guix substitute’ processes, we observe
‘fdatasync’ occasionally taking more than a second, and typically taking
more than 0.2s:

--8<---------------cut here---------------start------------->8---
mkdir("/var", 0777)                     = -1 EEXIST (File exists) <0.000048>
mkdir("/var/guix", 0777)                = -1 EEXIST (File exists) <0.000042>
mkdir("/var/guix/substitute", 0777)     = -1 EEXIST (File exists) <0.000040>
mkdir("/var/guix/substitute/cache", 0777) = -1 EEXIST (File exists) <0.000042>
mkdir("/var/guix/substitute/cache/kzwjeblndsbkjzmjailrt4bnhguil7tqjmewzcyw22hgajbhfy3q", 0777) = -1 EEXIST (File exists
) <0.000041>
clock_gettime(CLOCK_MONOTONIC, {tv_sec=153237, tv_nsec=595042938}) = 0 <0.000037>
openat(AT_FDCWD, "/var/guix/substitute/cache/kzwjeblndsbkjzmjailrt4bnhguil7tqjmewzcyw22hgajbhfy3q/nfmn2nkfjz5kzklw165aj
6ilwphw9zrz.3kAGMM", O_RDWR|O_CREAT|O_EXCL, 0600) = 15 <0.000123>
fstat(15, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0 <0.000037>
lseek(15, 0, SEEK_CUR)                  = 0 <0.000038>
write(15, "(narinfo (version 2) (cache-uri "..., 1066) = 1066 <0.000071>
fdatasync(15)                           = 0 <1.860604>
--8<---------------cut here---------------end--------------->8---

A longer sample:

--8<---------------cut here---------------start------------->8---
ludo@bayfront ~$ grep ^fdatasync log.strace 
fdatasync(15)                           = 0 <1.860604>
fdatasync(15)                           = 0 <1.101868>
fdatasync(15)                           = 0 <0.464357>
fdatasync(15)                           = 0 <0.363363>
fdatasync(15)                           = 0 <0.307759>
fdatasync(15)                           = 0 <0.619979>
fdatasync(15)                           = 0 <0.269880>
fdatasync(15)                           = 0 <0.274093>
fdatasync(15)                           = 0 <0.247207>
fdatasync(15)                           = 0 <0.367507>
fdatasync(15)                           = 0 <0.212277>
fdatasync(15)                           = 0 <0.234929>
fdatasync(15)                           = 0 <0.330697>
fdatasync(15)                           = 0 <0.193925>
fdatasync(15)                           = 0 <0.251554>
fdatasync(15)                           = 0 <0.379571>
--8<---------------cut here---------------end--------------->8---

That call comes from ‘with-atomic-file-output’, commit
1752a17a1e6f7138892eeeb4806cd04ccb3ca1b0, which refers to this
discussion:

  https://lists.gnu.org/archive/html/guix-devel/2016-06/msg00456.html

It probably makes sense in some uses of ‘with-atomic-file-output’, but
nor for a cache as is the case here.

Ludo’.