efivars: log whenever an EFI variable read access is slow

This should allow us to detect slowdowns caused by EFI variable read
access a bit.

diff --git a/src/basic/efivars.c b/src/basic/efivars.c
index b34df46926cded800f722a74414d67ade510ab0b..6b6f461446d2cc866257d1be5902b15fe280d7ed 100644 (file)
--- a/src/basic/efivars.c
+++ b/src/basic/efivars.c
@@ -50,6 +50,7 @@ int efi_get_variable(
         _cleanup_free_ char *p = NULL;
         _cleanup_free_ void *buf = NULL;
         struct stat st;
+        usec_t begin;
         uint32_t a;
         ssize_t n;
 
@@ -68,6 +69,9 @@ int efi_get_variable(
                 return 0;
         }
 
+        if (DEBUG_LOGGING)
+                begin = now(CLOCK_MONOTONIC);
+
         fd = open(p, O_RDONLY|O_NOCTTY|O_CLOEXEC);
         if (fd < 0)
                 return log_debug_errno(errno, "open(\"%s\") failed: %m", p);
@@ -121,6 +125,16 @@ int efi_get_variable(
                 /* Assume that the reported size is accurate */
                 n = st.st_size - 4;
 
+        if (DEBUG_LOGGING) {
+                char ts[FORMAT_TIMESPAN_MAX];
+                usec_t end;
+
+                end = now(CLOCK_MONOTONIC);
+                if (end > begin + EFI_RETRY_DELAY)
+                        log_debug("Detected slow EFI variable read access on " SD_ID128_FORMAT_STR "-%s: %s",
+                                  SD_ID128_FORMAT_VAL(vendor), name, format_timespan(ts, sizeof(ts), end - begin, 1));
+        }
+
         /* Note that efivarfs interestingly doesn't require ftruncate() to update an existing EFI variable
          * with a smaller value. */