From: Michal Sekletár Date: Mon, 24 Aug 2020 09:21:44 +0000 (+0200) Subject: udev: add basic set of user-space defined tracepoints (USDT) X-Git-Tag: v249-rc1~10 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=b428efa54bc9f8851514c595f14020a99fcf62a7;p=thirdparty%2Fsystemd.git 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 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 a90c9b89e59..66db123c930 100644 --- 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 c2cf7caa670..d1c33b86a74 100644 --- 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 +#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 f40b3120ca5..8a01e2512e3 100644 --- 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 edf2c385bd4..c37c86a5411 100644 --- 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 81d488a7047..13ac7c83b52 100644 --- 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; }