Debian Bug report logs - #925160
systemd: user session slow to start (11 seconds)

Toggle useless messages

Message #5 received at submit@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: Debian BTS submission <submit@bugs.debian.org>

Subject: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 17:36:44 +0100

Package: systemd
Version: 241-2
Severity: important


Dear Maintainer,

on this system, an initial ssh connection needs 11 seconds to complete (as root or any other user).  Further connections are fast.
This is not a slow boot problem because it occurs even when the machine has been booted for days.

It comes from a slow start of the user's session as can be seen in this log:

Mar 20 15:06:27 hostname sshd[172771]: Accepted publickey for root from 193.55.51.153 port 53702 ssh2: RSA SHA256:wmFQ70BsRjT4uCWua2ddnbfFv7kiMecLHVNtZMw0KMk
Mar 20 15:06:27 hostname sshd[172771]: pam_unix(sshd:session): session opened for user root by (uid=0)
Mar 20 15:06:27 hostname systemd-logind[743]: New session 3373 of user root.
Mar 20 15:06:27 hostname systemd[1]: Starting User Manager for UID 0...
Mar 20 15:06:27 hostname systemd[172774]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
[11 seconds gap]
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG network certificate management daemon.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Timers.
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG cryptographic agent and passphrase cache.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Paths.
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Mar 20 15:06:38 hostname systemd[172774]: Listening on Multimedia System.
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Mar 20 15:06:38 hostname systemd[172774]: Condition check resulted in Sound System being skipped.
Mar 20 15:06:38 hostname systemd[172774]: Starting D-Bus User Message Bus Socket.
Mar 20 15:06:38 hostname systemd[172774]: Listening on D-Bus User Message Bus Socket.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Sockets.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Basic System.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Default.
Mar 20 15:06:38 hostname systemd[172774]: Startup finished in 11.151s.
Mar 20 15:06:38 hostname systemd[1]: Started User Manager for UID 0.
Mar 20 15:06:38 hostname systemd[1]: Started Session 3373 of user root.

The problem can also be seen here:

# systemd-analyze --user
Startup finished in 11.151s (userspace) 
default.target reached after 11.151s in userspace

# systemd-analyze --user blame
             7ms dbus.socket

# systemd-analyze --user critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

default.target @11.151s
└─basic.target @11.150s
  └─sockets.target @11.150s
    └─dbus.socket @11.143s +7ms
      └─run-user-0.mount @11.137s
        └─-.mount @11.137s
          └─-.slice @11.137s

In a further e-mail I will send the output of this command:

# systemd-analyze --user dump


-- Package-specific info:

-- System Information:
Debian Release: buster/sid
  APT prefers unstable-debug
  APT policy: (500, 'unstable-debug'), (500, 'unstable'), (1, 'experimental-debug'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 4.19.0-4-amd64 (SMP w/2 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to en_US.UTF-8), LANGUAGE=en_US.
UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to en_US.UTF-8)
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages systemd depends on:
ii  adduser          3.118
ii  libacl1          2.2.53-4
ii  libapparmor1     2.13.2-9
ii  libaudit1        1:2.8.4-2
ii  libblkid1        2.33.1-0.1
ii  libc6            2.28-8
ii  libcap2          1:2.25-2
ii  libcryptsetup12  2:2.1.0-2
ii  libgcrypt20      1.8.4-5
ii  libgnutls30      3.6.6-3
ii  libgpg-error0    1.36-1
ii  libidn11         1.33-2.2
ii  libip4tc0        1.8.2-4
ii  libkmod2         26-1
ii  liblz4-1         1.8.3-1
ii  liblzma5         5.2.4-1
ii  libmount1        2.33.1-0.1
ii  libpam0g         1.3.1-5
ii  libseccomp2      2.3.3-4
ii  libselinux1      2.9-1
ii  libsystemd0      241-2
ii  mount            2.33.1-0.1
ii  util-linux       2.33.1-0.1

Versions of packages systemd recommends:
ii  dbus            1.13.8-1
ii  libpam-systemd  241-2

Versions of packages systemd suggests:
ii  policykit-1        0.115-3
ii  systemd-container  241-2

Versions of packages systemd is related to:
pn  dracut           <none>
ii  initramfs-tools  0.133
ii  udev             241-2

-- no debconf information

-- 
Laurent.

Message #10 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Michael Prokop <mika@debian.org>

To: Laurent Bonnaud <L.Bonnaud@laposte.net>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 17:47:25 +0100

[Message part 1 (text/plain, inline)]

* Laurent Bonnaud [Wed Mar 20, 2019 at 05:36:44PM +0100]:

> on this system, an initial ssh connection needs 11 seconds to complete (as root or any other user).  Further connections are fast.
> This is not a slow boot problem because it occurs even when the machine has been booted for days.

> It comes from a slow start of the user's session as can be seen in this log:

[...]

Just a quick shot, are you sure your reverse DNS is OK?
If you set `UseDNS no` in /etc/ssh/sshd_config, is the SSH login faster?

What do you mean with "Further connections are fast", ssh-ing into
the system as the same user (do you use ssh with ControlMaster?)?
Is connecting via `ssh -o ControlPath=none ...` also slow?

regards
-mika-

[signature.asc (application/pgp-signature, inline)]

Message #15 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Laurent Bonnaud <L.Bonnaud@laposte.net>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 17:52:36 +0100

[Message part 1 (text/plain, inline)]

On 20.03.19 17:36, Laurent Bonnaud wrote:
> Package: systemd
> Version: 241-2
> Severity: important
> 
> 
> Dear Maintainer,
> 
> on this system, an initial ssh connection needs 11 seconds to complete (as root or any other user).  Further connections are fast.

Is this problem reproducible if you login locally?


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #20 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 19:01:54 +0100

[Message part 1 (text/plain, inline)]

Here is the output of:

  systemd-analyze --user dump

I see a lot of references to my root partition/disk:

# grep -c INTEL_SSDSC2BA80 dump
113

which is an insane number.

Furthermore, when I attach external USB disks to this system, the user's session startup time if even greater (18 seconds).

Therefore I suspect that something is wrong with mount units, but I could not find it in systemd's config.

-- 
Laurent.

[dump (text/plain, attachment)]

Message #25 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: Michael Biebl <biebl@debian.org>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 19:05:14 +0100

On 3/20/19 5:52 PM, Michael Biebl wrote:

> Is this problem reproducible if you login locally?

Sorry, I will have to wait until tomorrow to have physical access to this system...

Thanks,

-- 
Laurent.

Message #30 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: Michael Prokop <mika@debian.org>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 18:50:06 +0100

On 3/20/19 5:47 PM, Michael Prokop wrote:

> Just a quick shot, are you sure your reverse DNS is OK?

Yes.

> If you set `UseDNS no` in /etc/ssh/sshd_config, is the SSH login faster?

Setting "UseDNS no" does not solve the problem.

Thanks,

-- 
Laurent.

Message #35 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: Michael Prokop <mika@debian.org>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 18:53:51 +0100

On 3/20/19 5:47 PM, Michael Prokop wrote:

> What do you mean with "Further connections are fast", ssh-ing into
> the system as the same user  ?

Exactly.

> (do you use ssh with ControlMaster?)

I do not use ControlMaster.

> Is connecting via `ssh -o ControlPath=none ...` also slow?

Using the "-o ControlPath=none" option is also slow.

Thanks,

-- 
Laurent.

Message #40 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Laurent Bonnaud <L.Bonnaud@laposte.net>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 19:19:09 +0100

[Message part 1 (text/plain, inline)]

Am 20.03.19 um 19:01 schrieb Laurent Bonnaud:
> Timestamp generators-start: Wed 2019-03-20 15:06:27 CET
> Timestamp generators-finish: Wed 2019-03-20 15:06:38 CET

That is odd.
Do you have any (user) generators which might take a long time?


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #45 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Laurent Bonnaud <L.Bonnaud@laposte.net>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 19:24:20 +0100

[Message part 1 (text/plain, inline)]

Am 20.03.19 um 19:19 schrieb Michael Biebl:
> Am 20.03.19 um 19:01 schrieb Laurent Bonnaud:
>> Timestamp generators-start: Wed 2019-03-20 15:06:27 CET
>> Timestamp generators-finish: Wed 2019-03-20 15:06:38 CET
> 
> That is odd.
> Do you have any (user) generators which might take a long time?

Typical places to check:

/usr/lib/systemd/user-environment-generators/
/usr/lib/systemd/user-generators/

and the equivalent locations in /etc and ~/.config/systemd

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #50 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Laurent Bonnaud <L.Bonnaud@laposte.net>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Wed, 20 Mar 2019 19:39:04 +0100

[Message part 1 (text/plain, inline)]

Control: tags -1 + moreinfo

Am 20.03.19 um 19:24 schrieb Michael Biebl:
> Am 20.03.19 um 19:19 schrieb Michael Biebl:
>> Am 20.03.19 um 19:01 schrieb Laurent Bonnaud:
>>> Timestamp generators-start: Wed 2019-03-20 15:06:27 CET
>>> Timestamp generators-finish: Wed 2019-03-20 15:06:38 CET
>>
>> That is odd.
>> Do you have any (user) generators which might take a long time?
> 
> Typical places to check:
> 
> /usr/lib/systemd/user-environment-generators/
> /usr/lib/systemd/user-generators/
> 
> and the equivalent locations in /etc and ~/.config/systemd
> 

Another info that might help give a clue is setting
LogLevel=debug in /etc/systemd/user.conf, reboot, log in, then attach
the output of journalctl --user -b


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #57 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: Michael Biebl <biebl@debian.org>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Thu, 21 Mar 2019 13:21:51 +0100

On 3/20/19 5:52 PM, Michael Biebl wrote:

> Is this problem reproducible if you login locally?

Yes.  When I log in from a local VT, just after typing the password: 
 - I see the contents of /etc/motd
 - I wait for 11 seconds
 - then I see the shell prompt

Thanks,

-- 
Laurent.

Message #62 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: Michael Biebl <biebl@debian.org>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Thu, 21 Mar 2019 13:30:30 +0100

On 3/20/19 7:24 PM, Michael Biebl wrote:

>> Do you have any (user) generators which might take a long time?
> Typical places to check:
> 
> /usr/lib/systemd/user-environment-generators/
> /usr/lib/systemd/user-generators/

Here is what I have in this system:

# ls -l /usr/lib/systemd/user-environment-generators/ /usr/lib/systemd/user-generators/
/usr/lib/systemd/user-environment-generators/:
total 28
-rwxr-xr-x 1 root root 14320 Mar 15 18:33 30-systemd-environment-d-generator
-rwxr-xr-x 1 root root   472 Feb 11 17:17 60-flatpak
-rwxr-xr-x 1 root root   287 Mar  8 18:09 70-im-config
-rwxr-xr-x 1 root root   309 Mar  2 17:49 90gpg-agent

/usr/lib/systemd/user-generators/:
total 0

> and the equivalent locations in /etc and ~/.config/systemd

This directory does not exist in my homedirs.

Thanks,

-- 
Laurent.

Message #67 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: Michael Biebl <biebl@debian.org>, 925160@bugs.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Thu, 21 Mar 2019 13:51:32 +0100

On 20/03/2019 19.39, Michael Biebl wrote:

> Another info that might help give a clue is setting
> LogLevel=debug in /etc/systemd/user.conf, reboot, log in, then attach
> the output of journalctl --user -b

Thanks, it allowed me to find the cause of the problem:

Mar 21 13:41:49 hostname sshd[237915]: Accepted publickey for root from 193.55.51.152 port 41646 ssh2: RSA SHA256:wmFQ70BsRjT4uCWua2ddnbfFv7kiMecLHVNtZMw0KMk
Mar 21 13:41:49 hostname sshd[237915]: pam_unix(sshd:session): session opened for user root by (uid=0)
Mar 21 13:41:49 hostname systemd-logind[743]: New session 4844 of user root.
Mar 21 13:41:49 hostname systemd[1]: Starting User Manager for UID 0...
Mar 21 13:41:49 hostname systemd[237918]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Mar 21 13:41:49 hostname systemd[237918]: Found container virtualization none.
Mar 21 13:41:49 hostname systemd[237918]: systemd 241 running in user mode for user 0/root. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELF
Mar 21 13:41:49 hostname systemd[237918]: RLIMIT_MEMLOCK is already as high or higher than we need it, not bumping.
Mar 21 13:41:49 hostname systemd[237918]: Found cgroup2 on /sys/fs/cgroup/unified, unified hierarchy for systemd controller
Mar 21 13:41:49 hostname systemd[237918]: Unified cgroup hierarchy is located at /sys/fs/cgroup/unified/user.slice/user-0.slice/user@0.service. Controllers are on legacy hierarchies.
Mar 21 13:41:49 hostname systemd[237918]: Got EBADF when using BPF_F_ALLOW_MULTI, which indicates it is supported. Yay!
Mar 21 13:41:49 hostname systemd[237918]: Controller 'cpu' supported: yes
Mar 21 13:41:49 hostname systemd[237918]: Controller 'cpuacct' supported: yes
Mar 21 13:41:49 hostname systemd[237918]: Controller 'io' supported: no
Mar 21 13:41:49 hostname systemd[237918]: Controller 'blkio' supported: yes
Mar 21 13:41:49 hostname systemd[237918]: Controller 'memory' supported: yes
Mar 21 13:41:49 hostname systemd[237918]: Controller 'devices' supported: yes
Mar 21 13:41:49 hostname systemd[237918]: Controller 'pids' supported: yes
Mar 21 13:41:49 hostname systemd[237918]: Controller 'bpf-firewall' supported: yes
Mar 21 13:41:49 hostname systemd[237918]: Controller 'bpf-devices' supported: yes
Mar 21 13:41:49 hostname systemd[237918]: Set up TFD_TIMER_CANCEL_ON_SET timerfd.
Mar 21 13:41:49 hostname systemd[237918]: Serializing user-environment-generators to memfd.
Mar 21 13:41:49 hostname systemd[237918]: Successfully forked off '(sd-executor)' as PID 237922.
Mar 21 13:41:49 hostname systemd[237922]: Serializing 30-systemd-environment-d-generator to memfd.
Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237923.
Mar 21 13:41:49 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/30-systemd-environment-d-generator succeeded.
Mar 21 13:41:49 hostname systemd[237922]: Serializing 60-flatpak to memfd.
Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237924.
Mar 21 13:41:49 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/60-flatpak succeeded.
Mar 21 13:41:49 hostname systemd[237922]: Serializing 70-im-config to memfd.
Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237927.
Mar 21 13:42:02 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/70-im-config succeeded.

Therefore the problem is in /usr/lib/systemd/user-environment-generators/70-im-config.  Moving this file away solves the problem :>.

Should I reassign this bug to the im-config package ?

Thanks again,

-- 
Laurent.

Message #72 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Laurent Bonnaud <L.Bonnaud@laposte.net>, 925160@bugs.debian.org, im-config@packages.debian.org

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Thu, 21 Mar 2019 17:51:45 +0100

[Message part 1 (text/plain, inline)]

Control: reassign -1 im-config
Control: tags -1 - moreinfo
Control: affects -1 + systemd

Am 21.03.19 um 13:51 schrieb Laurent Bonnaud:
> On 20/03/2019 19.39, Michael Biebl wrote:
> 
>> Another info that might help give a clue is setting
>> LogLevel=debug in /etc/systemd/user.conf, reboot, log in, then attach
>> the output of journalctl --user -b
> 
> Thanks, it allowed me to find the cause of the problem:
> 
> Mar 21 13:41:49 hostname sshd[237915]: Accepted publickey for root from 193.55.51.152 port 41646 ssh2: RSA SHA256:wmFQ70BsRjT4uCWua2ddnbfFv7kiMecLHVNtZMw0KMk
> Mar 21 13:41:49 hostname sshd[237915]: pam_unix(sshd:session): session opened for user root by (uid=0)
> Mar 21 13:41:49 hostname systemd-logind[743]: New session 4844 of user root.
> Mar 21 13:41:49 hostname systemd[1]: Starting User Manager for UID 0...
> Mar 21 13:41:49 hostname systemd[237918]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
> Mar 21 13:41:49 hostname systemd[237918]: Found container virtualization none.
> Mar 21 13:41:49 hostname systemd[237918]: systemd 241 running in user mode for user 0/root. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELF
> Mar 21 13:41:49 hostname systemd[237918]: RLIMIT_MEMLOCK is already as high or higher than we need it, not bumping.
> Mar 21 13:41:49 hostname systemd[237918]: Found cgroup2 on /sys/fs/cgroup/unified, unified hierarchy for systemd controller
> Mar 21 13:41:49 hostname systemd[237918]: Unified cgroup hierarchy is located at /sys/fs/cgroup/unified/user.slice/user-0.slice/user@0.service. Controllers are on legacy hierarchies.
> Mar 21 13:41:49 hostname systemd[237918]: Got EBADF when using BPF_F_ALLOW_MULTI, which indicates it is supported. Yay!
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'cpu' supported: yes
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'cpuacct' supported: yes
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'io' supported: no
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'blkio' supported: yes
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'memory' supported: yes
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'devices' supported: yes
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'pids' supported: yes
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'bpf-firewall' supported: yes
> Mar 21 13:41:49 hostname systemd[237918]: Controller 'bpf-devices' supported: yes
> Mar 21 13:41:49 hostname systemd[237918]: Set up TFD_TIMER_CANCEL_ON_SET timerfd.
> Mar 21 13:41:49 hostname systemd[237918]: Serializing user-environment-generators to memfd.
> Mar 21 13:41:49 hostname systemd[237918]: Successfully forked off '(sd-executor)' as PID 237922.
> Mar 21 13:41:49 hostname systemd[237922]: Serializing 30-systemd-environment-d-generator to memfd.
> Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237923.
> Mar 21 13:41:49 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/30-systemd-environment-d-generator succeeded.
> Mar 21 13:41:49 hostname systemd[237922]: Serializing 60-flatpak to memfd.
> Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237924.
> Mar 21 13:41:49 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/60-flatpak succeeded.
> Mar 21 13:41:49 hostname systemd[237922]: Serializing 70-im-config to memfd.
> Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237927.
> Mar 21 13:42:02 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/70-im-config succeeded.
> 
> Therefore the problem is in /usr/lib/systemd/user-environment-generators/70-im-config.  Moving this file away solves the problem :>.
> 
> Should I reassign this bug to the im-config package ?

Yup, let's do this.

@Laurent: you can attach the output of "reportbug --template im-config"
so the im-config maintainers have a bit more context.

Regards,
Michael

[signature.asc (application/pgp-signature, attachment)]

Message #85 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu@debian.org>

To: Michael Biebl <biebl@debian.org>

Cc: Laurent Bonnaud <L.Bonnaud@laposte.net>, 925160@bugs.debian.org, im-config@packages.debian.org, yy.y.ja.jp@gmail.com

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Fri, 22 Mar 2019 04:42:50 +0900

Hi,

On Thu, Mar 21, 2019 at 05:51:45PM +0100, Michael Biebl wrote:
> Control: reassign -1 im-config
> Control: tags -1 - moreinfo
> Control: affects -1 + systemd
> 
> Am 21.03.19 um 13:51 schrieb Laurent Bonnaud:
> > On 20/03/2019 19.39, Michael Biebl wrote:
> > 
> >> Another info that might help give a clue is setting
> >> LogLevel=debug in /etc/systemd/user.conf, reboot, log in, then attach
> >> the output of journalctl --user -b
> > 
> > Thanks, it allowed me to find the cause of the problem:
> > 
> > Mar 21 13:41:49 hostname sshd[237915]: Accepted publickey for root from 193.55.51.152 port 41646 ssh2: RSA SHA256:wmFQ70BsRjT4uCWua2ddnbfFv7kiMecLHVNtZMw0KMk
> > Mar 21 13:41:49 hostname sshd[237915]: pam_unix(sshd:session): session opened for user root by (uid=0)
> > Mar 21 13:41:49 hostname systemd-logind[743]: New session 4844 of user root.
> > Mar 21 13:41:49 hostname systemd[1]: Starting User Manager for UID 0...
> > Mar 21 13:41:49 hostname systemd[237918]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
> > Mar 21 13:41:49 hostname systemd[237918]: Found container virtualization none.
> > Mar 21 13:41:49 hostname systemd[237918]: systemd 241 running in user mode for user 0/root. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELF
> > Mar 21 13:41:49 hostname systemd[237918]: RLIMIT_MEMLOCK is already as high or higher than we need it, not bumping.
> > Mar 21 13:41:49 hostname systemd[237918]: Found cgroup2 on /sys/fs/cgroup/unified, unified hierarchy for systemd controller
> > Mar 21 13:41:49 hostname systemd[237918]: Unified cgroup hierarchy is located at /sys/fs/cgroup/unified/user.slice/user-0.slice/user@0.service. Controllers are on legacy hierarchies.
> > Mar 21 13:41:49 hostname systemd[237918]: Got EBADF when using BPF_F_ALLOW_MULTI, which indicates it is supported. Yay!
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'cpu' supported: yes
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'cpuacct' supported: yes
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'io' supported: no
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'blkio' supported: yes
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'memory' supported: yes
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'devices' supported: yes
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'pids' supported: yes
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'bpf-firewall' supported: yes
> > Mar 21 13:41:49 hostname systemd[237918]: Controller 'bpf-devices' supported: yes
> > Mar 21 13:41:49 hostname systemd[237918]: Set up TFD_TIMER_CANCEL_ON_SET timerfd.
> > Mar 21 13:41:49 hostname systemd[237918]: Serializing user-environment-generators to memfd.
> > Mar 21 13:41:49 hostname systemd[237918]: Successfully forked off '(sd-executor)' as PID 237922.
> > Mar 21 13:41:49 hostname systemd[237922]: Serializing 30-systemd-environment-d-generator to memfd.
> > Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237923.
> > Mar 21 13:41:49 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/30-systemd-environment-d-generator succeeded.
> > Mar 21 13:41:49 hostname systemd[237922]: Serializing 60-flatpak to memfd.
> > Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237924.
> > Mar 21 13:41:49 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/60-flatpak succeeded.
> > Mar 21 13:41:49 hostname systemd[237922]: Serializing 70-im-config to memfd.
> > Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237927.
> > Mar 21 13:42:02 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/70-im-config succeeded.
> > 
> > Therefore the problem is in /usr/lib/systemd/user-environment-generators/70-im-config.  Moving this file away solves the problem :>.

This is a code to support uim under wayland/gnome3 as I understand.
This is new one from YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>.

Are you using none/ibus/uim/SCIM/fcitx/ ... which one?

> > Should I reassign this bug to the im-config package ?

If 3 second is the problem, YES.
 
> Yup, let's do this.
> 
> @Laurent: you can attach the output of "reportbug --template im-config"
> so the im-config maintainers have a bit more context.

Please.

Osamu

Message #90 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu@debian.org>

To: Michael Biebl <biebl@debian.org>

Cc: Laurent Bonnaud <L.Bonnaud@laposte.net>, 925160@bugs.debian.org, im-config@packages.debian.org, yy.y.ja.jp@gmail.com

Subject: Re: Bug#925160: systemd: user session slow to start (11 seconds)

Date: Fri, 22 Mar 2019 04:48:50 +0900

On Fri, Mar 22, 2019 at 04:42:50AM +0900, Osamu Aoki wrote:
...
> > > Mar 21 13:41:49 hostname systemd[237922]: Successfully forked off '(direxec)' as PID 237927.
> > > Mar 21 13:42:02 hostname systemd[237922]: /usr/lib/systemd/user-environment-generators/70-im-config succeeded.
> If 3 second is the problem, YES.

Oops. 13 seconds after forking before finishing.

But how can this simple script takles so much time...


Osamu

Message #95 received at 925160@bugs.debian.org (full text, mbox, reply):

From: "Aaron M. Ucko" <ucko@debian.org>

To: Debian Bug Tracking System <925160@bugs.debian.org>

Subject: Re: systemd: user session slow to start (11 seconds)

Date: Thu, 21 Mar 2019 20:43:03 -0400

Package: im-config
Version: 0.39-1
Followup-For: Bug #925160

I've also encountered slowness here, sometimes to the point of
tripping systemd timeouts.  The culprit appears to be repeatedly
searching /usr/lib via find -- on the system where this issue has
bitten me most badly, I have hundreds of thousands of directory
entries there (yes, I'm a packrat):

  $ locate /usr/lib/ | wc -l
  864543

Here are a few suggestions for ways to do better here:

* Bail right away for non-graphical sessions (possibly extending to
  ssh sessions with X forwarding).

* Use shell globbing (ls or even echo) rather than find ... -path ...
  unless you specifically need to traverse an unknown number of
  directory levels.
** You can probably rely on multiarch specifiers to contain hyphens:
   /usr/lib/*-*/gtk-2.0/*/immodules/im-ibus.so

* If you really do need find, consolidate searches more and split them
  back out as needed:
  IM_CONFIG_ALL_MARKERS="$(find /usr/lib \
                           -path '/usr/lib*/gtk-?.0/immodules/im-ibus.so' -o \
                           -path ... -o ...)"
  IM_CONFIG_MARKER="$(echo "$IM_CONFIG_ALL_MARKERS" | grep ...)"

* Search ahead of time on the basis of dpkg triggers, an apt hook,
  and/or a cron job (bearing in mind that cron job results may
  occasionally be inaccurate by the time sessions start).

Could you please consider them, or otherwise address this slowness?

Thanks!

-- System Information:
Debian Release: buster/sid
  APT prefers unstable-debug
  APT policy: (500, 'unstable-debug'), (500, 'testing-debug'), (500, 'testing'), (500, 'stable'), (300, 'unstable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386, x32

Kernel: Linux 4.19.0-2-amd64 (SMP w/4 CPU cores)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_WARN, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages im-config depends on:
ii  gettext-base  0.19.8.1-9

Versions of packages im-config recommends:
ii  kde-baseapps-bin  4:16.08.3-3
ii  kdialog           4:17.08.3-2
ii  whiptail          0.52.20-8
ii  x11-common        1:7.7+19
ii  zenity            3.30.0-2

im-config suggests no packages.

-- no debconf information

Message #100 received at 925160-close@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu@debian.org>

To: 925160-close@bugs.debian.org

Subject: Bug#925160: fixed in im-config 0.40-1

Date: Sat, 23 Mar 2019 20:50:57 +0000

Source: im-config
Source-Version: 0.40-1

We believe that the bug you reported is fixed in the latest version of
im-config, which is due to be installed in the Debian FTP archive.

A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 925160@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
Osamu Aoki <osamu@debian.org> (supplier of updated im-config package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@ftp-master.debian.org)


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

Format: 1.8
Date: Sun, 24 Mar 2019 05:03:35 +0900
Source: im-config
Binary: im-config
Architecture: source all
Version: 0.40-1
Distribution: unstable
Urgency: medium
Maintainer: Debian Input Method Team <debian-input-method@lists.debian.org>
Changed-By: Osamu Aoki <osamu@debian.org>
Description:
 im-config  - Input method configuration framework
Closes: 877312 925160
Changes:
 im-config (0.40-1) unstable; urgency=medium
 .
   [ YOSHINO Yoshihito ]
   * Speed up by avoid using "find" but work around ddm+zsh
     problem originally reported at Bug#905129.
 .
   [ Osamu Aoki ]
   * Disable im-config for Gnome on wayland by default.
     Closes: #925160, #877312
   * Add im-launch-wayland to simplify code.
   * Avoid running time consuming code section twice.
Checksums-Sha1:
 4a4e8519604f6d4e75529dbea62acc7389910f53 1864 im-config_0.40-1.dsc
 1981ea7fb6d2a7727ef17523aff90320895dfbcc 45240 im-config_0.40.orig.tar.xz
 b3b31a09cdf3dd8046cad6a81a7de9cdf9f84649 8740 im-config_0.40-1.debian.tar.xz
 e57beab851ca2a3026cbd6e72855346c8982e58e 55816 im-config_0.40-1_all.deb
 8e7563aae63f3e653df6375057d2f44352d68eca 5490 im-config_0.40-1_amd64.buildinfo
Checksums-Sha256:
 12445711ae6e82eff7a3a1f3990775eb423b0184977fe63946c36ebbf6976a74 1864 im-config_0.40-1.dsc
 24e82e8b001e18a4c54bad4b7f6178f2b20287f16690a13fa0bd4c561858a5ea 45240 im-config_0.40.orig.tar.xz
 c04da580e3da75f79d081d909b88e16efacd8ce69ac42ea9d0583c1e73bdc84a 8740 im-config_0.40-1.debian.tar.xz
 6d5a0e17512059a699eb557265ec6a78ff6762c0d6c5a5e22421105a3672c9a6 55816 im-config_0.40-1_all.deb
 313308f63888af9c22d4afcddacf5ca0c44eeef9d176a715c49f63f253e5c352 5490 im-config_0.40-1_amd64.buildinfo
Files:
 32e2cc499f97ba8f13dd31016be6039a 1864 x11 optional im-config_0.40-1.dsc
 b584e230f1def0f731e0231d2b304348 45240 x11 optional im-config_0.40.orig.tar.xz
 cd17e3164358de10cfa6f1e99709456a 8740 x11 optional im-config_0.40-1.debian.tar.xz
 dafd75400ab84510167cd2678709bcf6 55816 x11 optional im-config_0.40-1_all.deb
 d5236f6b3102821bef28688624e1d8b0 5490 x11 optional im-config_0.40-1_amd64.buildinfo

-----BEGIN PGP SIGNATURE-----

iQIyBAEBCgAdFiEEMTNyTWIHiBV56V1iHhNWiB3Y15EFAlyWkjsACgkQHhNWiB3Y
15HARw/4zfcITsrXTVbcaOG1LhZ+HahosyQy1a4/EzTNOvhexm3R5PUMHSH9uU1P
WBaf9WaNoCHaPxWTUngfhPN/4rWlWl7Sk8ASSuQR/Dv/HtX7IhKumdgBt5nCv1Bj
58V/3i6zTj5wuApP0Lu5ypKMDMrDEiMoqjajyQWkjauzdsX85vwaBU5yrhtJUClk
rOJVQVPGRn3V3KlPbJVmTYtnDxP6LKqLrT+EXqHRFG1wRgHRdNQ5afTAsbFTj80k
uB70R01NWlHkWbRSdg7VG63cjQ+mMo/Iatkx4/3TsMQ3aLzFJuj0LXyChdmbKHZF
yVS9TPAvut5sNBp9vxU4rOE6pBxlemjDgAUnPX2HqHwcr6yygQEEWbQkIxr62BGz
AvC6FE0gH8xRHR3ZYvUmKM0wNbWdSFRdp3DWe9rF0rgA1eeKSU0b3eFp7k6auUXo
9PY7JWkTO4z3houwIzudDeYNOhyrSRGTzkqTZdHEjfjy80gMgaVEzNpdWOgwa6q3
zuBWXhLku6bpJQXfHhcaaEhWtngclffk/KxPTQ3kkYspVerHnqXasPI64caUKSHd
EN/MEO5nJGC4LVKu2rF+uxpPgWNrLhwept3GLkbqqu8PAMd/75souNgs4UGMDSVj
bZYX7VzCdbi2DLw8YytBK+F+nu8MvdJjIuCrEDPRD6iIDR157Q==
=wJue
-----END PGP SIGNATURE-----

Message #105 received at 925160@bugs.debian.org (full text, mbox, reply):

From: YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>

To: 925160@bugs.debian.org, Laurent Bonnaud <L.Bonnaud@laposte.net>, "Aaron M. Ucko" <ucko@debian.org>

Cc: Osamu Aoki <osamu@debian.org>

Subject: request for performance test in your environment

Date: Sun, 24 Mar 2019 19:12:23 +0900

Dear all,

I have changed im-config in 0.40-1 to search directories with globbing
/usr/lib/*-*/ as suggested by Aaron M. Ucko <ucko@debian.org>.
I would like to see the performance test results (like ssh login) in
your environment with im-config (>= 0.40-1)
with "IM_CONFIG_WAYLAND=enable" in /etc/default/im-config, to see if
the change helps.

Thanks in advance,
-- 
YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>

Message #110 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu@debian.org>

To: YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>, 925160@bugs.debian.org

Cc: Laurent Bonnaud <L.Bonnaud@laposte.net>, "Aaron M. Ucko" <ucko@debian.org>

Subject: Re: Bug#925160: request for performance test in your environment

Date: Sun, 24 Mar 2019 22:06:08 +0900

Hi,

On Sun, Mar 24, 2019 at 07:12:23PM +0900, YOSHINO Yoshihito wrote:
> Dear all,
> 
> I have changed im-config in 0.40-1 to search directories with globbing
> /usr/lib/*-*/ as suggested by Aaron M. Ucko <ucko@debian.org>.

I also tweaked code in 0.40-1 before uploading.  Basically direcory
walking is halved.

> I would like to see the performance test results (like ssh login) in
> your environment with im-config (>= 0.40-1)
> with "IM_CONFIG_WAYLAND=enable" in /etc/default/im-config, to see if
> the change helps.

FYI: I have uploaded 0.41-1 which is essentially code clean up with
lintian warning removal actions such as adding autopkgtest data.
So use this 0.41-1, please.

I will be curious how these affects performance.

When you report, please tell us you use SSD or HDD for /usr/lib/*.

Also give us idea how many directories we are talking by including

 $ ls -1 /usr/lib /usr/lib/x86_64-linux-gnu|wc -l

Thanks you.

Osamu

Message #115 received at 925160@bugs.debian.org (full text, mbox, reply):

From: ucko@debian.org (Aaron M. Ucko)

To: Osamu Aoki <osamu@debian.org>

Cc: YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>, <925160@bugs.debian.org>, Laurent Bonnaud <L.Bonnaud@laposte.net>, "Aaron M. Ucko" <ucko@debian.org>

Subject: Re: Bug#925160: request for performance test in your environment

Date: Sun, 24 Mar 2019 22:04:44 -0400

Osamu Aoki <osamu@debian.org> writes:

> So use this 0.41-1, please.
>
> I will be curious how these affects performance.

Much better, thanks -- the hook now takes only about a second on my
system.  I have a traditional HDD with about 17,000 entries under
/usr/lib and /usr/lib/x86_64-linux-gnu.

-- 
Aaron M. Ucko, KB1CJC (amu at alum.mit.edu, ucko at debian.org)
http://www.mit.edu/~amu/ | http://stuff.mit.edu/cgi/finger/?amu@monk.mit.edu

Message #120 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Laurent Bonnaud <L.Bonnaud@laposte.net>

To: Osamu Aoki <osamu@debian.org>, YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>, 925160@bugs.debian.org

Cc: "Aaron M. Ucko" <ucko@debian.org>

Subject: Re: Bug#925160: request for performance test in your environment

Date: Mon, 25 Mar 2019 10:42:32 +0100

On 3/24/19 2:06 PM, Osamu Aoki wrote:

> FYI: I have uploaded 0.41-1 which is essentially code clean up with
> lintian warning removal actions such as adding autopkgtest data.
> So use this 0.41-1, please.

Thanks a lot!

> I will be curious how these affects performance.

SSH connections are now almost instantaneous on my system.

> When you report, please tell us you use SSD or HDD for /usr/lib/*.

My system has a SSD.

> Also give us idea how many directories we are talking by including
> 
>  $ ls -1 /usr/lib /usr/lib/x86_64-linux-gnu|wc -l

18279

Thanks again,

-- 
Laurent.

Message #125 received at 925160@bugs.debian.org (full text, mbox, reply):

From: YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>

To: Laurent Bonnaud <L.Bonnaud@laposte.net>

Cc: Osamu Aoki <osamu@debian.org>, 925160@bugs.debian.org, "Aaron M. Ucko" <ucko@debian.org>

Subject: Re: Bug#925160: request for performance test in your environment

Date: Mon, 25 Mar 2019 22:59:23 +0900

Hi,

Thank you very much for your cooperation.

On Mon, Mar 25, 2019 at 6:42 PM Laurent Bonnaud <L.Bonnaud@laposte.net> wrote:
> > I will be curious how these affects performance.
>
> SSH connections are now almost instantaneous on my system.

I would like to confirm your performance test condition.
Does your /etc/default/im-config have "IM_CONFIG_WAYLAND=enable" set
(uncommented)?
If not, I would like to see the difference between the result you have
shown (with "IM_CONFIG_WAYLAND=disable")
and the one with "IM_CONFIG_WAYLAND=enable".

Thanks in advance,

-- 
YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>

Message #130 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu@debian.org>

To: "Aaron M. Ucko" <ucko@debian.org>, Laurent Bonnaud <L.Bonnaud@laposte.net>

Cc: YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>, 925160@bugs.debian.org

Subject: Re: Bug#925160: request for performance test in your environment

Date: Mon, 25 Mar 2019 23:20:38 +0900

Hi,

I think both of you see improvement.  (SSD and HDD)

package as installed disables im-config for wayland.

That's good but can you also tell us difference between 

IM_CONFIG_WAYLAND=disable

and 

IM_CONFIG_WAYLAND=enable

in /etc/default/im-config for YOSHINO-san's point. 

(You know what I mean, I hope)

Did you notice difference?  How much?

FYI:

If I can depend on dpkg-dev, I realize I can use be specific for
multiarch path using

$ dpkg-architecture -q DEB_HOST_MULTIARCH
x86_64-linux-gnu

Is these better way to get the primary multiarch path name?

$ pwd
/usr/lib
$ ls -1|wc -l
367
$ ls -1|grep -e "-" |wc -l
74
$ ls -1|grep -e "-.*-" |wc -l
18
$ ls -1|grep -e "x86_64-linux-gnu" |wc -l
1

So time difference should be:
  Original program run twice    --> 734
  Current one has - and rn once -->  74
  If specify                    -->   1
There is more to improve ...

(I can't do it during the build since this is arch ALL package)

Regards,

Osamu

Message #139 received at 925160@bugs.debian.org (full text, mbox, reply):

From: ucko@debian.org (Aaron M. Ucko)

To: Osamu Aoki <osamu@debian.org>

Cc: "Aaron M. Ucko" <ucko@debian.org>, Laurent Bonnaud <L.Bonnaud@laposte.net>, YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>, <925160@bugs.debian.org>

Subject: Re: Bug#925160: request for performance test in your environment

Date: Thu, 28 Mar 2019 22:47:19 -0400

Osamu Aoki <osamu@debian.org> writes:

> IM_CONFIG_WAYLAND=disable

===> multitime results
1: -q /usr/lib/systemd/user-environment-generators/70-im-config
            Mean        Std.Dev.    Min         Median      Max
real        0.001       0.000       0.001       0.001       0.002       
user        0.001       0.000       0.000       0.001       0.001       
sys         0.000       0.001       0.000       0.000       0.001       

> IM_CONFIG_WAYLAND=enable

===> multitime results
1: -q /usr/lib/systemd/user-environment-generators/70-im-config
            Mean        Std.Dev.    Min         Median      Max
real        0.004       0.000       0.003       0.004       0.004       
user        0.003       0.001       0.001       0.003       0.005       
sys         0.001       0.001       0.000       0.002       0.004       

... so quite fast either way.

> Is these better way to get the primary multiarch path name?

Not to my knowledge. :-/

> (I can't do it during the build since this is arch ALL package)

I suppose you could formally make it architecture: any for this purpose;
the package is small enough that the resulting duplication would be no
big deal.

-- 
Aaron M. Ucko, KB1CJC (amu at alum.mit.edu, ucko at debian.org)
http://www.mit.edu/~amu/ | http://stuff.mit.edu/cgi/finger/?amu@monk.mit.edu

Message #144 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu@debian.org>

To: 925160@bugs.debian.org

Cc: YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>

Subject: systemd: user session slow to start (11 seconds)

Date: Sat, 30 Mar 2019 00:14:09 +0900

control: summary -1 0 slow to start user ssh session (11 seconds)

Hi,

I reopened this bug since the current unstable package isn't good enough
and requires some touch up to get accepted for testing.

Problem:
========
 * The default desktop Debain install is Gnome-wayland.
 * Some localization tasks pull in im-config (its important)
 * The testing had im-config=0.39-1
 * Im-config=0.39-1 caused major degradation to the ssh login with
   11 unresponsive latency under wayland+systemd.
 * The root cause was the slow script run by im-config during the start of
   a new process to set its environment variable using the systemd's
   systemd.environment-generator(7).
 * this performance degradation of the default system is unacceptable.


Bug #925160 back ground:
========================
Many unnoticed performance bugs crept into im-config to cause this bug.

 * Nov 2011 (version 0.5) -- older than oldstable/jessie
   Since im-config is ARCH=all package, it used "*" as the path part for
   the multiarch such as x86_64-linux-gnu 
   --> This should have been "*-*-*" instead of just "*"
 * Feb 2015 (version 0.27-2) jessie released version
 * Dec 2016 (version 0.30-1) stretch released version
 * Bug #905129: im-config: Wrongly run shell scripts with user's shell
                interpreter, raises error with zsh (Jul 2018)
   This was really a problem of KDE + sddm.
 * Aug 2018 (0.37-1) -- during buster development cycle
   im-config worked around bug #905129 by replacing shell glob with a
   shell function call which runs script with "find" command.
   --> This should have been worked around by using the simple one liner: 
       if [ x != x"$ZSH_NAME" ]; then emulate -R sh ; fi
 * Mar 2019 (version 0.40-1)
   Patch provided by Y. Yoshino was applied to make im-config useful for
   Gnome-wayland.  Since gnome-session has no easy hook script
   mechanism like /etc/X11/Xsession.d/* files for X, this patch decided
   to use systemd.environment-generator(7) to set the user environment.
   --> This script run the problematic slow code twice which made situation
       worse.
   --> This startup code should have been disabled if it finds
       ibus-daemon just as gnome-session (main.c) does.
   --> This startup code should run only when it finds
       XDG_SESSION_TYPE=wayland (ideally -- but can't check it if
       systemd.environment-generator is used)
 * Bug #925160 systemd: user session slow to start (11 seconds) (Mar 2019)
   Since 0.40-1 used systemd.environment-generator, the hook scrip was
   run even for ssh login and delay of 11 seconds was noticed. ssh with
   X-session doesn't have this problem for ssh and 11 second during X
   start up may not be as annoying.

How to solve Bug #925160:
=========================
 * Fix glob to use "*-*-*"
 * Use "emulate -R sh" trick (not script with "find") for zsh
 * save environment variables to avoid running the problematic slow code
   twice
 * check existence of ibus-daemon and disable systemd.environment-generator
   script if you find it.


Technical reference:
====================
 $ cd /usr/lib
 $ ( ls -1d * ; ls -1d * )|wc -l
734
 $ ls -1d *-*   |wc -l
74
 $ ls -1d *-*-* |wc -l
18

So not running slow glob twice and changing "*" --> "*-*-*" can improve
speed 40 times!

Shell glob approach is faster than script with "find"

Future vision:
==============
I see 2 parts of code which may be patched to make cleaner solution
 * gnome-session ibus related environment variable setting
 * gnome-shell:  ibus starting code
But that is for future.

im-config's complicated time consuming code may be useless to start with
from today's situation since settings such as:
  GTK_IM_MODULE=xim
  QT4_IM_MODULE=xim
are not good idea .  It is usually a source of lost key input etc.
It's now better to use settings such as:
  GTK_IM_MODULE=ibus
  QT4_IM_MODULE=ibus

This simplify code greatly but doing this may be too late for buster
under freeze.

Osamu

Message #151 received at 925160-close@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu@debian.org>

To: 925160-close@bugs.debian.org

Subject: Bug#925160: fixed in im-config 0.42-1

Date: Fri, 29 Mar 2019 16:37:22 +0000

Source: im-config
Source-Version: 0.42-1

We believe that the bug you reported is fixed in the latest version of
im-config, which is due to be installed in the Debian FTP archive.

A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 925160@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
Osamu Aoki <osamu@debian.org> (supplier of updated im-config package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@ftp-master.debian.org)


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

Format: 1.8
Date: Sat, 30 Mar 2019 00:55:07 +0900
Source: im-config
Binary: im-config
Architecture: source all
Version: 0.42-1
Distribution: unstable
Urgency: medium
Maintainer: Debian Input Method Team <debian-input-method@lists.debian.org>
Changed-By: Osamu Aoki <osamu@debian.org>
Description:
 im-config  - Input method configuration framework
Closes: 925160
Changes:
 im-config (0.42-1) unstable; urgency=medium
 .
   * Better fix to reopened #925160 by:
     - Fix glob to use "*-*-*"
     - Use "emulate -R sh" trick (not script with "find") for zsh
     - Save environment variables to avoid running the problematic
       slow code twice
     - Check the existence of ibus-daemon to disable
       systemd.environment-generator script.
     - Separate wayland code from Xsession ones.
     - Move one line code from desktop to separated wayland code.
   * The above combination.  Closes: #925160
Checksums-Sha1:
 1126a0e6641be2d83e749e45df409a43f65ec244 1887 im-config_0.42-1.dsc
 6bf12342243076af7af7f9a5ee3a4720492e5724 45136 im-config_0.42.orig.tar.xz
 ba007bbed3d5ffd0f41e5f5667394c171324d8ef 8948 im-config_0.42-1.debian.tar.xz
 7bf8b4e1f7c32069bde140b52e50fce301202e05 55832 im-config_0.42-1_all.deb
 85080d72a06aa03fb27507140ca489ca0fc75ac5 5490 im-config_0.42-1_amd64.buildinfo
Checksums-Sha256:
 6da17eead5f513d5817fe3771eb5c1f1c08bac29c758628967f5b94f921abdf4 1887 im-config_0.42-1.dsc
 396cd1721519dda2edfc3bb1d4e1dd3f80db4876edd1533404c72115fcdef145 45136 im-config_0.42.orig.tar.xz
 93fbf4cbbef658c54e1ff323d06306dadf0256e6d69b7a2963207e5687ec3cdf 8948 im-config_0.42-1.debian.tar.xz
 4613cb2f2f5d12a3c6bb62c7a17476372323ce9ec7e149d68bc7287eaf8fa602 55832 im-config_0.42-1_all.deb
 de1e429a28839b237ca961b831cd72ad25558c380aedc406724f3c21af0479b8 5490 im-config_0.42-1_amd64.buildinfo
Files:
 6056d5d59e6823531ef3f9cb36864292 1887 x11 optional im-config_0.42-1.dsc
 5829d27cb9a12da26f38616fba4c0b5c 45136 x11 optional im-config_0.42.orig.tar.xz
 74fa522d3a43000d43b5b4dad0732727 8948 x11 optional im-config_0.42-1.debian.tar.xz
 83c094e751ab4ea3e1bc7533a439e903 55832 x11 optional im-config_0.42-1_all.deb
 e24e04ec42abb56efaf6cf1dbab033a6 5490 x11 optional im-config_0.42-1_amd64.buildinfo

-----BEGIN PGP SIGNATURE-----

iQIzBAEBCgAdFiEEMTNyTWIHiBV56V1iHhNWiB3Y15EFAlyeRIgACgkQHhNWiB3Y
15EigA//V8uo7jGWmUP5ijlLCpHE4200rpAJRs7tTxJbnvMXypVThDHOSUEXn/e1
1yiIiJDTil8SMMHdjwF2+CCknx/H2jWJHcTosXtvkPGznbZagNOdVnufnpvMgcCp
HmnD71ftz16QU/6LLHojLVBDG4yd3uie9fJ8Gn/05FmKPhRx2FsnFbxF6oWH8SEn
Icvv505CJTTmiQu+S344oK0TnFr5twKwCghaGz6FMwy0pvmpftq1pEFXBG4Y5IbZ
IT1hLVQp6u6mmR4dK5O7OTWqErQpxu8N+tcr0lODDhyfjPsNhDOy61n28D2bRYMn
HN40YlrmX3X9LR/p6aJM76G9WIKQTue1tiqfu5J60hrybXRmvozlRmUh2e1mGhlj
YpXrH0cSZHb2XJuXfdp4YqaM1rsAOB12G6sGggJqUj+uxFGMw4KnCi3pROMhXPLs
4f2xxJAjDoPVDqsofVQTCsi7qSvFy3dx57ZnHbUGaQ8m07fFIJdJrgh/lxu10ZPq
fvgFCUlhlF26btm8en57e9yLE6QL11aWBkqDfBrxzzoXfoPSd/snqv0lKCjF/Ukb
747kVuVfdbgBS+c7mcR0dPyb+VmtwXMqwl9WgFW/wF8+RhxCqtAoFlSE/a09y6I9
2CBBoCKqPI9ChCdwqoGNm0ZB5ZNiVBiaIxMfH3UQqp/Gg33MkMo=
=W16v
-----END PGP SIGNATURE-----

Message #160 received at 925160@bugs.debian.org (full text, mbox, reply):

From: ucko@debian.org (Aaron M. Ucko)

To: <925160@bugs.debian.org>

Cc: Osamu Aoki <osamu@debian.org>, Laurent Bonnaud <L.Bonnaud@laposte.net>, YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>

Subject: Re: Bug#925160: request for performance test in your environment

Date: Sat, 30 Mar 2019 22:17:39 -0400

Please note that the Hurd (admittedly not a release architecture) uses a
multiarch tag of hurd-i386, with only two components, which is why I'd
suggested *-* rather than *-*-*.  Sorry for not stating that explicitly
earlier.

-- 
Aaron M. Ucko, KB1CJC (amu at alum.mit.edu, ucko at debian.org)
http://www.mit.edu/~amu/ | http://stuff.mit.edu/cgi/finger/?amu@monk.mit.edu

Message #165 received at 925160@bugs.debian.org (full text, mbox, reply):

From: amu@alum.mit.edu (Aaron M. Ucko)

To: <925160@bugs.debian.org>

Cc: Osamu Aoki <osamu@debian.org>, Laurent Bonnaud <L.Bonnaud@laposte.net>, YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>

Subject: Re: Bug#925160: request for performance test in your environment

Date: Sat, 30 Mar 2019 22:19:13 -0400

I meant i386-gnu for the Hurd; sorry for the thinko.

-- 
Aaron M. Ucko, KB1CJC (amu at alum.mit.edu, ucko at debian.org)
http://www.mit.edu/~amu/ | http://stuff.mit.edu/cgi/finger/?amu@monk.mit.edu

Message #170 received at 925160@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu.aoki@gmail.com>

To: "Aaron M. Ucko" <amu@alum.mit.edu>

Cc: 925160@bugs.debian.org, Osamu Aoki <osamu@debian.org>, Laurent Bonnaud <L.Bonnaud@laposte.net>, YOSHINO Yoshihito <yy.y.ja.jp@gmail.com>

Subject: Re: Bug#925160: request for performance test in your environment

Date: Sun, 31 Mar 2019 11:37:15 +0900

Aaron

Thanks for reminder

The latest code candidate doesn’t use glob any more to reduce diff following Yoshino-san’s suggestion 

Now question are possible other regressions to fcitx and scim 

Sent from iPhone 

2019/03/31 11:19、Aaron M. Ucko <amu@alum.mit.edu>のメール:

> I meant i386-gnu for the Hurd; sorry for the thinko.
> 
> -- 
> Aaron M. Ucko, KB1CJC (amu at alum.mit.edu, ucko at debian.org)
> http://www.mit.edu/~amu/ | http://stuff.mit.edu/cgi/finger/?amu@monk.mit.edu

Message #175 received at 925160-close@bugs.debian.org (full text, mbox, reply):

From: Osamu Aoki <osamu@debian.org>

To: 925160-close@bugs.debian.org

Subject: Bug#925160: fixed in im-config 0.43-1

Date: Sun, 31 Mar 2019 14:47:51 +0000

Source: im-config
Source-Version: 0.43-1

We believe that the bug you reported is fixed in the latest version of
im-config, which is due to be installed in the Debian FTP archive.

A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 925160@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
Osamu Aoki <osamu@debian.org> (supplier of updated im-config package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@ftp-master.debian.org)


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

Format: 1.8
Date: Sat, 30 Mar 2019 21:06:10 +0900
Source: im-config
Binary: im-config
Architecture: source all
Version: 0.43-1
Distribution: unstable
Urgency: medium
Maintainer: Debian Input Method Team <debian-input-method@lists.debian.org>
Changed-By: Osamu Aoki <osamu@debian.org>
Description:
 im-config  - Input method configuration framework
Closes: 925160 926016
Changes:
 im-config (0.43-1) unstable; urgency=medium
 .
   * Minimal change from the testing 0.39-1 upload aiming for buster release.
   * The slow execution #925160 bug is addressed by disabling useless
     checks by imconfig_find_files_with_prefixpath_glob.
   * The 0.39-1 upload caused regression on the most common Gnome wayland
     system with ibus since Gnome also tries to set up input method.
     This regression is fixed by making 70-im-config and
     im-launch.desktop conditional to the existence of ibus-daemon.
     Closes: #925160
   * The 0.39-1 upload caused another regression of lost $HOME value.
     This regression is fixed by adding HOME to the env command argument
     in im-launch.
   * House keeping to erase conffile introduced by some unstable packages
     using dpkg-maintscript-helper.  Closes: #926016
Checksums-Sha1:
 593e97e315e925920ad96560ae9f986589d4c201 1864 im-config_0.43-1.dsc
 d941fb1f52c8041d06095e20cdcecfebd42ea9f0 45124 im-config_0.43.orig.tar.xz
 9c68185b17b33e4493ec346057d24600c8ecdcfe 9296 im-config_0.43-1.debian.tar.xz
 cf8ae87d7fb76d543e0336b07222e47006ad9697 55964 im-config_0.43-1_all.deb
 0e69347281b4e5158290d7a4e9aaa690eb5ad258 5490 im-config_0.43-1_amd64.buildinfo
Checksums-Sha256:
 696c7a2d8de927c3c6af24095fd3de51f600819d2d1d42f049299f98015812af 1864 im-config_0.43-1.dsc
 acfe16cc0c5b77e2d047626f7b1d73420e423c66664e23fc78b22bae7618e173 45124 im-config_0.43.orig.tar.xz
 0f1d497b6f3d1dc8911dc1a2bf1feb37111c1d07ee01c1f47e2874e9dd68bc6a 9296 im-config_0.43-1.debian.tar.xz
 81ff3a5fff6dd9f97f7b962fa9eaacb31dc37289699c198b96e832252dc82eb6 55964 im-config_0.43-1_all.deb
 ff1c77e56048304fdfe12439e99f1d32d7f81aac0636ae5d3855a7305f26b9c7 5490 im-config_0.43-1_amd64.buildinfo
Files:
 61fe314604383886b2a350aac7145389 1864 x11 optional im-config_0.43-1.dsc
 7a45a7e0fe66be16526ee41f81fffd79 45124 x11 optional im-config_0.43.orig.tar.xz
 fa86dc9b9b0fbbcc4a1bd39e963f13c7 9296 x11 optional im-config_0.43-1.debian.tar.xz
 ba4bb8f8a9770288fc31a7fe126eb063 55964 x11 optional im-config_0.43-1_all.deb
 e278a357928c8b43301e82657bbf06ae 5490 x11 optional im-config_0.43-1_amd64.buildinfo

-----BEGIN PGP SIGNATURE-----

iQIzBAEBCgAdFiEEMTNyTWIHiBV56V1iHhNWiB3Y15EFAlygy4gACgkQHhNWiB3Y
15HQdg//cWKn3mdD4XYu246ETcsAeZKvGqbEmFKTvA2OzQXHS4SW49Lo+98BukEJ
MlyTW91wF9ptxj4SOWWCtMxvmkA0LhrgCZuG46txt3f5L2sE3caYJsAxCpVwvo9Q
oeA9q41jZSL3u5gO+o8sLaMXx5FKkygfMy8L5duuc7OLecwmPR5nkQntiux3UvTQ
L+LtPDVKhtP00Gv9HsALWqrrQux+esvzOumESNL1GT8OXAFp6XxRAIQWtD79qM+C
tXBqs5fGJbjbN5PaotZHUZiZjCTrDEPyoMCBxv1ueWM8XZVocp1k2/SOWmZ9nbhE
bNCS0xg0JNGytfCzaBqtfgpgjUPUebNnpQOuua6Cga/5FeXMn9pnxgj2fnO/YP3D
hY8IyAPDf/ep/bTePeMnG1t2lqaloaR0k/ENF453jkNR3rkBX85JKzhaEf6jPD8h
4rqmGNt/lGeZdt5lYEVbJzz7BAxKcduiO9qaGh84YH5XHLLDrtp8dRrAx4BBHZP7
wY0b+I+20jrCHS4jm5LYobQTDrnL5q5DLjTul4kU3dImhlxv89qogDHhZDhJsmCo
83ejv87uV/B96DeIrIQsPRhMqw3ZnEemE/r1w2l4+963EkfSV3F26qfd8whJPG9a
93nEeBTtHkJcmvEMqCvRnWBznCZ5dIPjBTmtGwP+ojZUNi/ll5I=
=eBzn
-----END PGP SIGNATURE-----

Send a report that this bug log contains spam.