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</dev/pts/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</dev/pts/0>, [{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</.#.#machine.c8578d59f810b73d.lck>
403-2064 fcntl(3</.#.#machine.c8578d59f810b73d.lck>, F_OFD_SETLK,
{l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
404-2064 newfstatat(3</.#.#machine.c8578d59f810b73d.lck>, "",
{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</dev/pts/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</.#machine.c8578d59f810b73d>
420-2064 getdents64(6</.#machine.c8578d59f810b73d>, 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</tmp>,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
{st_mode=S_IFDIR|0700, st_size=17, ...}, AT_SYMLINK_NOFOLLOW) = 0
2297 statx(7</tmp>,
"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</tmp>,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC|O_DIRECTORY) =
9</tmp/systemd-private-ceff107148c24952bc
2765d331699258-switcheroo-control.service-ZzjWeB>
2297
newfstatat(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>,
"", {st_mode=S_IFDIR|0700, st_size=17, ...}, AT_EMPTY_PATH) = 0
2297
fcntl(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>,
F_GETFL) = 0x38000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_DIRECTORY)
2297
fcntl(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>,
F_SETFD, FD_CLOEXEC) = 0
2297 openat(8</.#machine.556acffc5c4193f9/tmp>,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
O_RDONLY|O_CLOEXEC|O_DIRECTORY) = -1 ENOENT (No such file or directo
ry)
2297 mkdirat(8</.#machine.556acffc5c4193f9/tmp>,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
0700) = 0
2297 openat(8</.#machine.556acffc5c4193f9/tmp>,
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB",
O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC|O_DIRECTORY) = 10</.#machine.
556acffc5c4193f9/tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>
2297
getdents64(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>,
0x55f6b5181f00 /* 3 entries */, 32768) = 72
2297 rt_sigtimedwait([INT], NULL, {tv_sec=0, tv_nsec=0}, 8) = -1 EAGAIN
(Resource temporarily unavailable)
2297
newfstatat(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>,
"tmp", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=6, ...},
AT_SYMLINK_NOFOLLOW) = 0
2297
statx(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>,
"tmp", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW|AT_NO_AUTOMOUNT,
STATX_TYPE, {stx_mask=STATX_BASIC
_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|S_ISVTX|0777,
stx_size=6, ...}) = 0
2297
openat(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>,
"tmp", O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC|O_DIRECTORY) =
11</tmp/systemd-private-ceff107148c24
952bc2765d331699258-switcheroo-control.service-ZzjWeB/tmp>
2297
newfstatat(11</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB/tmp>,
"", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=6, ...}, AT_EMPTY_PATH) = 0
2297
fcntl(11</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB/tmp>,
F_GETFL) = 0x38000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_DIRECTORY)
2297
fcntl(11</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB/tmp>,
F_SETFD, FD_CLOEXEC) = 0
2297
openat(10</.#machine.556acffc5c4193f9/tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>,
"tmp", O_RDONLY|O_CLOEXEC|O_DIRECTORY) = -1 ENOENT (No such file or di
rectory)
Any thoughts, or comments are appreciated.
Regards,
-Tom
PS and fwiw: systemd version 250, Linux 5.14.0-70.17.1.el9_0.x86_64,
over xfs.
On 8/4/22 16:49, Lennart Poettering wrote:
On Do, 04.08.22 13:30, Thomas Archambault (toma@xxxxxxxxxxxxxxxxx) wrote:
Following up on xfs and reflinks, it appears they are enabled on my
out-of-box RHEL9.0. Fwiw, this is a VBox VM however so if the FC34 system
which works correctly, but is using btrfs.
As always, appreciate any help/references.
Try straceing nspawn, to see what it does.
strace -f -y -s 500 -o /tmp/nspawnstrace.log systemd-nspawn …
Then look at the generated log and see what is busy doing... If unsure
paste things somewhre.
Lennart
--
Lennart Poettering, Berlin
