google-chrome startup delay

[marmarek]

Reported by joanna on 28 Jun 2012 12:42 UTC
I used to have the same thing in f15, not it happens on f17 as well. Here's a fragment of strace (new line added manually before "Gtk-Message" error):

14:35:37 gettimeofday({1340886937, 917929}, {0, 17593804676615}) = 0
14:35:37 gettimeofday({1340886937, 922383}, {0, 140734337615576}) = 0
14:35:37 futex(0x7fff44338704, FUTEX_WAIT_PRIVATE, 1, NULL
Gtk-Message: Failed to load module "pk-gtk-module"
[Failed to call method: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
) = 0
14:36:02 gettimeofday({1340886962, 114936}, {0, 0}) = 0
14:36:02 futex(0x7fff443386d8, FUTEX_WAKE_PRIVATE, 1) = 0
14:36:02 --- SIGPROF {si_signo=SIGPROF, si_code=SI_KERNEL} ---

Sometime this trace looks different:

14:40:41 readlink("/home/user/.config/google-chrome/SingletonSocket", "/tmp/.com.google.Chrome.wN40HW/S"..., 4096) = 46
14:40:41 readlink("/home/user/.config/google-chrome/SingletonCookie", "17525233685009578478", 4096) = 20
14:40:41 readlink("/tmp/.com.google.Chrome.wN40HW/SingletonCookie", "17525233685009578478", 4096) = 20
14:40:41 connect(45, {sa_family=AF_FILE, sun_path="/home/user/.config/google-chrome/SingletonSocket"}, 110) = 0
14:40:41 readlink("/tmp/.com.google.Chrome.wN40HW/SingletonCookie", "17525233685009578478", 4096) = 20
14:40:41 setsockopt(45, SOL_SOCKET, SO_SNDTIMEO, "\24\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0
14:40:41 getcwd("/rw/home/user", 4096)  = 14
14:40:41 write(45, "START\0/rw/home/user\0/bin/google-"..., 80) = 80
14:40:41 shutdown(45, SHUT_WR)          = 0
14:40:41 select(46, [45](1721:1734:552990954:ERROR:object_proxy.cc(489)]), NULL, NULL, {20, 0}

Gtk-Message: Failed to load module "pk-gtk-module"
) = 0 (Timeout)
14:41:01 readlink("/home/user/.config/google-chrome/SingletonLock", "personal-1924", 4096) = 13
14:41:01 uname({sys="Linux", node="personal", ...}) = 0
14:41:01 unlink("/home/user/.config/google-chrome/SingletonLock") = 0

The common denominator seems to be the 'pk-gtk-module'...?

As we can see this cause a 20+ sec delay on start the Chrome Browser, which degrades the user experience.

Migrated-From: https://wiki.qubes-os.org/ticket/611

[marmarek]

Comment by marmarek on 1 Jul 2012 17:21 UTC
'pk-gtk-module' looks irrelevant for me. The call that cause delay is

14:40:41 connect(45, {sa_family=AF_FILE, sun_path="/home/user/.config/google-chrome/SingletonSocket"}, 110) = 0
(...)
14:40:41 select(46, [45], NULL, NULL, {20, 0}) = 0 (Timeout)

which is wait for reply from /home/user/.config/google-chrome/SingletonSocket. For me it looks like some mechanism to wake already running instance of chrome, but actually no instance was running. Looks like bug in chrome, not related to Qubes...

[marmarek]

Comment by marmarek on 1 Jul 2012 17:21 UTC
'pk-gtk-module' looks irrelevant for me. The call that cause delay is

14:40:41 connect(45, {sa_family=AF_FILE, sun_path="/home/user/.config/google-chrome/SingletonSocket"}, 110) = 0
(...)
14:40:41 select(46, [45], NULL, NULL, {20, 0}) = 0 (Timeout)

which is wait for reply from /home/user/.config/google-chrome/SingletonSocket. For me it looks like some mechanism to wake already running instance of chrome, but actually no instance was running. Looks like bug in chrome, not related to Qubes...

[marmarek]

Comment by joanna on 4 Jul 2012 08:33 UTC
It is very unlikely to be a bug in Chrome, because it has been present for some time now, and I cannot believe users living with that without complaining...

[marmarek]

Comment by joanna on 4 Jul 2012 08:33 UTC
It is very unlikely to be a bug in Chrome, because it has been present for some time now, and I cannot believe users living with that without complaining...

[marmarek]

Comment by marmarek on 4 Jul 2012 10:51 UTC
Hmm... I've found on the web some complains about slow startup, caused by proxy discovery, but it wasn't the case here. Actually the cause is in Dbus error message - chrome tries to start NetworkManager (via dbus), which is disabled in AppVM so timeout occurs. Unfortunately dbus do not recognize disabled (by start condition) systemd units and "systemctl start dbus-org.freedesktop.NetworkManager.sevice" returns 0, but does nothing...

This is the same issue as in #610 so marking as duplicate.

[marmarek]

Comment by marmarek on 4 Jul 2012 10:51 UTC
Hmm... I've found on the web some complains about slow startup, caused by proxy discovery, but it wasn't the case here. Actually the cause is in Dbus error message - chrome tries to start NetworkManager (via dbus), which is disabled in AppVM so timeout occurs. Unfortunately dbus do not recognize disabled (by start condition) systemd units and "systemctl start dbus-org.freedesktop.NetworkManager.sevice" returns 0, but does nothing...

This is the same issue as in #610 so marking as duplicate.