712471 - Thunderbird and dbus-daemon eat 100% CPU when transitioning to list view tab

Status: RESOLVED INCOMPLETE

(Thunderbird :: General, defect)

Description

[kcstrom]

User Agent: Mozilla/5.0 (Ubuntu; X11; Linux x86_64; rv:8.0) Gecko/20100101 Firefox/8.0
Build ID: 20111115183813

Steps to reproduce:

I closed the mail window tab with either the X button on the tab or with Ctrl-W.

This is 100% reproducible at the moment between reboots of the PC and restarting Thunderbird in safe mode. Let me know if I can capture any other specific info (and instructions on how) that would be useful - otherwise I'll start trying to figure out how to get rid of / mask the behavior so I can do email normally again. :)

This is on Ubuntu 11.10 with the latest Thunderbird (v8) package available for 11.10 - 8.0+build1-0ubuntu0.11.10.1


Actual results:

The mail window tab closes and Thunderbird becomes non-responsive for 10-15 seconds. I can see that thunderbird-bin and dbus-daemon are taking all of both CPUs (so 200% really) during that time. Running strace -p on dbus-daemon I see a plethora of these:

recvmsg(24, {msg_name(0)=NULL, msg_iov(1)=[{"a11y.atspi.Component\0\0\0\0\0\0\0\0\0\0\0\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 2048
recvmsg(24, {msg_name(0)=NULL, msg_iov(1)=[{"e\0\0\0\30\0\0\0org.a11y.atspi.Component"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 2048
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=POLLIN}, {fd=8, events=POLLIN}, {fd=10, events=POLLIN}, {fd=11, events=POLLIN}, {fd=12, events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}, {fd=16, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, events=POLLIN}, {fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}, {fd=14, events=POLLIN}, {fd=22, events=POLLIN}, {fd=23, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, events=POLLIN}, {fd=24, events=POLLIN}, {fd=28, events=POLLIN}, {fd=29, events=POLLIN}], 26, 108294) = 1 ([{fd=24, revents=POLLIN}])
recvmsg(24, {msg_name(0)=NULL, msg_iov(1)=[{"52867\0\0\0\0\0\0\0=\0\0\0\31\0\0\0org.a11y.ats"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 2048

Running strace -p on Thunderbird during this period, I see:
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0

about 45000 times and then an increasing number of sendmsg calls that all look similar to

sendmsg(38, {msg_name(0)=NULL, msg_iov(2)=[{"l\4\1\1\24\1\0\0002\304\23\0x\0\0\0\1\1o\0\25\0\0\0/org/a11"..., 136}, {"\5\0\0\0:1.48\0\0\0!\0\0\0/org/a11y/atspi/"..., 276}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 412

That goes on until line 356014 and then some polls, reads, a ton of

madvise(0x7fa56ccbc000, 4096, MADV_DONTNEED) = 0

and I had killed strace at that point while thunderbird and dbus were still going nuts.

The file descriptor numbers fro the recvmsg() and sendmsg() calls were both symbolic links from /proc/<id>/fd/<fd-num> to sockets.


Expected results:

It should not use 100% CPU with DBUS for an extended period of time and be responsive.

Comment 1

[kcstrom]

This is with an IMAP account that has about 800MB total in the few folders I have. Most email is stored in the Inbox (I've given up on folders since the search works pretty well). I've tried deleting the .msf files as well as the mbox file for the inbox. This only happens with this account. I have another IMAP account setup that does not exhibit this issue. This started happening overnight (it used to be fine) - I think it was around the last update to the version mentioned in the original description.

Comment 2

[kcstrom]

I've realized that occurs as a result of transitioning from a tab to the initial tab when it is on my inbox folder (sync via IMAP). I can close emails that are open as tabs just fine as long as there is another tab (opened email, search, etc.) that then is on top which is not the initial list view tab showing the contents of my inbox.

Comment 3

[kcstrom]

This issue went away for about a day and then returned. I had made no configuration changes during that period of time.

Comment 4

[kcstrom]

I've tested this out with the Ubuntu PPA of the daily build of Thunderbird from https://launchpad.net/~ubuntu-mozilla-daily/+archive/ppa as of today (01/12/2012) and it exhibits the same issue.

Comment 5

[kcstrom]

If I open messages in a new window instead of a tab, I don't have the long hang and spewage of dbus messages (which most don't seem to show up in dbus-monitor anyway) except on startup (when the primary list tab is first focused).

Comment 6

[tct]

(In reply to kcstrom from comment #0)
> Running strace -p on Thunderbird during this period, I see:
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
> 
> about 45000 times and then an increasing number of sendmsg calls that all
> look similar to
> 
> sendmsg(38, {msg_name(0)=NULL,
> msg_iov(2)=[{"l\4\1\1\24\1\0\0002\304\23\0x\0\0\0\1\1o\0\25\0\0\0/org/a11"...
> , 136}, {"\5\0\0\0:1.48\0\0\0!\0\0\0/org/a11y/atspi/"..., 276}],
> msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 412

The same here. Thunderbird 10.0.1 Fedora GNU/Linux x86_64. Any idea why does this bug manifest?

Comment 7

[flavio.l]

Also the new Thunderbird 12.0 (as well as 11.x but NOT 10.x ) on Fedora 16 x86_64 has the same issue.
The GUI is completely unresponsive at launch and while switching accounts (all POP no IMAP).
This lasts for a few minutes, then sporadically for a few seconds during thunderbird usage.
In strace -C I see tons of 
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2652, ...}) = 0

strace summary shows:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 30.05    2.655653           2   1095513           sendmsg
 21.65    1.914007           1   1734477      1078 stat
 14.42    1.274889          50     25692      1656 futex
  9.52    0.841157           5    184555           poll
  7.60    0.671383           1    569220    185028 read
  3.25    0.286913           1    222155           lseek
  2.47    0.218755           2     88824           madvise
  2.18    0.192830           3     71249           writev
  1.92    0.169900           6     28395           write
  1.82    0.160995          13     12299           getdents
  1.71    0.151511           2     64084           fstat
  1.33    0.117582           6     18337       352 access

Comment 8

[Wayne Mery (:wsmwk)]

which desktop/window manager do you use?

Comment 9

[kcstrom]

unity

Comment 10

[flavio.l]

I use standard gnome 3 Fedora 17 desktop...the issue continued with thunderbird 13, 14 and now 15...

Comment 11

[Wayne Mery (:wsmwk)]

please install profiler https://addons.mozilla.org/en-us/thunderbird/addon/gecko-profiler/ 

enable profiler to capture activity (bottom right side), then dump (bottom right side), and upload  (bottom left side), and post URL here.

Comment 12

[kcstrom]

The link to the profiler says "Not available for your platform". The add-on manager in Thunderbird also can't find that plugin.

Comment 13

[flavio.l]

(In reply to Wayne Mery (:wsmwk) from comment #11)
> please install profiler
> https://addons.mozilla.org/en-us/thunderbird/addon/gecko-profiler/ 
> 
> enable profiler to capture activity (bottom right side), then dump (bottom
> right side), and upload  (bottom left side), and post URL here.

I can confirm the add-on is not available for my platform (x86_64 Linux)
I still have the same issues described above on fedora 17 thunderbird 17...

Comment 14

[Wayne Mery (:wsmwk)]

(In reply to kcstrom from comment #12)
> The link to the profiler says "Not available for your platform". The add-on
> manager in Thunderbird also can't find that plugin.

perhaps the issue is bug 812946, mentioned at https://developer.mozilla.org/en-US/docs/Performance/Profiling_with_the_Built-in_Profiler#Availability

Mike, do you agree?

Comment 15

[Wayne Mery (:wsmwk)]

or go to the ultimate source re comment 14

Comment 16

[Nicolas B. Pierron [:nbp]]

You can download the sources of the gecko profiler to "build" the xpi to import it in thunderbird.

Bug 812946 might cause more hangs with some pthread functions.  The current implementation of the profiler should at least be able to report the JavaScript stack or the C++ stack, but not both at the same time which should be enough if you can reproduce this bug.

Comment 17

[Mike Conley (:mconley) (:⚙️)]

(In reply to Wayne Mery (:wsmwk) from comment #14)
> (In reply to kcstrom from comment #12)
> > The link to the profiler says "Not available for your platform". The add-on
> > manager in Thunderbird also can't find that plugin.
> 
> perhaps the issue is bug 812946, mentioned at
> https://developer.mozilla.org/en-US/docs/Performance/
> Profiling_with_the_Built-in_Profiler#Availability
> 
> Mike, do you agree?

I think BenWa has been having difficulty getting the Gecko Profiler add-on approved by the AMO mods.

Installing directly from Github might be an easier path: https://github.com/bgirard/Gecko-Profiler-Addon/raw/master/geckoprofiler.xpi

-Mike

Comment 18

[Wayne Mery (:wsmwk)]

If you can still reproduce, please comment and add a profile.
And also comment whether this reproduce when using something other than gnome.

Comment 19

[GFabio]

Hi all,
I have some problem with new versione thunderbird 31.1.2 on ubuntu 12.04 lts 64Bit
Precedent version not have this problem.

I hope someone have a solution