[Date Prev][Date Next] [Thread Prev][Thread Next] [Date Index] [Thread Index]

Bug#1056344: libefivar1: sleeps for 10ms twice for every variable read



Package: libefivar1
Version: 38-2
Severity: normal

Dear Maintainer,

-- >8 --
$ strace efibootmgr
...
access("/sys/firmware/efi/efivars/", F_OK) = 0
statfs("/sys/firmware/efi/efivars/", {f_type=EFIVARFS_MAGIC, f_bsize=4096, f_blocks=0, f_bfree=0, f_bavail=0, f_files=0, f_ffree=0, f_fsid={val=[0, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_NOSUID|ST_NODEV|ST_NOEXEC|ST_RELATIME}) = 0
openat(AT_FDCWD, "/sys/firmware/efi/efivars/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=0, ...}, AT_EMPTY_PATH) = 0
fcntl(4, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
getdents64(4, 0x55cc6cbb7420 /* 55 entries */, 32768) = 3952
getdents64(4, 0x55cc6cbb7420 /* 0 entries */, 32768) = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0001-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\1\0\0\0\r\0U\0E\0F\0I\0:\0C\0D\0/\0D\0V\0D\0 \0D\0"..., 4096) = 55
read(4, "", 4041)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0002-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\1\0\0\0\r\0U\0E\0F\0I\0:\0R\0e\0m\0o\0v\0a\0b\0l\0"..., 4096) = 63
read(4, "", 4033)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0003-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\1\0\0\0\r\0U\0E\0F\0I\0:\0N\0e\0t\0w\0o\0r\0k\0 \0"..., 4096) = 59
read(4, "", 4037)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0004-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0\314\0D\0e\0b\0i\0a\0n\0 \0G\0N\0U\0/\0L\0i\0"..., 4096) = 686
read(4, "", 3410)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0005-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0\314\0D\0e\0b\0i\0a\0n\0 \0G\0N\0U\0/\0L\0i\0"..., 4096) = 686
read(4, "", 3410)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/BootNext-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = -1 ENOENT (No such file or directory)
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/BootCurrent-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\6\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\5\0", 4096)                   = 2
read(4, "", 4094)                       = 0
close(4)                                = 0
newfstatat(1, "", {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}, AT_EMPTY_PATH) = 0
write(1, "BootCurrent: 0005\n", 18)     = 18
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Timeout-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\1\0", 4096)                   = 2
read(4, "", 4094)                       = 0
close(4)                                = 0
write(1, "Timeout: 1 seconds\n", 19)    = 19
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/BootOrder-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\5\0\4\0\1\0\2\0\3\0", 4096)   = 10
read(4, "", 4086)                       = 0
close(4)                                = 0
write(1, "BootOrder: 0005,0004,0001,0002,0"..., 36) = 36
write(1, "Boot0001* UEFI:CD/DVD Drive\tBBS("..., 42) = 42
write(1, "Boot0002* UEFI:Removable Device\t"..., 46) = 46
write(1, "Boot0003* UEFI:Network Device\tBB"..., 44) = 44
write(1, "Boot0004* Debian GNU/Linux trixi"..., 947) = 947
write(1, "Boot0005* Debian GNU/Linux trixi"..., 947) = 947
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/MirrorCurrent-7b9be2e0-e28a-4197-ad3e-32f062f9462c", O_RDONLY) = -1 ENOENT (No such file or directory)
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/MirrorRequest-7b9be2e0-e28a-4197-ad3e-32f062f9462c", O_RDONLY) = -1 ENOENT (No such file or directory)
close(3)                                = 0
-- >8 --
and time of the same is
  real    0m0.194s
  user    0m0.000s
  sys     0m0.007s

Similarly,
-- >8 --
$ time KLAPKI_HOST=$mid klapki -nEEEEEEEE
...
creator.c:393 efi_generate_file_device_path(): child_devpath:/dev/nvme0n1p1
creator.c:395 efi_generate_file_device_path(): parent_devpath:/dev/nvme0n1
creator.c:396 efi_generate_file_device_path(): child_devpath:/dev/nvme0n1p1
creator.c:397 efi_generate_file_device_path(): rc:0
context.save(): Making device path for ESP: Permission denied

real    0m0.383s
user    0m0.026s
sys     0m0.025s
-- >8 --
(this is with verbosity level 6, and I think libefivar tops out at 2):
there are other warnings formatted so debug logging works,
and no "hey you have a shitty firmware so I'm sleeping"
(and, indeed, this doens't appear to be necessary:
   # time wc /sys/firmware/efi/efivars/*
   ...
       0     2   148 /sys/firmware/efi/efivars/SignatureSupport-8be4df61-93ca-11d2-aa0d-00e098032b8c
       0     1    12 /sys/firmware/efi/efivars/SmbiosEntryPointTable-4b3082a3-80c6-4d7e-9cd0-583917265df1
       0     1    12 /sys/firmware/efi/efivars/SmbiosScratchBuffer-4b3082a3-80c6-4d7e-9cd0-583917265df1
       0     1    12 /sys/firmware/efi/efivars/SmbiosV3EntryPointTable-4b3082a3-80c6-4d7e-9cd0-583917265df1
       0     0     5 /sys/firmware/efi/efivars/SOFTWAREGUARDSTATUS-9cb2e73f-7325-40f4-a484-659bb344c3cd
       0     0     6 /sys/firmware/efi/efivars/TbtHRStatusVar-ba1d893b-803e-4b26-a3de-585703ff7bd6
       0     0     6 /sys/firmware/efi/efivars/Timeout-8be4df61-93ca-11d2-aa0d-00e098032b8c
       0     0     5 /sys/firmware/efi/efivars/VendorKeys-8be4df61-93ca-11d2-aa0d-00e098032b8c
       0     0    68 /sys/firmware/efi/efivars/WriteOnceStatus-4b3082a3-80c6-4d7e-9cd0-583917265df1
      73   470 16418 total
   
   real    0m0.084s
   user    0m0.006s
   sys     0m0.005s
 and the BootNNNN/BootOrder entries are as-written)
and strace says
-- >8 --
openat(AT_FDCWD, "/dev/null", O_WRONLY|O_APPEND|O_CLOEXEC) = 3
getrandom("\xac\xea\x2a\x2c\x98\x5b\x8e\x37", 8, 0) = 8
access("/sys/firmware/efi/efivars/", F_OK) = 0
statfs("/sys/firmware/efi/efivars/", {f_type=EFIVARFS_MAGIC, f_bsize=4096, f_blocks=0, f_bfree=0, f_bavail=0, f_files=0, f_ffree=0, f_fsid={val=[0, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_NOSUID|ST_NODEV|ST_NOEXEC|ST_RELATIME}) = 0
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 4
newfstatat(4, "", {st_mode=S_IFREG|0644, st_size=8555216, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 8555216, PROT_READ, MAP_PRIVATE, 4, 0) = 0x7f46a9955000
close(4)                                = 0
newfstatat(AT_FDCWD, "/boot", {st_mode=S_IFDIR|0755, st_size=11, ...}, 0) = 0
newfstatat(AT_FDCWD, "/boot/efi", {st_mode=S_IFDIR|0755, st_size=1536, ...}, 0) = 0
openat(AT_FDCWD, "/etc/klapki/efi-root", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/sys/firmware/efi/efivars/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=0, ...}, AT_EMPTY_PATH) = 0
fcntl(4, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
getdents64(4, 0x562fb72b97e0 /* 55 entries */, 32768) = 3952
getdents64(4, 0x562fb72b97e0 /* 0 entries */, 32768) = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/BootOrder-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\5\0\4\0\1\0\2\0\3\0", 4096)   = 10
read(4, "", 4086)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0003-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\1\0\0\0\r\0U\0E\0F\0I\0:\0N\0e\0t\0w\0o\0r\0k\0 \0"..., 4096) = 59
read(4, "", 4037)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0002-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\1\0\0\0\r\0U\0E\0F\0I\0:\0R\0e\0m\0o\0v\0a\0b\0l\0"..., 4096) = 63
read(4, "", 4033)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0001-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\1\0\0\0\r\0U\0E\0F\0I\0:\0C\0D\0/\0D\0V\0D\0 \0D\0"..., 4096) = 55
read(4, "", 4041)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0005-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0\314\0D\0e\0b\0i\0a\0n\0 \0G\0N\0U\0/\0L\0i\0"..., 4096) = 686
read(4, "", 3410)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/Boot0004-8be4df61-93ca-11d2-aa0d-00e098032b8c", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0\314\0D\0e\0b\0i\0a\0n\0 \0G\0N\0U\0/\0L\0i\0"..., 4096) = 686
read(4, "", 3410)                       = 0
close(4)                                = 0
geteuid()                               = 1000
openat(AT_FDCWD, "/sys/firmware/efi/efivars/731b69f0dac147efadfed92f12712736-a8a9ad3a-f831-11ea-946d-674ccd7415cc", O_RDONLY) = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\7\0\0\0", 4)                  = 4
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=10000000}, NULL) = 0
read(4, "\0\0break\0\0\0\4\374\264\240\3027\231\v\264V8t\371\245\214\200\203\237\205f\3076"..., 4096) = 363
read(4, "", 3733)                       = 0
close(4)                                = 0
openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 4
-- >8 --
which is 14 10ms sleeps, which by itself accounts for 36% of the run-time.

For the case of efibootmgr above, that's 16 of them(!)
and they account for 82% of the run-time!

There is no need for this in the general case (clearly, since it's a
filesystem you can read correctly with cat), and I scarcely believe
there are specific cases that do need it. Please remove this.

Best,
наб

-- System Information:
Debian Release: trixie/sid
  APT prefers unstable-debug
  APT policy: (500, 'unstable-debug'), (500, 'unstable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 6.1.0-9-amd64 (SMP w/8 CPU threads; PREEMPT)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_OOT_MODULE
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages libefivar1 depends on:
ii  libc6  2.37-12

libefivar1 recommends no packages.

libefivar1 suggests no packages.

-- no debconf information

Attachment: signature.asc
Description: PGP signature


Reply to: