Thank you Lennart for the follow-up.
There does appear to be mostly filesystem operations prior to my
manually killing nspawn as you suggested. I only let it run about 3
minutes prior to sending a signal given that the strace output = ~25M.
One obvious issue is the non-zero return from an ioctl call with the
BTRFS_IOC_SUBVOL_CREATE arg at line 410, in the snippet below from my
RHEL9.0 strace capture; this is occurring right after the initial blast
of debug log messages. I'm trying to get a stack trace for that error
currently.
410-2064 ioctl(5, BTRFS_IOC_SUBVOL_CREATE, {fd=0,
name=".#machine.c8578d59f810b73d"}) = -1 ENOTTY (Inappropriate ioctl for
device)
...
Setting RLIMIT_SIGPENDING to 14657.
Setting RLIMIT_MSGQUEUE to 819200.
Setting RLIMIT_NICE to 0.
Setting RLIMIT_RTPRIO to 0.
Setting RLIMIT_RTTIME to infinity.
Found cgroup2 on/sys/fs/cgroup/, full unified hierarchy
...
With the last line above generated from line 395's writev below.
Unfortunately, I believe I left off the '-s 500' arg to strace. I can
run things again if that's a help.
toma@toma-MacBookPro:20220808$ grep -nA25 cgroup2
nspawn.rhel90.boot.strace.out
395:2064 writev(2, [{iov_base="Found cgroup2 on
/sys/fs/cgroup/"..., iov_len=56}, {iov_base="\n", iov_len=1}], 2) = 57
396-2064 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[],
sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f0298fb3db0}, NULL, 8) = 0
397-2064 umask(022) = 022
398-2064 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) =
3
399-2064 close(3) = 0
400-2064 getrandom("\x8c\x75\xd8\x95\x8f\x01\x7b\xd3", 8,
GRND_NONBLOCK|GRND_INSECURE) = 8
401-2064 newfstatat(AT_FDCWD, "/.#machine.c8578d59f810b73d",
0x7ffef92612a0, 0) = -1 ENOENT (No such file or directory)
402-2064 openat(AT_FDCWD, "/.#.#machine.c8578d59f810b73d.lck",
O_RDWR|O_CREAT|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC, 0600) =
3
403-2064 fcntl(3, F_OFD_SETLK,
{l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
404-2064 newfstatat(3, "",
{st_mode=S_IFREG|0600, st_size=0, ...}, AT_EMPTY_PATH) = 0
405-2064 rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
406-2064 openat(AT_FDCWD, "/", O_RDONLY|O_NOCTTY|O_CLOEXEC|O_DIRECTORY)
= 4
407-2064 newfstatat(4, "", {st_mode=S_IFDIR|0555, st_size=4096,
...}, AT_EMPTY_PATH) = 0
408-2064 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_DIRECTORY) = 5
409-2064 fcntl(5, F_GETFL) = 0x18000 (flags
O_RDONLY|O_LARGEFILE|O_DIRECTORY)
410-2064 ioctl(5, BTRFS_IOC_SUBVOL_CREATE, {fd=0,
name=".#machine.c8578d59f810b73d"}) = -1 ENOTTY (Inappropriate ioctl for
device)
411-2064 close(5) = 0
412-2064 mkdir("/.#machine.c8578d59f810b73d", 0755) = 0
413-2064 newfstatat(4, "", {st_mode=S_IFDIR|0555, st_size=4096,
...}, AT_EMPTY_PATH) = 0
414-2064 fcntl(4, F_DUPFD_CLOEXEC, 3) = 5
415-2064 getrandom("\x77\x72\x24\xdb\xb2\xcf\x6e\x46", 8,
GRND_NONBLOCK|GRND_INSECURE) = 8
416-2064 newfstatat(5, "", {st_mode=S_IFDIR|0555, st_size=4096,
...}, AT_EMPTY_PATH) = 0
417-2064 fcntl(5, F_GETFL) = 0x18000 (flags
O_RDONLY|O_LARGEFILE|O_DIRECTORY)
418-2064 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
419-2064 openat(AT_FDCWD, "/.#machine.c8578d59f810b73d",
O_RDONLY|O_CLOEXEC|O_DIRECTORY) = 6
420-2064 getdents64(6, 0x7ffef9260cc0 /* 2
entries */, 840) = 48
toma@toma-MacBookPro:20220808$
That failure leads to many repeated filesystem operations for each
resource, similar to the following except with differing file paths. As
you suggested that's the reason for the delay in spawning the container.
2297 newfstatat(7,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
{st_mode=S_IFDIR|0700, st_size=17, ...}, AT_SYMLINK_NOFOLLOW) = 0
2297 statx(7,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW|AT_NO_AUTOMOUNT, STATX_TYPE,
{stx_mask=STATX_BASIC_STA
TS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0700, stx_size=17,
...}) = 0
2297 openat(7,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC|O_DIRECTORY) =
9
2765d331699258-switcheroo-control.service-ZzjWeB>
2297
newfstatat(9,
"", {st_mode=S_IFDIR|0700, st_size=17, ...}, AT_EMPTY_PATH) = 0
2297
fcntl(9,
F_GETFL) = 0x38000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_DIRECTORY)
2297
fcntl(9,
F_SETFD, FD_CLOEXEC) = 0
2297 openat(8,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
O_RDONLY|O_CLOEXEC|O_DIRECTORY) = -1 ENOENT (No such file or directo
ry)
2297 mkdirat(8,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
0700) = 0
2297 openat(8,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC|O_DIRECTORY) = 10
