#591397 Iceweasel produces error popups before starting and runs incredibly slowly

Package:
libdbus-1-3
Source:
dbus
Description:
simple interprocess messaging system (library)
Submitter:
Richard Kettlewell
Date:
2010-08-09 09:00:05 UTC
Severity:
normal
#591397#5
Date:
2010-08-02 19:18:45 UTC
From:
To:
Iceweasel runs extremely slowly in my unstable VM.  This is a relatively
new development (it used to be acceptable fast).

First, it displays dialog box but removes it too quickly to read it,
then after a while displays one which reads:

   An error occurred while loading or saving
   configuration information for firefox-bin. Some of
   your configuration settings may not work properly.

There are Details and OK buttons, neither of which appear to do anything.

After waiting a bit more a large, empty window appears.  A bit after
that the title changes to match the page I wanted to visit.  With
sufficient patience it does actually display the web page.

System load remains very low (<0.1) during all of this.

An strace fragment while it's failing to get anywhere:

open("/var/lib/dbus/machine-id", O_RDONLY) = 46
fstat64(46, {st_mode=S_IFREG|0644, st_size=33, ...}) = 0
read(46, "620e4e5789a46d4838ff0b004746dfa0"..., 33) = 33
close(46)                               = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
pipe([46, 48])                          = 0
pipe([55, 60])                          = 0
clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0xb7583748) = 2517
close(48)                               = 0
close(60)                               = 0
read(46, "unix:abstract=/tmp/dbus-VqVjSbtp"..., 1024) = 81
read(46, "", 1024)                      = 0
waitpid(2517, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 2517
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
close(46)                               = 0
close(55)                               = 0
socket(PF_FILE, SOCK_STREAM, 0)         = 46
connect(46, {sa_family=AF_FILE, path=@"/tmp/dbus-VqVjSbtpYZ"}, 23) = -1
ECONNREFUSED (Connection refused)
close(46)                               = 0
open("/var/lib/dbus/machine-id", O_RDONLY) = 46
fstat64(46, {st_mode=S_IFREG|0644, st_size=33, ...}) = 0
read(46, "620e4e5789a46d4838ff0b004746dfa0"..., 33) = 33
close(46)                               = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
pipe([46, 48])                          = 0
pipe([55, 60])                          = 0
clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0xb7583748) = 2522
close(48)                               = 0
close(60)                               = 0
read(46, ^C <unfinished ...>
Process 1748 detached

I tried erasing ~/.mozilla and reinstalling both iceweasel and dbus, but
the behavior is the same (possibly a little faster but still hopelessly
slow).  However a later strace doesn't show any mention of dbus, so it
might well be unrelated.

There is nothing at all relevant-looking in /var/log/kern.log or
/var/log/daemon.log.

$ uname -a
Linux deodand 2.6.32-5-686-bigmem #1 SMP Sat Jul 24 03:13:16 UTC 2010
i686 GNU/Linux

ii  iceweasel      3.5.11-1       Web browser based on Firefox
ii  libc6          2.11.2-2       Embedded GNU C Library: Shared libraries

ttfn/rjk

#591397#10
Date:
2010-08-02 20:12:23 UTC
From:
To:
environment variable, but no corresponding session. Try unsetting that
environment variable.

Mike

#591397#15
Date:
2010-08-02 20:23:23 UTC
From:
To:
Doesn't look like it.

richard@deodand:~$ env|grep -i dbus
richard@deodand:~$ env|sort
DISPLAY=localhost:10.0
EDITOR=emacs
HOME=/home/richard
http_proxy=http://www-proxy:3128/
LANG=en_GB.UTF-8
LOGNAME=richard
MAIL=/var/mail/richard
PATH=/usr/local/gimp-2.7/bin:/usr/local/sbin:/usr/sbin:/sbin:/usr/local/bin:/usr/bin:/bin:/usr/games
PKG_CONFIG_PATH=/usr/local/gimp-2.7/lib/pkgconfig
PWD=/home/richard
SHELL=/bin/bash
SHLVL=1
SSH_CLIENT=172.17.207.8 51611 22
SSH_CONNECTION=172.17.207.8 51611 172.17.207.12 22
SSH_TTY=/dev/pts/0
TERM=dtterm
USER=richard
_=/usr/bin/env
richard@deodand:~$

ttfn/rjk

#591397#20
Date:
2010-08-03 12:58:16 UTC
From:
To:
Can you then try to install iceweasel-dbg and gdb, then run iceweasel -g.
At the gdb prompt, rype run, then when startup looks frozen, press ctrl+c
and then get a full backtrace with "bt full". Please paste its output here.
Try several times during startup. I'd expect the resulting traces to look
similar.

Mike

#591397#25
Date:
2010-08-04 18:29:37 UTC
From:
To:
OK, attached.

ttfn/rjk

#591397#30
Date:
2010-08-04 18:41:43 UTC
From:
To:
Thanks. It looks like it's blocking on dbus access triggered by gconf.
Do other gconf using programs have the same problem ?
Is dbus installed and  running on your system ?

Mike

#591397#35
Date:
2010-08-04 19:12:37 UTC
From:
To:
It looks like dbus is running:

richard@deodand:~$ ps -ef |grep dbus
103        906     1  0 Aug02 ?        00:00:00 /usr/bin/dbus-daemon
--system
richard  23759 23744  0 20:05 pts/0    00:00:00 grep dbus

gconf doesn't seem to take unreasonably long, using an example from the
man page:

richard@deodand:~$ time gconftool-2 --get
/desktop/gnome/background/picture_filename
/usr/share/images/desktop-base/desktop-background

real	0m0.125s
user	0m0.104s
sys	0m0.020s

...but strace indicates that command just reads files rather than doing
any IPC, so I could be checking in the wrong way.

ttfn/rjk

#591397#40
Date:
2010-08-08 07:25:07 UTC
From:
To:
Could you attach a full strace output for iceweasel ?

Mike

#591397#45
Date:
2010-08-08 11:25:35 UTC
From:
To:
Attached.  Command was "strace -r -q -o trace -f iceweasel".

ttfn/rjk

#591397#50
Date:
2010-08-09 07:48:24 UTC
From:
To:
10037      0.000075 mkdir("/home/richard/.dbus", 0700) = -1 EEXIST (File exists)
10037      0.000061 mkdir("/home/richard/.dbus/session-bus", 0700) = -1 EACCES (Permission denied)
10037      0.000198 write(2, "Unable to create /home/richard/."..., 49) = 49
10037      0.000082 open("/home/richard/.dbus/session-bus/620e4e5789a46d4838ff0b004746dfa0-10", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)

Arguably, it shouldn't have such a startup impact, but that would be a
problem with how dbus operates, imho.

Can you check the permissions in these directories, fix them, and see if
it works better? If so, we'll reassign to dbus.

Mike

#591397#55
Date:
2010-08-09 08:22:54 UTC
From:
To:
*red face*

richard@deodand:~$ ls -ld .dbus
drwx--S--- 3 root richard 4096 Nov 22  2009 .dbus

With that fixed it works fine.

Sorry for the waste of time!

ttfn/rjk

#591397#60
Date:
2010-08-09 08:56:40 UTC
From:
To:
reassign 591397 libdbus-1-3
thanks

I still think there must be something wrong with how dbus handles that,
as it shouldn't lead to such a delay in application startup.

Cheers,

Mike