X applications load window content w/ 30sec delay (SOLVED)

bencze · 2023-06-14 07:11:55

I use a thinkpad p14s gen2 amd.
It's hard to describe an Arch install (I'm a newbie so just followed some guides), but essentially I'm using X, with lightdm, i3, and picom.

For most applications, I start something (for example Thunar, file manager). The application borders and titlebar load (just system default graphics, like black background), and it takes about 30 seconds for the application specific graphics to load (window contents like background, graphics, buttons). I have previously used similar Arch config, I also use i3wm on Manjaro on my desktop, and never had this problem so I'm assuming I did something wrong with this install but not sure how to troubleshoot. I don't see any errors in logs that I can identify (/var/log directory, or journalctl, but I don't know how to work systemd).
If I start the application from the terminal, there's no error either. It's almost every app, but interestingly chromium loads fine, but firefox and most other apps don't, they all exhibit the above behavior.
Any suggestions please?

edit: I ended up cleaning up everything sound and use pulseaudio just for the sake of not experimenting with pipewire now as sound i ssomething i clearl don't understand. The 'solution' I was looking for was mainly identifying the weird and annoying behaviour.

Last edited by bencze (2023-06-30 09:05:42)

seth · 2023-06-14 07:40:47

Sounds like a dbus timeout (25s, not 30s?) and the current offender is https://archlinux.org/packages/extra/x8 … tal-gnome/ which doesn't work outside gnome and gets in the way.
If removing that package doesn't solve it, please try w/o picom first and then post your complete system journal for the boot:

sudo journalctl -b | curl -F 'f:1=<-' ix.io

bencze · 2023-06-14 08:09:15

Appreciate the feedback.

I don't have that package installed, or any package with gnome in name according to pacman -Q.
I disabled picom (it was started by i3 config and just commented it there) and rebooted but didn't make a difference.

I tried now 2 times with a stopwatch (thunar, and firefox) and they were both 30 sec within +1 sec margin of error which can be my reflexes and the actual load time etc.

http://ix.io/4yc4

seth · 2023-06-14 12:56:10

You've at least NM and system-networkd fighting over your wifi NIC, pick one disable the other and post the output of

find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f

If that's not the cause, we'll have to strace thunar.

bencze · 2023-06-14 14:14:16

Disabled the systemd networkj and it didn't seem to make any difference.

New log: http://ix.io/4ydj

$ find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f
bluetooth.service                        | bluetooth.target.wants
dbus-org.bluez.service                   | system
dbus-org.freedesktop.nm-dispatcher.service | system
display-manager.service                  | system
gcr-ssh-agent.socket                     | sockets.target.wants
getty@tty1.service                       | getty.target.wants
NetworkManager-wait-online.service       | network-online.target.wants
NetworkManager.service                   | multi-user.target.wants
p11-kit-server.socket                    | sockets.target.wants
pipewire-media-session.service           | pipewire.service.wants
pipewire-session-manager.service         | user
pipewire.socket                          | sockets.target.wants
pulseaudio.socket                        | sockets.target.wants
remote-fs.target                         | multi-user.target.wants

seth · 2023-06-14 14:16:24

we'll have to strace thunar

strace -f -tt -o /tmp/thunar.strace thunar

bencze · 2023-06-15 14:26:26

I think file was too large for ix but the same worked with the other service in the wiki links:
http://0x0.st/HT-K.txt

The experience is the exact same with many other apps: tried firefox, smplayer and got same results. Weirdly chromium is an exception, it always starts fast as I expect all apps to.

seth · 2023-06-15 15:07:08

1302  16:23:48.525352 readlink("/proc/self/exe", "/usr/bin/thunar", 99) = 15
1302  16:23:48.525546 newfstatat(15, "", {st_mode=S_IFREG|0644, st_size=1216, ...}, AT_EMPTY_PATH) = 0
1302  16:23:48.525575 read(15, "# This file is part of PulseAudi"..., 4096) = 1216
1302  16:23:48.525605 read(15, "", 4096) = 0
1302  16:23:48.525629 openat(AT_FDCWD, "/etc/pulse/client.conf.d", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 ENOENT (No such file or directory)
1302  16:23:48.525657 close(15)         = 0
1302  16:23:48.525683 openat(AT_FDCWD, "/dev/shm/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 15
1302  16:23:48.525712 newfstatat(15, "", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=40, ...}, AT_EMPTY_PATH) = 0
1302  16:23:48.525739 getdents64(15, 0x563c3b725ab0 /* 2 entries */, 32768) = 48
1302  16:23:48.525778 getdents64(15, 0x563c3b725ab0 /* 0 entries */, 32768) = 0
1302  16:23:48.525802 close(15)         = 0
1302  16:23:48.525826 openat(AT_FDCWD, "/dev/urandom", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 15
1302  16:23:48.525854 fcntl(15, F_GETFD) = 0x1 (flags FD_CLOEXEC)
1302  16:23:48.525882 read(15, "O&\36~", 4) = 4
1302  16:23:48.525907 close(15)         = 0
1302  16:23:48.525931 memfd_create("pulseaudio", MFD_ALLOW_SEALING) = 15
1302  16:23:48.525958 ftruncate(15, 67108864) = 0
1302  16:23:48.525982 mmap(NULL, 67108864, PROT_READ|PROT_WRITE, MAP_SHARED|MAP_NORESERVE, 15, 0) = 0x7fb0d8000000
1302  16:23:48.526014 openat(AT_FDCWD, "/usr/share/locale/C.UTF-8/LC_MESSAGES/pulseaudio.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
1302  16:23:48.526041 openat(AT_FDCWD, "/usr/share/locale/C.utf8/LC_MESSAGES/pulseaudio.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
1302  16:23:48.526067 openat(AT_FDCWD, "/usr/share/locale/C/LC_MESSAGES/pulseaudio.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
1302  16:23:48.526103 getpid()          = 1302
1302  16:23:48.526127 getpid()          = 1302
1302  16:23:48.526152 newfstatat(AT_FDCWD, "/run/user/1000", {st_mode=S_IFDIR|0700, st_size=300, ...}, 0) = 0
1302  16:23:48.526181 getuid()          = 1000
1302  16:23:48.526205 umask(077)        = 022
1302  16:23:48.526229 mkdir("/run/user/1000/pulse", 0700) = -1 EEXIST (File exists)
1302  16:23:48.526255 umask(022)        = 077
1302  16:23:48.526279 openat(AT_FDCWD, "/run/user/1000/pulse", O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC) = 16
1302  16:23:48.526305 newfstatat(16, "", {st_mode=S_IFDIR|0700, st_size=80, ...}, AT_EMPTY_PATH) = 0
1302  16:23:48.526332 getuid()          = 1000
1302  16:23:48.526355 getgid()          = 1000
1302  16:23:48.526379 close(16)         = 0
1302  16:23:48.526403 readlink("/run", 0x7ffe88fc94f0, 1023) = -1 EINVAL (Invalid argument)
1302  16:23:48.526429 readlink("/run/user", 0x7ffe88fc94f0, 1023) = -1 EINVAL (Invalid argument)
1302  16:23:48.526455 readlink("/run/user/1000", 0x7ffe88fc94f0, 1023) = -1 EINVAL (Invalid argument)
1302  16:23:48.526480 readlink("/run/user/1000/pulse", 0x7ffe88fc94f0, 1023) = -1 EINVAL (Invalid argument)
1302  16:23:48.526511 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 16
1302  16:23:48.526542 fcntl(16, F_GETFD) = 0x1 (flags FD_CLOEXEC)
1302  16:23:48.526566 setsockopt(16, SOL_SOCKET, SO_PRIORITY, [6], 4) = 0
1302  16:23:48.526593 fcntl(16, F_GETFL) = 0x2 (flags O_RDWR)
1302  16:23:48.526617 fcntl(16, F_SETFL, O_RDWR|O_NONBLOCK) = 0
1302  16:23:48.526641 connect(16, {sa_family=AF_UNIX, sun_path="/run/user/1000/pulse/native"}, 110) = 0
1302  16:23:48.526671 sendto(14, "W", 1, MSG_NOSIGNAL, NULL, 0) = -1 ENOTSOCK (Socket operation on non-socket)
1302  16:23:48.526705 write(14, "W", 1) = 1
1302  16:23:48.526731 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=508835559}) = 0
1302  16:23:48.526758 write(14, "W", 1) = 1
1302  16:23:48.526785 rt_sigprocmask(SIG_BLOCK, ~[], [], 8) = 0
1302  16:23:48.526813 clone3({flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, child_tid=0x7fb0f2ffd990, parent_tid=0x7fb0f2ffd990, exit_signal=0, stack=0x7fb0f27fd000, stack_size=0x7ffcc0, tls=0x7fb0f2ffd6c0} => {parent_tid=[1313]}, 88) = 1313
1302  16:23:48.526868 rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
1313  16:23:48.526874 rseq(0x7fb0f2ffdfe0, 0x20, 0, 0x53053053 <unfinished ...>
1302  16:23:48.526881 <... rt_sigprocmask resumed>NULL, 8) = 0
1302  16:23:48.526894 futex(0x563c3b71d128, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
1313  16:23:48.526900 <... rseq resumed>) = 0
1313  16:23:48.526928 set_robust_list(0x7fb0f2ffd9a0, 24) = 0
1313  16:23:48.526956 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
1313  16:23:48.526988 prctl(PR_SET_NAME, "threaded-ml") = 0
1313  16:23:48.527017 rt_sigprocmask(SIG_SETMASK, NULL, [], 8) = 0
1313  16:23:48.527042 rt_sigaction(SIGSYS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
1313  16:23:48.527069 rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], NULL, 8) = 0
1313  16:23:48.527095 read(13, "WW", 10) = 2
1313  16:23:48.527122 getsockopt(16, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
1313  16:23:48.527153 fcntl(16, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
1313  16:23:48.527180 write(14, "W", 1) = 1
1313  16:23:48.527208 write(14, "W", 1) = 1
1313  16:23:48.527246 setsockopt(16, SOL_SOCKET, SO_RCVBUF, [65472], 4) = 0
1313  16:23:48.527272 setsockopt(16, SOL_SOCKET, SO_SNDBUF, [65472], 4) = 0
1313  16:23:48.527301 openat(AT_FDCWD, "/home/ben/.config/pulse/cookie", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 17
1313  16:23:48.527334 fcntl(17, F_GETFD) = 0x1 (flags FD_CLOEXEC)
1313  16:23:48.527358 fcntl(17, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = -1 EBADF (Bad file descriptor)
1313  16:23:48.527387 fcntl(17, F_SETLKW, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
1313  16:23:48.527413 read(17, "r\261\224\336h\235\24\203L\21549\317\335-\217g\325H%=S\340\326t\33\0177\314_\324\31"..., 256) = 256
1313  16:23:48.527440 fcntl(17, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
1313  16:23:48.527466 close(17)         = 0
1313  16:23:48.527496 getsockname(16, {sa_family=AF_UNIX}, [256 => 2]) = 0
1313  16:23:48.527523 setsockopt(16, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0
1313  16:23:48.527549 getuid()          = 1000
1313  16:23:48.527573 getgid()          = 1000
1313  16:23:48.527610 write(14, "W", 1) = 1
1313  16:23:48.527640 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=509744124}) = 0
1313  16:23:48.527667 write(14, "W", 1) = 1
1313  16:23:48.527692 futex(0x563c3b71d128, FUTEX_WAKE_PRIVATE, 2147483647) = 1
1302  16:23:48.527708 <... futex resumed>) = 0
1302  16:23:48.527718 futex(0x563c3b722f10, FUTEX_LOCK_PI_PRIVATE, NULL <unfinished ...>
1313  16:23:48.527722 read(13, "WWWW", 10) = 4
1313  16:23:48.527749 read(13, 0x7fb0f2ffc9ce, 10) = -1 EAGAIN (Resource temporarily unavailable)
1313  16:23:48.527774 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=509878289}) = 0
1313  16:23:48.527801 futex(0x563c3b722f10, FUTEX_UNLOCK_PI_PRIVATE) = 0
1302  16:23:48.527816 <... futex resumed>) = 0
1302  16:23:48.527825 futex(0x563c3b722f10, FUTEX_UNLOCK_PI_PRIVATE <unfinished ...>
1313  16:23:48.527828 poll([{fd=13, events=POLLIN}, {fd=16, events=POLLIN|POLLOUT}], 2, 30000 <unfinished ...>
1302  16:23:48.527833 <... futex resumed>) = 0
1302  16:23:48.527846 futex(0x563c3b71d12c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
1313  16:23:48.527850 <... poll resumed>) = 1 ([{fd=16, revents=POLLOUT}])
1313  16:23:48.527864 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=509967895}) = 0
1313  16:23:48.527890 write(14, "W", 1) = 1
1313  16:23:48.527930 getpid()          = 1302
1313  16:23:48.527958 sendmsg(16, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0\0\1\24\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=20}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=1302, uid=1000, gid=1000}}], msg_controllen=32, msg_flags=0}, MSG_NOSIGNAL) = 20
1313  16:23:48.527989 write(14, "W", 1) = 1
1313  16:23:48.528015 read(13, "WW", 10) = 2
1313  16:23:48.528039 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=510143476}) = 0
1313  16:23:48.528065 poll([{fd=13, events=POLLIN}, {fd=16, events=POLLIN|POLLOUT}], 2, 30000) = 1 ([{fd=16, revents=POLLOUT}])
1313  16:23:48.528094 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=510197883}) = 0
1313  16:23:48.528120 write(14, "W", 1) = 1
1313  16:23:48.528144 sendto(16, "L\0\0\0\10L\0\0\0\0L\300\0\0#x\0\0\1\0r\261\224\336h\235\24\203L\21549"..., 276, MSG_NOSIGNAL, NULL, 0) = 276
1313  16:23:48.528179 read(13, "W", 10) = 1
1313  16:23:48.528204 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=510308511}) = 0
1313  16:23:48.528230 poll([{fd=13, events=POLLIN}, {fd=16, events=POLLIN}], 2, 30000 <unfinished ...>
1306  16:23:48.983015 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out)
1306  16:23:48.983165 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=965297808}) = 0
1306  16:23:48.983279 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97, tv_nsec=965400265}) = 0
1306  16:23:48.983349 futex(0x563c3b38d910, FUTEX_WAIT_PRIVATE, 0, {tv_sec=14, tv_nsec=999896735} <unfinished ...>
1307  16:23:48.999877 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out)
1307  16:23:48.999967 rt_sigprocmask(SIG_BLOCK, ~[RT_1], NULL, 8) = 0
1307  16:23:49.000057 madvise(0x7fb0f2ffe000, 8368128, MADV_DONTNEED) = 0
1307  16:23:49.000166 exit(0)           = ?
1307  16:23:49.000259 +++ exited with 0 +++
1304  16:23:55.966869 <... poll resumed>) = 0 (Timeout)
1304  16:23:55.967018 clock_gettime(CLOCK_MONOTONIC, {tv_sec=104, tv_nsec=949145685}) = 0
1304  16:23:55.967153 clock_gettime(CLOCK_MONOTONIC, {tv_sec=104, tv_nsec=949282504}) = 0
1304  16:23:55.967274 clock_gettime(CLOCK_MONOTONIC, {tv_sec=104, tv_nsec=949406123}) = 0
1304  16:23:55.967376 clock_gettime(CLOCK_MONOTONIC, {tv_sec=104, tv_nsec=949488675}) = 0
1304  16:23:55.967430 clock_gettime(CLOCK_MONOTONIC, {tv_sec=104, tv_nsec=949540637}) = 0
1304  16:23:55.967483 poll([{fd=3, events=POLLIN}, {fd=11, events=POLLIN}], 2, -1 <unfinished ...>
1306  16:24:03.983742 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out)
1306  16:24:03.983957 rt_sigprocmask(SIG_BLOCK, ~[RT_1], NULL, 8) = 0
1306  16:24:03.984093 madvise(0x7fb0f37ff000, 8368128, MADV_DONTNEED) = 0
1306  16:24:03.984373 exit(0)           = ?
1306  16:24:03.984596 +++ exited with 0 +++
1313  16:24:18.558443 <... poll resumed>) = 0 (Timeout)
1313  16:24:18.558617 clock_gettime(CLOCK_MONOTONIC, {tv_sec=127, tv_nsec=540745547}) = 0
1313  16:24:18.558745 futex(0x563c3b71d12c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
1302  16:24:18.558859 <... futex resumed>) = 0
1313  16:24:18.558886 write(14, "W", 1 <unfinished ...>

Looks like pulsenoaudio (render me shocked…)

Do you use pipewire (i don't see any trace in the strace) or pulseaudio?
Does

pactl list sinks

timeout as well?

bencze · 2023-06-16 21:08:57

That command also waits about 30 seconds then says: Connection failure: Timeout.

To be honest I don't know what am I using. At some point I was trying to get some decent sound from my headphones / usb dac and according to some recommendations I tried to work with some combination of alsa / pipewire but I think sound was borked and I managed to 'fix' it (as in: get sound again) by installing pulseaudio and its mixer tool (so I can switch between the speakers and usb dac when needed, etc). I think originally I needed Easyeffects and it was related to that but it was some while back (not sure but could also be the fact at some point I needed to use bluetooth earbuds; I vaguely remember installing pulseaudio on my last train trip). So I think I have both installed, maybe partially.

Sadly I really don't understand how Linux sound works. Sound, and graphic interface (X and all the stuff on top of it) are great mysteries. Recently I had a little bit of luck / partial successes regarding the second (although diferent scaling monitors are a challenge); I am yet to have any real successes with sound.
I can try removing all that I can find that is sound related and reinstall what I needed, there's possibly some guides for that.

Last edited by bencze (2023-06-16 21:13:14)

seth · 2023-06-16 21:16:24

pacman -Qs 'pipe|pulse'
ps fax

Try to disable the pulseaudio.socket

bencze · 2023-06-28 12:05:25

Apologies, I was traveling and without this notebook.
Stopping the pulseaudio socket miraculously removed the delay completely, everything starts basically instant.
This is really awesome work, appreciate it greatly! I do have to learn how to fix / not mess up / my audio system, but the biggest issue (for me) is that I don't lilke not knowing what is the cause and I don't like reinstall as a 'solution', it just bugs me to no end. So thanks a lot for your help. Would say I owed you a beer or two if you ever come to Bavaria.

Last edited by bencze (2023-06-28 12:06:40)

seth · 2023-06-28 15:17:01

The trajectory is certainly to replace everything pulseaudio w/ pipewire (the new awesome way to break your sound …) and only use pulseaudio emulating shims for clients that rely on it.

Please always remember to mark resolved threads by editing your initial posts subject - so others will know that there's no task left, but maybe a solution to find.
Thanks.

Arch Linux

#1 2023-06-14 07:11:55

X applications load window content w/ 30sec delay (SOLVED)

#2 2023-06-14 07:40:47

Re: X applications load window content w/ 30sec delay (SOLVED)

#3 2023-06-14 08:09:15

Re: X applications load window content w/ 30sec delay (SOLVED)

#4 2023-06-14 12:56:10

Re: X applications load window content w/ 30sec delay (SOLVED)

#5 2023-06-14 14:14:16

Re: X applications load window content w/ 30sec delay (SOLVED)

#6 2023-06-14 14:16:24

Re: X applications load window content w/ 30sec delay (SOLVED)

#7 2023-06-15 14:26:26

Re: X applications load window content w/ 30sec delay (SOLVED)

#8 2023-06-15 15:07:08

Re: X applications load window content w/ 30sec delay (SOLVED)

#9 2023-06-16 21:08:57

Re: X applications load window content w/ 30sec delay (SOLVED)

#10 2023-06-16 21:16:24

Re: X applications load window content w/ 30sec delay (SOLVED)

#11 2023-06-28 12:05:25

Re: X applications load window content w/ 30sec delay (SOLVED)

#12 2023-06-28 15:17:01

Re: X applications load window content w/ 30sec delay (SOLVED)

Board footer