udev: add basic set of user-space defined tracepoints (USDT)

Debugging udev issues especially during the early boot is fairly
difficult. Currently, you need to enable (at least) debug logging and
start monitoring uevents, try to reproduce the issue and then analyze
and correlate two (usually) huge log files. This is not ideal.

This patch aims to provide much more focused debugging tool,
tracepoints. More often then not we tend to have at least the basic idea
about the issue we are trying to debug further, e.g. we know it is
storage related. Hence all of the debug data generated for network
devices is useless, adds clutter to the log files and generally
slows things down.

Using this set of tracepoints you can start asking very specific
questions related to event processing for given device or subsystem.
Tracepoints can be used with various tracing tools but I will provide
examples using bpftrace.

Another important aspect to consider is that using tracepoints you can
debug production systems. There is no need to install test packages with
added logging, no debuginfo packages, etc...

Example usage (you might be asking such questions during the debug session),

Q: How can I list all tracepoints?
A: bpftrace -l 'usdt:/usr/lib/systemd/systemd-udevd:udev:*'

Q: What are the arguments for each tracepoint?
A: Look at the code and search for use of DEVICE_TRACE_POINT macro.

Q: How many times we have executed external binary?
A: bpftrace -e 'usdt:/usr/lib/systemd/systemd-udevd:udev:spawn_exec { @cnt = count(); }'

Q: What binaries where executed while handling events for "dm-0" device?
A  bpftrace -e 'usdt:/usr/lib/systemd/systemd-udevd:udev:spawn_exec / str(arg1) == "dm-0"/ { @cmds[str(arg4)] = count(); }'

Thanks to Thomas Weißschuh <thomas@t-8ch.de> for reviewing this patch
and contributions that allowed us to drop the dependency on dtrace tool
and made the resulting code much more concise.

diff --git a/meson.build b/meson.build
index a90c9b89e591dd60c9323d9bf777dfe5cdbada45..66db123c9305f0a860ac87557ceb6a2aeaf5049c 100644 (file)
--- a/meson.build
+++ b/meson.build
@@ -660,6 +660,7 @@ foreach header : ['crypt.h',
                   'valgrind/memcheck.h',
                   'valgrind/valgrind.h',
                   'linux/time_types.h',
+                  'sys/sdt.h',
                  ]
 
         conf.set10('HAVE_' + header.underscorify().to_upper(),

diff --git a/src/shared/udev-util.h b/src/shared/udev-util.h
index c2cf7caa67054ef025a4ff538b45eec3aef28cc6..d1c33b86a74d3666b2409ef4289d23f24761b6ca 100644 (file)
--- a/src/shared/udev-util.h
+++ b/src/shared/udev-util.h
@@ -1,6 +1,11 @@
 /* SPDX-License-Identifier: LGPL-2.1-or-later */
 #pragma once
 
+#if HAVE_SYS_SDT_H
+#define SDT_USE_VARIADIC
+#include <sys/sdt.h>
+#endif
+
 #include "sd-device.h"
 
 #include "time-util.h"
@@ -46,3 +51,30 @@ int udev_resolve_subsys_kernel(const char *string, char *result, size_t maxsize,
 
 int udev_queue_is_empty(void);
 int udev_queue_init(void);
+
+#if HAVE_SYS_SDT_H
+
+/* Each trace point can have different number of additional arguments. Note that when the macro is used only
+ * additional arguments are listed in the macro invocation!
+ *
+ * Default arguments for each trace point are as follows:
+ *   - arg0 - action
+ *   - arg1 - sysname
+ *   - arg2 - syspath
+ *   - arg3 - subsystem
+ */
+#define DEVICE_TRACE_POINT(name, dev, ...)                                                                 \
+        do {                                                                                               \
+                PROTECT_ERRNO;                                                                             \
+                const char *_n = NULL, *_p = NULL, *_s = NULL;                                             \
+                sd_device *_d = (dev);                                                                     \
+                sd_device_action_t _a = _SD_DEVICE_ACTION_INVALID;                                         \
+                (void) sd_device_get_action(_d, &_a);                                                      \
+                (void) sd_device_get_sysname(_d, &_n);                                                     \
+                (void) sd_device_get_syspath(_d, &_p);                                                     \
+                (void) sd_device_get_subsystem(_d, &_s);                                                   \
+                STAP_PROBEV(udev, name, device_action_to_string(_a), _n, _p, _s __VA_OPT__(,) __VA_ARGS__);\
+        } while(false);
+#else
+#define DEVICE_TRACE_POINT(name, dev, ...) ((void) 0)
+#endif

diff --git a/src/udev/udev-event.c b/src/udev/udev-event.c
index f40b3120ca5bce297efe9370a919779ebfbdef17..8a01e2512e35be6f425ab5591efef535f2a02110 100644 (file)
--- a/src/udev/udev-event.c
+++ b/src/udev/udev-event.c
@@ -603,6 +603,8 @@ static int on_spawn_timeout(sd_event_source *s, uint64_t usec, void *userdata) {
 
         assert(spawn);
 
+        DEVICE_TRACE_POINT(spawn_timeout, spawn->device, spawn->cmd);
+
         kill_and_sigcont(spawn->pid, spawn->timeout_signal);
 
         log_device_error(spawn->device, "Spawned process '%s' ["PID_FMT"] timed out after %s, killing",
@@ -648,6 +650,8 @@ static int on_spawn_sigchld(sd_event_source *s, const siginfo_t *si, void *userd
                 log_device_error(spawn->device, "Process '%s' failed due to unknown reason.", spawn->cmd);
         }
 
+        DEVICE_TRACE_POINT(spawn_exit, spawn->device, spawn->cmd);
+
         sd_event_exit(sd_event_source_get_event(s), ret);
         return 1;
 }
@@ -785,6 +789,8 @@ int udev_event_spawn(UdevEvent *event,
                 (void) close_all_fds(NULL, 0);
                 (void) rlimit_nofile_safe();
 
+                DEVICE_TRACE_POINT(spawn_exec, event->dev, cmd);
+
                 execve(argv[0], argv, envp);
                 _exit(EXIT_FAILURE);
         }
@@ -1014,10 +1020,14 @@ int udev_event_execute_rules(
                         return r;
         }
 
+        DEVICE_TRACE_POINT(rules_start, dev);
+
         r = udev_rules_apply_to_event(rules, event, timeout_usec, timeout_signal, properties_list);
         if (r < 0)
                 return log_device_debug_errno(dev, r, "Failed to apply udev rules: %m");
 
+        DEVICE_TRACE_POINT(rules_finished, dev);
+
         r = rename_netif(event);
         if (r < 0)
                 return r;

diff --git a/src/udev/udev-rules.c b/src/udev/udev-rules.c
index edf2c385bd4ec2834ea898589915cfe2040a7ebc..c37c86a5411cd1e6f83949eedf5ca2586d04f12e 100644 (file)
--- a/src/udev/udev-rules.c
+++ b/src/udev/udev-rules.c
@@ -29,6 +29,7 @@
 #include "udev-builtin.h"
 #include "udev-event.h"
 #include "udev-rules.h"
+#include "udev-util.h"
 #include "user-util.h"
 #include "virt.h"
 
@@ -2261,6 +2262,9 @@ static int udev_rule_apply_line_to_event(
                 return 0;
 
         event->esc = ESCAPE_UNSET;
+
+        DEVICE_TRACE_POINT(rules_apply_line, event->dev, line->rule_file->filename, line->line_number);
+
         LIST_FOREACH_SAFE(tokens, token, next_token, line->tokens) {
                 line->current_token = token;
 

diff --git a/src/udev/udevd.c b/src/udev/udevd.c
index 81d488a7047609a848e614bf94dffa8983bdb4be..13ac7c83b525d83f3d13f4dcad8e2fe066e16610 100644 (file)
--- a/src/udev/udevd.c
+++ b/src/udev/udevd.c
@@ -617,6 +617,8 @@ static int worker_spawn(Manager *manager, struct event *event) {
                 return log_error_errno(r, "Failed to fork() worker: %m");
         }
         if (r == 0) {
+                DEVICE_TRACE_POINT(worker_spawned, event->dev, getpid());
+
                 /* Worker process */
                 r = worker_main(manager, worker_monitor, sd_device_ref(event->dev));
                 log_close();
@@ -1045,6 +1047,8 @@ static int on_uevent(sd_device_monitor *monitor, sd_device *dev, void *userdata)
 
         assert(manager);
 
+        DEVICE_TRACE_POINT(kernel_uevent_received, dev);
+
         device_ensure_usec_initialized(dev, NULL);
 
         r = event_queue_insert(manager, dev);
@@ -1180,6 +1184,8 @@ static int synthesize_change_one(sd_device *dev, sd_device *target) {
         if (r < 0)
                 return log_device_debug_errno(target, r, "Failed to trigger 'change' uevent: %m");
 
+        DEVICE_TRACE_POINT(synthetic_change_event, dev);
+
         return 0;
 }