Post B8AiAcxB3eVKO3CXoG by cks@mastodon.social
(DIR) More posts by cks@mastodon.social
(DIR) Post #B8AeEC1mi2M0DhnjRw by cks@mastodon.social
0 likes, 0 repeats
Today's mystery: on exactly one system (with shared NFS home directories), logins take 3+ seconds to start because '/usr/lib/systemd/systemd --user' sits on its hands between running systemd-xdg-autostart-generator and running the next step of a remarkably opaque login process.I don't even know where to start and I only got this far with a hacked version of the great extrace¹ that also reports a process start time number.¹ https://github.com/leahneukirchen/extrace (seriously, sysadmins, get a copy today)
(DIR) Post #B8AeECZofVZlvFiuUi by wolf480pl@mstdn.io
0 likes, 0 repeats
@cksyou could probably drill down further by either:- tracing functions inside systemd using uprobes - eg. through bpftrace or iovisor/bcc- tracing syscalls - either with tools mentioned above, or even manually by toggling flags in /sys/kernel/tracing and cat-ting the trace pipehowever, if I was to guess, it's DNS
(DIR) Post #B8Aeg4EdHBNW9x6ONk by cks@mastodon.social
0 likes, 0 repeats
@wolf480pl The machine has our standard DNS configuration and everything appears healthy on it. (And the network speed and etc are the same as everything else.)
(DIR) Post #B8Af83cj8uYgN6idJg by wolf480pl@mstdn.io
0 likes, 0 repeats
@cks this was a wild guess, and the following may be a wild goose chase, but:it has different hostname than the other ones, right?What happens if yougetent hosts $(hostname)?
(DIR) Post #B8AgBOSAFs8tnRvtlw by cks@mastodon.social
0 likes, 0 repeats
@wolf480pl On all of our machines this only reports link-local IPv6 addresses for local reasons. If I use the fully qualified name it gets the right IPv4 address.
(DIR) Post #B8AgKpcKd4s8eOBmL2 by wolf480pl@mstdn.io
0 likes, 0 repeats
@cks ok but in both cases it resolves instantly?
(DIR) Post #B8Agfhc3aJWZuG0pYu by cks@mastodon.social
0 likes, 0 repeats
@wolf480pl Yes, instant resolution (and 'resolvectl query' resolves instantly, and the resolvectl settings are the same; we're using systemd-resolved since that's the 26.04 Ubuntu LTS default).
(DIR) Post #B8Ah7G6bRwp2hbRLIu by wolf480pl@mstdn.io
0 likes, 0 repeats
@cks if getent returns instantly then I wouldn't dig further into DNS and just find the relevant functions in the source code and use bpftrace with uprobes to see where it gets stuck.Or you could try to catch it with gcore when its stuck, then open the coredump with gdb and show stack trace.Both require debug symbols though.
(DIR) Post #B8AhE5TxLTqFmWcSvo by wolf480pl@mstdn.io
0 likes, 0 repeats
@cks btw you got me quite curious what's causing the issue, but lmk if I'm too pushy and you want me to leave you alone.
(DIR) Post #B8AiAcxB3eVKO3CXoG by cks@mastodon.social
0 likes, 0 repeats
@wolf480pl The problem with tracing 'systemd --user' in this situation is that it is started transiently in a complicated chain of things, and of course systemd itself is running as PID 1 already so any tracing of 'systemd' in general instead of a specific instance is going to be very messy.As for reading the systemd source to trace this ... aha ahem. That is a project far bigger than I have any interest in tackling.(Ubuntu makes debugging symbols available if you try hard, but.)
(DIR) Post #B8Al7E5nKl8aH9ImUS by cks@mastodon.social
0 likes, 0 repeats
@wolf480pl An extra complication is that this specific server that this happens on is in production so I cannot just do random things on it, everything has to be non-intrusive and small.
(DIR) Post #B8Al7EGmftvapERYcS by wolf480pl@mstdn.io
0 likes, 0 repeats
@cks ok so in terms of code, I think this is what runs generators, including systemd-xdg-autostart-generator:https://github.com/systemd/systemd/blob/main/src/core/manager.c#L2166There's another place where manager_run_environment_generators() is called but that's in manager_reload but I'd be surprised if that one ran during startup.Note that this is a link to the main branch, you should probably check which version you're running and switch to the right git tag before browsing the source code further.1/
(DIR) Post #B8AlFt9EZfxrvK2buC by wolf480pl@mstdn.io
0 likes, 0 repeats
@cks What I noticed in that code is that systemd records timestamps before and after running the generators, and it does that with other steps too.It seems these timings can be extracted with `systemd-analyze --user dump`. That'd at least indicate if the 3s wait is inside the manager_run_environment_generators() function or in some later step.2/
(DIR) Post #B8AlYB20p3zUbJNr5U by wolf480pl@mstdn.io
0 likes, 0 repeats
@cks Also, regarding "transient process, difficult to trace" - you could eg./ comm == "systemd" && pid != 1 /in bpftrace syntax, or sth equivalent with other tools.As for the gcore method, you don't need to catch the start, you're trying to catch the part where it spends the most time. Anywhere within the 3s window will do, and it seems gcore can dump multiple PIDs at once, when given as separate args, sogcore $(pidof systemd)and then picking the right coredump should work.
(DIR) Post #B8Apz8QuzTwUB58x7o by JdeBP@tty0.social
0 likes, 0 repeats
@wolf480pl @cks Nah. With per-user service management it is far more likely to be D-Bus. It could be a D-Bus service failing, or not present, or not starting properly; or even a problem with the per-user broker.Crank up your D-Bus monitor.#systemd
(DIR) Post #B8Ar1nb90lCSNjlE9Y by cks@mastodon.social
0 likes, 0 repeats
@wolf480pl Well hmm, there's clearly a Problem here, according to --user dump, where loading units is very slow (despite sub-processes finishing right away):Timestamp units-load-start: Thu 2026-07-09 18:40:30 EDTTimestamp units-load-finish: Thu 2026-07-09 18:40:33 EDT
(DIR) Post #B8Av5BvFQkD2VX2MMq by wolf480pl@mstdn.io
0 likes, 0 repeats
@cks that'd be manager_enumerate_perpetual or manager_enumerate:https://github.com/systemd/systemd/blob/main/src/core/manager.c#L2191-L2194but I'm a bit confused what these two do - they seem to call .enumerate and .enumerate_perpetual method on all unit types, but it seems only the weird unit types have those? I couldn't find one for eg. Service :/
(DIR) Post #B8C3Xk7Et48DSLjOSm by cks@mastodon.social
0 likes, 0 repeats
@JdeBP @wolf480pl Unfortunately I'm not sure how to monitor D-Bus here, especially if it's a session D-Bus. There doesn't seem to be anything getting logged (either system-wide or in the user journal).
(DIR) Post #B8C3XkLm11l2BQX07M by JdeBP@tty0.social
0 likes, 0 repeats
@cks You should have this:https://manpages.ubuntu.com/manpages/resolute/man1/dbus-monitor.1.htmlIf it cannot connect, in a session for the relevant user, without tweaking the DBUS_SESSION_BUS_ADDRESS environment variable, or at all, then that might well be the problem. (-:@wolf480pl #systemd #DesktopBus
(DIR) Post #B8C3XkZxAJ6GtPAKDg by cks@mastodon.social
0 likes, 0 repeats
@JdeBP @wolf480pl I implicitly left out a detail: this only happens when 'systemd --user' is starting up. If you already have a session (eg through another login), everything is fast. Unfortunately this means that when the problem happens, there is no user session D-Bus bus at the start for dbus-monitor to monitor.(I'm not sure the session D-Bus has been created when the stall happens.)
(DIR) Post #B8C3XkmMQB1bVsyEYi by wolf480pl@mstdn.io
0 likes, 0 repeats
@ckshow about:while true; do dbus-monitor --address /run/user/<uid>/bus; done@JdeBP
(DIR) Post #B8C3hcfRR187FeRLk0 by wolf480pl@mstdn.io
0 likes, 0 repeats
@cksand if session bus doesn't exist at the time of the delay, then it can't be causing the delay, so you'd at most have to monitor the system bus@JdeBP
(DIR) Post #B8CEREG9VvcmPjzrl2 by cks@mastodon.social
0 likes, 0 repeats
@wolf480pl @JdeBP Based on when /run/user/<uid>/bus was created versus 'systemd-analyze --user dump' times, the bus was created after the delay (which is not unreasonable if systemd is loading units before creating the bus and the loading is what's slow for some reason).