Very slow startup of GTK+ applications

For the last couple months, I've noticed that GTK+ applications can be

very slow to start on my Guix / Debian system. It may take up to a

minute before they finish launching.

Here's an strace log of 'mousepad' startup. The pause occurs at line

3638, and then resumes after the the timeout is reached. Excerpt:

------

3621 [pid 10026] poll([{fd=7, events=POLLIN}], 1, 0) = 0 (Timeout)

3622 [pid 10026] poll([{fd=6, events=POLLIN}], 1, 0) = 1 ([{fd=6, revents=POLLIN}])

3623 [pid 10026] recvmsg(6, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\0\0\0\0\f\0\0\0005\0\0\0", iov_len=16}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG _CMSG_CLOEXEC) = 16

3624 [pid 10026] poll([{fd=7, events=POLLIN}], 1, 0) = 0 (Timeout)

3625 [pid 10026] poll([{fd=6, events=POLLIN}], 1, 0) = 1 ([{fd=6, revents=POLLIN}])

3626 [pid 10026] recvmsg(6, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\6\0\0\0:1.337\0\0\5\1u\0\n\0\0\0\7\1s\0\24\0\0\0"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_f lags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 56

3627 [pid 10026] poll([{fd=7, events=POLLIN}], 1, 0) = 0 (Timeout)

3628 [pid 10026] poll([{fd=6, events=POLLIN}], 1, 0) = 1 ([{fd=6, revents=POLLIN}])

3629 [pid 10026] recvmsg(6, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\0\0\0\0\r\0\0\0005\0\0\0", iov_len=16}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG _CMSG_CLOEXEC) = 16

3630 [pid 10026] poll([{fd=7, events=POLLIN}], 1, 0) = 0 (Timeout)

3631 [pid 10026] poll([{fd=6, events=POLLIN}], 1, 0) = 1 ([{fd=6, revents=POLLIN}])

3632 [pid 10026] recvmsg(6, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\6\0\0\0:1.337\0\0\5\1u\0\v\0\0\0\7\1s\0\24\0\0\0"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_f lags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 56

3633 [pid 10026] poll([{fd=7, events=POLLIN}], 1, 0) = 0 (Timeout)

3634 [pid 10026] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3635 [pid 10026] write(7, "\1\0\0\0\0\0\0\0", 8) = 8

3636 [pid 10026] poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 2, -1) = 1 ([{fd=7, revents=POLLIN}])

3637 [pid 10026] read(7, "\1\0\0\0\0\0\0\0", 16) = 8

3638 [pid 10026] poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 2, -1 <unfinished ...>

3639 [pid 10024] <... poll resumed> ) = 0 (Timeout)

------

Here is another strace log, for gnome-calculator.

It pauses at line 3755:

------

3738 [pid 10510] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3739 [pid 10510] poll([{fd=5, events=POLLIN}], 1, 0) = 1 ([{fd=5, revents=POLLIN}])

3740 [pid 10510] recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\0\0\0\0\n\0\0\0005\0\0\0", iov_len=16}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG _CMSG_CLOEXEC) = 16

3741 [pid 10510] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3742 [pid 10510] poll([{fd=5, events=POLLIN}], 1, 0) = 1 ([{fd=5, revents=POLLIN}])

3743 [pid 10510] recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\6\0\0\0:1.343\0\0\5\1u\0\t\0\0\0\7\1s\0\24\0\0\0"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_f lags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 56

3744 [pid 10510] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3745 [pid 10510] poll([{fd=5, events=POLLIN}], 1, 0) = 1 ([{fd=5, revents=POLLIN}])

3746 [pid 10510] recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\0\0\0\0\v\0\0\0005\0\0\0", iov_len=16}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG _CMSG_CLOEXEC) = 16

3747 [pid 10510] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3748 [pid 10510] poll([{fd=5, events=POLLIN}], 1, 0) = 1 ([{fd=5, revents=POLLIN}])

3749 [pid 10510] recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\6\0\0\0:1.343\0\0\5\1u\0\n\0\0\0\7\1s\0\24\0\0\0"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_f lags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 56

3750 [pid 10510] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3751 [pid 10510] poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout)

3752 [pid 10510] write(6, "\1\0\0\0\0\0\0\0", 8) = 8

3753 [pid 10510] poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 2, -1) = 1 ([{fd=6, revents=POLLIN}])

3754 [pid 10510] read(6, "\1\0\0\0\0\0\0\0", 16) = 8

3755 [pid 10510] poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 2, -1 <unfinished ...>

3756 [pid 10508] <... poll resumed> ) = 0 (Timeout)

------

On Mon, Jun 07, 2021 at 06:34:59PM -0400, Leo Famulari wrote:

And another, but with less abbreviation. It pauses at line 3775:

------

3757 [pid 10717] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3758 [pid 10717] poll([{fd=5, events=POLLIN}], 1, 0) = 1 ([{fd=5, revents=POLLIN}])

3759 [pid 10717] recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\0\0\0\0\n\0\0\0005\0\0\0", iov_len=16}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG _CMSG_CLOEXEC) = 16

3760 [pid 10717] sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1(\0\0\0\v\0\0\0\203\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0 \0\0\0\6\1s\0\24\0\0\0org.freedesk"..., iov_len=192}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 192

3761 [pid 10717] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3762 [pid 10717] poll([{fd=5, events=POLLIN}], 1, 0) = 1 ([{fd=5, revents=POLLIN}])

3763 [pid 10717] recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\6\0\0\0:1.345\0\0\5\1u\0\t\0\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0", iov_len=56}], msg_iovlen=1 , msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 56

3764 [pid 10717] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3765 [pid 10717] poll([{fd=5, events=POLLIN}], 1, 0) = 1 ([{fd=5, revents=POLLIN}])

3766 [pid 10717] recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\0\0\0\0\v\0\0\0005\0\0\0", iov_len=16}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG _CMSG_CLOEXEC) = 16

3767 [pid 10717] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3768 [pid 10717] poll([{fd=5, events=POLLIN}], 1, 0) = 1 ([{fd=5, revents=POLLIN}])

3769 [pid 10717] recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\6\0\0\0:1.345\0\0\5\1u\0\n\0\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0", iov_len=56}], msg_iovlen=1 , msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 56

3770 [pid 10717] poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

3771 [pid 10717] poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout)

3772 [pid 10717] write(6, "\1\0\0\0\0\0\0\0", 8) = 8

3773 [pid 10717] poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 2, -1) = 1 ([{fd=6, revents=POLLIN}])

3774 [pid 10717] read(6, "\1\0\0\0\0\0\0\0", 16) = 8

3775 [pid 10717] poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 2, -1 <unfinished ...>

3776 [pid 10715] <... poll resumed> ) = 0 (Timeout)

------

Googling, I found some similar bug reports:

The Arch discussion is very similar, as we are both using i3 launched

with startx.

The Arch discussion pointed to their wiki page on xinit, which

includes this note:

------

Note: At the very least, ensure that the last if block in

/etc/X11/xinit/xinitrc is present in your ~/.xinitrc file to ensure that

the scripts in /etc/X11/xinit/xinitrc.d are sourced.

------

I did that, and it fixed the problem.

The file /etc/X11/xinit/xinitrc on my Debian system merely sources

/etc/X11/Xsession, which is attached for your reference.

It does a lot of things and references other files... I have no idea

what actually fixed my problem.

#!/bin/sh

#

# /etc/X11/Xsession

#

# global Xsession file -- used by display managers and xinit (startx)

# $Id: Xsession 967 2005-12-27 07:20:55Z dnusinow $

set -e

PROGNAME=Xsession

message () {

# pretty-print messages of arbitrary length; use xmessage if it

# is available and $DISPLAY is set

MESSAGE="$PROGNAME: $*"

echo "$MESSAGE" | fold -s -w ${COLUMNS:-80} >&2

if [ -n "$DISPLAY" ] && which xmessage > /dev/null 2>&1; then

echo "$MESSAGE" | fold -s -w ${COLUMNS:-80} | xmessage -center -file -

fi

}

message_nonl () {

# pretty-print messages of arbitrary length (no trailing newline); use

# xmessage if it is available and $DISPLAY is set

MESSAGE="$PROGNAME: $*"

echo -n "$MESSAGE" | fold -s -w ${COLUMNS:-80} >&2;

if [ -n "$DISPLAY" ] && which xmessage > /dev/null 2>&1; then

echo -n "$MESSAGE" | fold -s -w ${COLUMNS:-80} | xmessage -center -file -

fi

}

errormsg () {

# exit script with error

message "$*"

exit 1

}

internal_errormsg () {

# exit script with error; essentially a "THIS SHOULD NEVER HAPPEN" message

# One big call to message() for the sake of xmessage; if we had two then

# the user would have dismissed the error we want reported before seeing the

# request to report it.

errormsg "$*" \

"Please report the installed version of the \"x11-common\"" \

"package and the complete text of this error message to" \

"<debian-x@lists.debian.org>."

}

# initialize variables for use by all session scripts

OPTIONFILE=/etc/X11/Xsession.options

SYSRESOURCES=/etc/X11/Xresources

USRRESOURCES=$HOME/.Xresources

SYSSESSIONDIR=/etc/X11/Xsession.d

USERXSESSION=$HOME/.xsession

USERXSESSIONRC=$HOME/.xsessionrc

ALTUSERXSESSION=$HOME/.Xsession

ERRFILE=$HOME/.xsession-errors

# attempt to create an error file; abort if we cannot

if (umask 077 && touch "$ERRFILE") 2> /dev/null && [ -w "$ERRFILE" ] &&

[ ! -L "$ERRFILE" ]; then

chmod 600 "$ERRFILE"

elif ERRFILE=$(tempfile 2> /dev/null); then

if ! ln -sf "$ERRFILE" "${TMPDIR:=/tmp}/xsession-$USER"; then

message "warning: unable to symlink \"$TMPDIR/xsession-$USER\" to" \

"\"$ERRFILE\"; look for session log/errors in" \

"\"$TMPDIR/xsession-$USER\"."

fi

else

errormsg "unable to create X session log/error file; aborting."

fi

exec >>"$ERRFILE" 2>&1

echo "$PROGNAME: X session started for $LOGNAME at $(date)"

# sanity check; is our session script directory present?

if [ ! -d "$SYSSESSIONDIR" ]; then

errormsg "no \"$SYSSESSIONDIR\" directory found; aborting."

fi

# Attempt to create a file of non-zero length in /tmp; a full filesystem can

# cause mysterious X session failures. We do not use touch, :, or test -w

# because they won't actually create a file with contents. We also let standard

# error from tempfile and echo go to the error file to aid the user in

# determining what went wrong.

WRITE_TEST=$(tempfile)

if ! echo "*" >>"$WRITE_TEST"; then

message "warning: unable to write to ${WRITE_TEST%/*}; X session may exit" \

"with an error"

fi

rm -f "$WRITE_TEST"

# use run-parts to source every file in the session directory; we source

# instead of executing so that the variables and functions defined above

# are available to the scripts, and so that they can pass variables to each

# other

SESSIONFILES=$(run-parts --list $SYSSESSIONDIR)

if [ -n "$SESSIONFILES" ]; then

set +e

for SESSIONFILE in $SESSIONFILES; do

. $SESSIONFILE

done

set -e

fi

exit 0

# vim:set ai et sts=2 sw=2 tw=80:

Hi,

Leo Famulari <leo@famulari.name> skribis:

Weird.

I conclude this is not a Guix-specific issue and can be closed, right?

Thanks for sharing the tip!

Ludo’.

tags 48910 notabug

close 48910

quit