Closed Bug 363163 Opened 19 years ago Closed 18 years ago

Thunderbird and Firefox chewing up cpu cycles even when idle due to continued firing of progressmeter timer

Categories

(Thunderbird :: General, defect)

Product:
Thunderbird
Component:
General
Type:
defect
Priority:
Not set
Severity:
major

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: brian.utterback, Assigned: mscott)

References

Details

(Keywords: perf, verified1.8.1.2)

Attachments

(2 files, 1 obsolete file)

Better workaround
2.12 KB, patch
enndeakin
: review+
jay
: approval1.8.1.2+
Details | Diff | Splinter Review
Testcase exhibiting problem
996 bytes, application/vnd.mozilla.xul+xml
Details
User-Agent: Mozilla/5.0 (X11; U; SunOS sun4u; en-US; rv:1.8.1.1) Gecko/20061205 Firefox/2.0.0.1 Build Identifier: version 2 beta 1 (20061206) Sometime recently Thunderbird has started chewing up CPU cycles like they were going out of style. The two main threads, thread 1 and thread 3 never stop processing. Here is a typical truss output from thread 1 from Thunderbird 1.5 when it was iconized and otherwise idle: 30470/1: pollsys(0x0034AC90, 9, 0x00000000, 0x00000000) (sleeping...) 30470/1: 250.9763 14.9983 0.0001 pollsys(0x0034AC90, 9, 0x00000000, 0x00000000) = 1 30470/1: 250.9768 0.0005 0.0000 write(18, " 8", 1) = 1 30470/1: 250.9772 0.0004 0.0000 lwp_unpark(3) = 0 30470/1: 250.9775 0.0003 0.0001 read(9, "FA", 1) = 1 30470/1: 250.9778 0.0003 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 30470/1: pollsys(0x0034AC90, 9, 0x00000000, 0x00000000) (sleeping...) 30470/1: 265.6516 14.6738 0.0001 pollsys(0x0034AC90, 9, 0x00000000, 0x00000000) = 1 30470/1: 265.6528 0.0012 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 30470/1: 265.6530 0.0002 0.0000 read(4, "1CE89B X\0 0\0 A\0\001 $".., 32) = 32 30470/1: 265.6533 0.0003 0.0000 ioctl(4, FIONREAD, 0xFFBFE264) = 0 30470/1: 265.6534 0.0001 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 30470/1: 265.9770 0.3236 0.0001 pollsys(0x0034AC90, 9, 0x00000000, 0x00000000) = 1 30470/1: 265.9775 0.0005 0.0000 write(18, " 8", 1) = 1 30470/1: 265.9779 0.0004 0.0000 lwp_unpark(3) = 0 30470/1: 265.9783 0.0004 0.0000 read(9, "FA", 1) = 1 30470/1: 265.9786 0.0003 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 30470/1: pollsys(0x0034AC90, 9, 0x00000000, 0x00000000) (sleeping...) 30470/1: 280.9801 15.0015 0.0001 pollsys(0x0034AC90, 9, 0x00000000, 0x00000000) = 1 30470/1: 280.9805 0.0004 0.0000 write(18, " 8", 1) = 1 30470/1: 280.9808 0.0003 0.0000 lwp_unpark(3) = 0 30470/1: 280.9812 0.0004 0.0000 read(9, "FA", 1) = 1 30470/1: 280.9814 0.0002 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 Notice that it pretty much would sleep for 10-15 seconds and otherwise do noting. And this was the busiest thread. Here is the same thread from Thunderbird 2.0: 58105/1: 0.1376 0.0002 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 58105/1: 0.1388 0.0012 0.0000 pollsys(0x003FE270, 9, 0x00000000, 0x00000000) = 1 58105/1: 0.1404 0.0016 0.0000 write(20, "FA", 1) = 1 58105/1: 0.1407 0.0003 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 58105/1: 0.1408 0.0001 0.0000 pollsys(0x003FE270, 9, 0x00000000, 0x00000000) = 1 58105/1: 0.1410 0.0002 0.0000 read(19, "FA", 1) = 1 58105/1: 0.1411 0.0001 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 58105/1: 0.1413 0.0002 0.0000 pollsys(0x003FE270, 9, 0x00000000, 0x00000000) = 1 58105/1: 0.1414 0.0001 0.0000 read(19, "FA", 1) = 1 58105/1: 0.1417 0.0003 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 58105/1: 0.1438 0.0021 0.0000 pollsys(0x003FE270, 9, 0x00000000, 0x00000000) = 1 58105/1: 0.1474 0.0036 0.0000 write(20, "FA", 1) = 1 58105/1: 0.1496 0.0022 0.0000 lwp_unpark(3) = 0 58105/1: 0.1499 0.0003 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 58105/1: 0.1500 0.0001 0.0000 pollsys(0x003FE270, 9, 0x00000000, 0x00000000) = 1 58105/1: 0.1515 0.0015 0.0000 read(19, "FA", 1) = 1 58105/1: 0.1518 0.0003 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 58105/1: 0.1519 0.0001 0.0000 pollsys(0x003FE270, 9, 0x00000000, 0x00000000) = 1 58105/1: 0.1521 0.0002 0.0000 read(19, "FA", 1) = 1 58105/1: 0.1522 0.0001 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 58105/1: 0.1537 0.0015 0.0000 pollsys(0x003FE270, 9, 0x00000000, 0x00000000) = 1 58105/1: 0.1569 0.0032 0.0000 write(20, "FA", 1) = 1 58105/1: 0.1571 0.0002 0.0000 ioctl(4, FIONREAD, 0xFFBFE384) = 0 As you can see, it never goes to sleep at all. As near as I can tell, file descriptors 19 and 20 are two ends of the same connection, so the thread is continually reading and writing to itself. Reproducible: Always Steps to Reproduce: 1. Start Thunderbird 2. Truss it. 3. Actual Results: High percentage of cpu usage when idle Expected Results: Low cpu usage when idle
do you have a virus checker installed? Are you using IMAP?
This is on Solaris so there is no virus checker. Yes, I am using IMAP.
does going offline in Thunderbird stop the churning? An imap protocol log might help: http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap
I have been also experiencing this, but I have not posted it because I was not sure if what I was seeing was local to my system. But let me post my observations so far as possibly helpful. What I will describe occurs reliably on my custom build, based on 2006-11-30 Mozilla_1_8_BRANCH with debug enabled and minor patches (for bug #362741, though the problem existed before those patches). But I could not reproduce using a download of "version 2 beta 1 (20061208)" (windows 2000) executable. The main diagnostic is what percentage of CPU cycles does TB use when idle. If I do nothing, it stays around 1% (all automatic account checking disabled). I have a POP3 account (dovecot on Fedora 2). I repeatedly check that account with no new mail in it, running it manually from the GetMail toolbar icon downarrow. Each time I check it, the base CPU usage of TB increases a little, perhaps by a few percent (using a Pentium III processor.) Eventually it will reach 100% after about 25 checks of the account. Even when at 100%, TB still seems to operate normally. Also, each time I check mail I get "Begin mail message delivery; Abort mail message delivery." in the DOS console. I'm not sure what tools to apply to investigate this further (using Visual Studio 6.0). If you could suggest an approach I would be happy to give results.
Kent, your debug build was on Windows as well? That's very strange. I'm not seeing that with my debug trunk build - I can try a 2.0 branch debug build. I wonder if file handles are getting used up somehow...though that's not something that bothers windows much, afaik.
All of my reports in this bug reference my Windows 2000 builds. So far, I can see the problem with checkouts with -D "30 Nov 2006" but I do not see the problem with checkouts of -D "2006-11-27 12:00", all using MOZILLA_1_8_BRANCH My current theory is this. On checkouts with -D "2006-11-28 12:00" and later, I see in mozilla/client.mk: # Checkout Tags # # For branches, uncomment the MOZ_CO_TAG line with the proper tag, # and commit this file on that tag. MOZ_CO_TAG = MOZILLA_1_8_BRANCH NSPR_CO_TAG = NSPR_4_6_4_RTM NSS_CO_TAG = NSS_3_11_4_RTM LDAPCSDK_CO_TAG = MOZILLA_1_8_BRANCH LOCALES_CO_TAG = MOZILLA_1_8_BRANCH while in checkouts of -D "2006-11-27 12:00" and earlier I see: # Checkout Tags # # For branches, uncomment the MOZ_CO_TAG line with the proper tag, # and commit this file on that tag. MOZ_CO_TAG = MOZILLA_1_8_BRANCH NSPR_CO_TAG = MOZILLA_1_8_BRANCH NSS_CO_TAG = MOZILLA_1_8_BRANCH LDAPCSDK_CO_TAG = MOZILLA_1_8_BRANCH LOCALES_CO_TAG = MOZILLA_1_8_BRANCH So my theory is that this problem is associated with the change of the branch of NSPR and NSS. I am currently checking out -D "2006-11-28 12:00" which has the tag change, I will confirm that debug compiles there show the problem, then recheckout and recompile with the same date but reverting all tags to MOZILLA_1_8_BRANCH. If that does not show the problem, then I believe that will confirm my theory. I still don't know if this is a local problem or not since it is unconfirmed. But I have seen several hints of similar problems by others in the last few days (including this bug), so I thought I would clarify my problem since I seem to have a clear test case.
Interesting - I don't know if those tags are actually different...
Brian, do you know what the "FA" string in your truss output means? write(20, "FA", 1) read(19, "FA", 1) Since only one byte (character) is written and read, I don't know why truss shows two characters "FA". I suspect that fd 19 and fd 20 are an NSPR pollable event, which is implemented as a pipe on Solaris, so fd 19 and fd 20 could be the two ends of a pipe. But the character that NSPR writes to and reads from a pollable event is '\x38', which is the digit '8', not 'F' or 'A'. Regarding the good and bad NSPR and NSS CVS tags that Kent reported in comment 6, I can confirm that they are identical: - For NSPR (mozilla/nsprpub), -r MOZILLA_1_8_BRANCH -D "2006-11-27 12:00" has the same contents as -r NSPR_4_6_4_RTM - For NSS (mozilla/security/coreconf and mozilla/security/nss), -r MOZILLA_1_8_BRANCH -D "2006-11-27 12:00" has the same contents as -r NSS_3_11_4_RTM. I verified as follows: % cvs -q co -r MOZILLA_1_8_BRANCH -D "2006-11-27 12:00" mozilla/nsprpub mozilla/security/coreconf mozilla/security/nss % cvs -q diff -kk -r NSPR_4_6_4_RTM mozilla/nsprpub % cvs -q diff -kk -r NSS_3_11_4_RTM mozilla/security/coreconf mozilla/security/nss The two "cvs diff" commands produced no output.
The "FA" is the hex representation of the single byte being written and read. As you noted, it looks like Fd 19 and 20 are the end points of a pipe. You will notice that in the truss output I provided, there is the ASCII "8" that you said is used by NSPR, so it would appear that this is not the same thing.
Brian, I still don't understand what the "FA" and " 8" strings mean. In write(18, " 8", 1), the string " 8" contains the space ' ' and the digit '8'. What does the space ' ' mean?
Here is the stacks when the "FA" is read and written: libc.so.1`_write+0x8 libxpcom_core.so`0xff1b7b48 libxpcom_core.so`PL_ProcessPendingEvents+0xd4 libxpcom_core.so`__1cQnsEventQdDueueImplUProcessPendingEvents6M_I_+0x20 libwidget_gtk2.so`0xfaa2438c libglib-2.0.so.0.1000.2`g_main_dispatch+0x1e0 libglib-2.0.so.0.1000.2`g_main_context_dispatch+0xc8 libglib-2.0.so.0.1000.2`g_main_context_iterate+0x49c libglib-2.0.so.0.1000.2`g_main_loop_run+0x3e4 libgtk-x11-2.0.so.0.800.20`gtk_main+0xd8 libwidget_gtk2.so`0xfaa24754 libtoolkitcomps.so`0xfa97570c thunderbird-bin`XRE_main+0x1a08 thunderbird-bin`_start+0x108 190 times libc.so.1`_write+0x8 libxpcom_core.so`0xff1b7b48 libxpcom_core.so`PL_PostEvent+0x88 libxpcom_core.so`__1cQnsEventQdDueueImplJPostEvent6MpnHPLEvent__I_+0x94 libxpcom_core.so`__1cLnsTimerImplOPostTimerEvent6M_v_+0x114 libxpcom_core.so`__1cLTimerThreadDRun6M_I_+0x114 libxpcom_core.so`__1cInsThreadEMain6Fpv_v_+0x28 libnspr4.so`0xff255d64 libc.so.1`_lwp_start 235 times libc.so.1`_read+0x8 libxpcom_core.so`0xff1b7bb8 libxpcom_core.so`PL_ProcessPendingEvents+0xc0 libxpcom_core.so`__1cQnsEventQdDueueImplUProcessPendingEvents6M_I_+0x20 libwidget_gtk2.so`0xfaa2438c libglib-2.0.so.0.1000.2`g_main_dispatch+0x1e0 libglib-2.0.so.0.1000.2`g_main_context_dispatch+0xc8 libglib-2.0.so.0.1000.2`g_main_context_iterate+0x49c libglib-2.0.so.0.1000.2`g_main_loop_run+0x3e4 libgtk-x11-2.0.so.0.800.20`gtk_main+0xd8 libwidget_gtk2.so`0xfaa24754 libtoolkitcomps.so`0xfa97570c thunderbird-bin`XRE_main+0x1a08 thunderbird-bin`_start+0x108 426 times
The truss command in Solaris dumps data in a odd manner. Each byte is displayed as exactly two bytes in the data dump. Printable characters are printed as they are with a preceding space character. Special characters that have a c-language escape sequence are printed in the backslash format, e.g. newline is printed as \n. Special characters without a c escape are printed in hexadecimal, so the FA is really 0xFA, which is 0372 or decimal 250. The single ASCII character for "8" is printed " 8".
Here is my current status in isolating the bug I am reporting (perhaps related to the Solaris report, or perhaps only my local problem) where my debug builds under Windows 2000 reliably increase in idle CPU usage. I have been checking out and compiling source with different -D tags, trying to isolate the start of the problem. Currently, I do not see the bug with checkouts of -D and MOZ_CO_DATE set to "2006-11-29 12:00" and earlier, but do see it with "01 Dec 2006 12:00 PDT" or later (all on MOZILLA_1_8_BRANCH compiled using Visual Studio 6). That transition is later than the changes to the NSPR tags, so that is likely NOT the problem unlike my earlier theory. Sorry for the change in date formats, I'm still trying to get my checkout procedure working reliably. I also see the bug on a 2006-11-30 checkout, but that was done actually on that date so I do not have a more precise time fix. Unfortunately I am moving tonight halfway around the world (from Azerbaijan to Redmond, WA - no connection to Microsoft BTW) so it may be awhile before I can get back to this, or even respond to questions since I will be relying on Starbucks for internet for awhile.
I'm confirming this bug, because I get it on Linux, too, with my latest nightly 1.8 branch build. (In reply to comment #3) > does going offline in Thunderbird stop the churning? No!
Status: UNCONFIRMED → NEW
Ever confirmed: true
Version: unspecified → 1.5
The busy loop is probably on the main thread (thread 1 ?) I have only limited symbol info in this build, after attaching to the process with gdb, I see this stack: #0 0x0058b251 in JS_GetStringChars () from /home/kaie/moz/multi/thunderbird/libmozjs.so #1 0x080a1cb0 in putchar () #2 0x080b5d63 in putchar () #3 0x080bc51b in putchar () #4 0x005b69b6 in js_Invoke () from /home/kaie/moz/multi/thunderbird/libmozjs.so #5 0x005b6fe3 in js_InternalInvoke () from /home/kaie/moz/multi/thunderbird/libmozjs.so #6 0x005b7181 in js_InternalGetOrSet () from /home/kaie/moz/multi/thunderbird/libmozjs.so #7 0x005d461d in js_SetProperty () from /home/kaie/moz/multi/thunderbird/libmozjs.so #8 0x005be637 in js_Interpret () from /home/kaie/moz/multi/thunderbird/libmozjs.so #9 0x005b6a9d in js_Invoke () from /home/kaie/moz/multi/thunderbird/libmozjs.so #10 0x005b6fe3 in js_InternalInvoke () from /home/kaie/moz/multi/thunderbird/libmozjs.so #11 0x0058ad2e in JS_CallFunctionValue () from /home/kaie/moz/multi/thunderbird/libmozjs.so #12 0x084f19e7 in nsReadingIterator<unsigned short>::advance () #13 0x08502b28 in nsReadingIterator<unsigned short>::advance () #14 0x08503012 in nsReadingIterator<unsigned short>::advance () #15 0x008941e6 in nsTimerImpl::Fire () from /home/kaie/moz/multi/thunderbird/libxpcom_core.so #16 0x00894254 in handleTimerEvent () from /home/kaie/moz/multi/thunderbird/libxpcom_core.so #17 0x0088fc57 in PL_HandleEvent () from /home/kaie/moz/multi/thunderbird/libxpcom_core.so #18 0x0088fb84 in PL_ProcessPendingEvents () from /home/kaie/moz/multi/thunderbird/libxpcom_core.so #19 0x008917e9 in nsEventQueueImpl::CheckForDeactivation () from /home/kaie/moz/multi/thunderbird/libxpcom_core.so #20 0x082883f5 in XmlInitUnknownEncodingNS () #21 0x001c194d in g_io_channel_unix_get_fd () from /lib/libglib-2.0.so.0 #22 0x00198342 in g_main_context_dispatch () from /lib/libglib-2.0.so.0 #23 0x0019b31f in g_main_context_check () from /lib/libglib-2.0.so.0 #24 0x0019b6c9 in g_main_loop_run () from /lib/libglib-2.0.so.0 #25 0x05d34be4 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0 #26 0x08288738 in XmlInitUnknownEncodingNS () #27 0x087a37c7 in nsXPTCVariant::Init () #28 0x08080f64 in nsXPTCStubBase::Stub246 () #29 0x0afb4b80 in ?? () #30 0x08b2b228 in _IO_stdin_used () #31 0x00000000 in ?? () All the other threads (but one) are waiting on a condition variable. I have one more thread, which is our smartcard thread. It uses sleep calls. This should be sufficient to avoid the 100% cpu usage that I see.
I started a debug build. I waited until the cpu consumption started. I used "top" with option "show threads" and can see, it's the first thread that contains nearly all the cpu. I attached with gdb. I repeatedly interrupted the execution and looked at the stack of the first thread. The common denominator of all my stacks is this: #11 0x0891e7c5 in nsGlobalWindow::RunTimeout (this=0x9aa8250, aTimeout=0xa20ed18) at /extra/moz/18/mozilla/dom/src/base/nsGlobalWindow.cpp:6736 #12 0x0891f31f in nsGlobalWindow::TimerCallback (aTimer=0xa20f770, aClosure=0xa20ed18) at /extra/moz/18/mozilla/dom/src/base/nsGlobalWindow.cpp:7109 #13 0x00210936 in nsTimerImpl::Fire (this=0xa20f770) at /extra/moz/18/mozilla/xpcom/threads/nsTimerImpl.cpp:394 #14 0x00210b2b in handleTimerEvent (event=0xad100920) at /extra/moz/18/mozilla/xpcom/threads/nsTimerImpl.cpp:459 #15 0x0020888b in PL_HandleEvent (self=0xad100920) at /extra/moz/18/mozilla/xpcom/threads/plevent.c:688 #16 0x00208740 in PL_ProcessPendingEvents (self=0x97f6f20) at /extra/moz/18/mozilla/xpcom/threads/plevent.c:623 #17 0x0020bb99 in nsEventQueueImpl::ProcessPendingEvents (this=0x97ffe80) at /extra/moz/18/mozilla/xpcom/threads/nsEventQueue.cpp:417 #18 0x073c0e5c in event_processor_callback (source=0x9ad6310, condition=G_IO_IN, data=0x97ffe80) at /extra/moz/18/mozilla/widget/src/gtk2/nsAppShell.cpp:67 #19 0x00c4394d in g_io_channel_unix_get_fd () from /lib/libglib-2.0.so.0 #20 0x00c1a342 in g_main_context_dispatch () from /lib/libglib-2.0.so.0 #21 0x00c1d31f in g_main_context_check () from /lib/libglib-2.0.so.0 #22 0x00c1d6c9 in g_main_loop_run () from /lib/libglib-2.0.so.0 #23 0x05d34be4 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0 #24 0x073c14d4 in nsAppShell::Run (this=0x9880010) at /extra/moz/18/mozilla/widget/src/gtk2/nsAppShell.cpp:139 #25 0x02b9df40 in nsAppStartup::Run (this=0x987ffc8) at /extra/moz/18/mozilla/toolkit/components/startup/src/nsAppStartup.cpp:151 #26 0x08058954 in XRE_main (argc=3, argv=0xbfc0d854, aAppData=0x8073aa0) at /extra/moz/18/mozilla/toolkit/xre/nsAppRunner.cpp:2444 #27 0x080503cc in main (argc=3, argv=0xbfc0d854) at /extra/moz/18/mozilla/mail/app/nsMailApp.cpp:62
I'm seeing this too, on Thunderbird 1.5.0.8 under Linux kernel 2.6.17. This started happening about 2 months ago, and at first I thought it was related to my having just upgraded from a Pentium-III to a Core2Duo, but having seen this thread, I remember that around the same time, I switched all my email accounts from POP3 to IMAP. Anyway, this happens at least once per day and often 2 or more times per day, but I have no idea what initially triggers it. Going offline does not make it stop; the only way I've found to stop it is to exit Thunderbird and restart it. And, if I leave it running long enough, it will eventually use up 100% of *both* my CPU cores, so it seems to be something that can/will affect multiple threads. I don't have much experience with strace; I just ran it attached to my tbird pid, but I don't know what to look for in the output. Let me know if I can do anything to help track down the problem here. (Also, I realize that this was initially filed for Sun/Solaris, but given the number of bugs that mention tbird spiking the CPU, it seems to not be platform-specific. If I'm wrong about that, feel free to point me to some other bug on this issue.)
After an exhaustive binary search through CVS downloads, compiling different dates and times, we have a winner: bug #352260 When the patch for that bug is applied, I consistently get the increase in CPU use described in comment #4. These are tested with standard MOZILLA_1_8_BRANCH CVS downloads at different dates and times, built with the debug option under Windows 2000. For other reporters of similar behavior, it would be useful if you could test whether the behavior begins with builds after 2006-11-30. Then we would know if we are chasing the same bug or not. Other than comments, Bug #352260 only changes a single line of code. Any thoughts on why this change might cause an increase in CPU cycles?
I'm afflicted by this issue, and my build is version 1.5.0.8 (20061115) on Linux.
per Kent's analysis...
Blocks: 352260
Flags: blocking-thunderbird2+
Here is an update of what I have learned. I modified a section of nsXULElement.cpp (where bug #352260 made its change) like this: --- nsXULElement::GetBoxObject(nsIBoxObject** aResult) { *aResult = nsnull; // XXX sXBL/XBL2 issue! Owner or current document? // Be sure to get the same document as the NS_ENSURE_TRUE uses in // nsDocument.cpp::GetBoxObjectFor(). nsCOMPtr<nsIDOMNSDocument> nsDoc(do_QueryInterface(GetOwnerDoc())); nsCOMPtr<nsIDOMNSDocument> nsDocx(do_QueryInterface(GetCurrentDoc())); if (nsDoc != nsDocx) { // test break for RKJ int testit=1; } --- That is, when do the new and old code give different results? If they differ, then execute testit=1 (and I can break on that). When I do, I find that the issue centers around the progress meter. I can add dump() statements to dist\bin\chrome\toolkit\content\global\bindings\progressmeter.xml like so: --- <method name="init"> <body><![CDATA[ var stack = document.getAnonymousElementByAttribute(this, "anonid", "stack"); var spacer = document.getAnonymousElementByAttribute(this, "anonid", "spacer"); var position = -1; var interval = setInterval(function nextStep() { try { var width = stack.boxObject.width >> 2; spacer.height = stack.boxObject.height; spacer.width = width; spacer.left = width * position; position += 15 / (width + 150); if (position >= 4) position = -1; dump("Processing interval\n"); } catch (e) { clearInterval(interval); dump("Clearing interval\n"); } }, 1000); ]]></body> </method> --- (I also changed the interval above from 20 to 1000 in the third from the last statement to slow everything down ). When I do these changes, then I see this with the versions that have the problem: The first time I check email, I see "Processing interval" once per second. Second time, two "Processing interval" per second, etc. That is, each time I check email, a progressmeter is started but never terminated. So I accumulate progress meters that fire every second (or every 20 milliseconds with the default interval value). Never do I see the "Clearing interval" in the dump that would indicate the shutdown of the progressmeter. If I try the same change on code that does not have the problem, then I see the "Clearing interval" dump immediately. BTW this is also an easy test that others can do to see if you are chasing the same bug that I am. So my current theory is that the try/catch loop relied on the previous behaviour of the code to generate the exception that terminates the loop. Now this progress meter never terminates. At this point, I have clearly reached the end of my competence to move this forward. Scott, perhaps you can make sure that whoever is competent to fix this looks this over.
Great detective work, Kent!
I added the 'dump("Processing interval\n")' statement (as described in comment #21) to progressmeter.xml on a nightly TB 2.0 download (20061207). I can confirm that the problem of never-ending progress meters exists on that build as well. So the underlying problem is not dependent on the debug build, or my personal compile environment. There must be something in the debug builds that chews up extra CPUs per timer cycle that makes the problem more visible though, as I still cannot notice the extra CPU usage on the standard build.
OS/Platform should be All/All, right?
Sorry for my lack of response on this, just got back from Xmas vacation. Kent, great work tracking this down! Scott, I'll get a t-bird build up today and see if I can't figure out why the progressmeter is so strange. Please let me know if you have made some progress on this already.
My preliminary investigation makes me think the progress bar implementation is relying on the broken behavior (fixed by bug 352260) of nsXULElement::GetBoxObject(), which would return an error code which gets turned into an exception and gets caught in the interval which clears the interval. What I see happening is that the interval never gets cleared and so continues to fire. I also see multiple progressmeters getting created which would account for the growing in the CPU hit. Basically it looks like we are leaking a progressmeter (I put a destructor function in that doesn't ever get called) and creating a new one every time we fire an async request that doesn't quickly complete. The reason we now see the CPU spike is because we are no longer clearing the interval and ALL of the progressmeters that get created are still running every 20 milliseconds. Whee. Looking into where the progressmeter gets created...
Hmmm, so I notice that the css for progressmeter changes the -moz-binding when the mode changes: from xul.css: 654 progressmeter { 655 -moz-binding: url("chrome://global/content/bindings/progressmeter.xml#progressmeter"); 656 } from gnomestripe/global/global.css: progressmeter[mode="undetermined"] { -moz-binding: url("chrome://global/content/bindings/progressmeter.xml#progressmeter-undetermined"); } I would presume then that when the code in mailWindow.js changes the mode from normal to undetermined and back ( startMeteors and _stopMeteors: around http://lxr.mozilla.org/mozilla1.8/source/mail/base/content/mailWindow.js#354 ) then the new binding gets applied and is generating a new object each time. I have no idea where these objects would get rooted or who owns them since that happens in the application of the css rule (and stuff). It seems to me that progressmeter could be written a little differently to not need the change in binding on mode change. Any thoughts? Suggestions?
(In reply to comment #24) > OS/Platform should be All/All, right? OS=ALL AFAICT, based on Kent comments. mscott sees this on windows?
Keywords: perf
OS: Solaris → All
Hardware: Sun → All
I've seen what is probably this bug - opening new message and/or compose windows seems to cause this (but perhaps it's the progress meter started by doing an auto-save of a draft). If we're no longer getting an exception, are we getting something else we can detect, like an empty box? Or is the owner document valid, along with the box, but just not the current doc?
this looks like a leak of xul elements - the destructor for the xbl element never seems to get called...any suggestions for tracking this down?
(In reply to comment #26) >My preliminary investigation makes me think the progress bar implementation is >relying on the broken behavior (fixed by bug 352260) of >nsXULElement::GetBoxObject(), which would return an error code which gets >turned into an exception and gets caught in the interval which clears the >interval. Hmm... 50% of the time I get an exception and 50% of the time I get 0...
Attached patch Workaround (obsolete) — — Splinter Review
This is all I can think of... unless you have a better idea?
Attachment #250382 - Flags: review?(enndeakin)
Comment on attachment 250382 [details] [diff] [review] Workaround What happens if the progressmeter is collapsed and then shown again? Won't the timer stop as the width is 0 and never start up again?
Attachment #250382 - Attachment is obsolete: true
Attachment #250401 - Flags: review?(enndeakin)
Attachment #250382 - Flags: review?(enndeakin)
thx very much for the patch, Neil! I'll try this at home later...
So far, this is working fine - idle cpu usage is staying at 0. We would love to have this fix for beta 2, which is scheduled for mid January.
Comment on attachment 250401 [details] [diff] [review] Better workaround If this is a branch only issue, then OK.
Attachment #250401 - Flags: review?(enndeakin) → review+
Comment on attachment 250401 [details] [diff] [review] Better workaround As nobody's complaining about this on trunk requesting this for branch only.
Attachment #250401 - Flags: approval1.8.1.1?
Comment on attachment 250401 [details] [diff] [review] Better workaround I think Neil wanted to nominate for 1.8.1.2 as .1 is gone already.
Attachment #250401 - Flags: approval1.8.1.2?
I've been running a Thunderbird 1.8 branch build having this fix since yesterday, and it looks good to me, too.
Comment on attachment 250401 [details] [diff] [review] Better workaround Approved for 1.8 branch, a=jay for drivers.
Attachment #250401 - Flags: approval1.8.1.2?
Attachment #250401 - Flags: approval1.8.1.2+
Attachment #250401 - Flags: approval1.8.1.1?
Keywords: fixed1.8.1.2
I think we should take this on trunk too. That said, shouldn't .width on the boxObject throw if there's no frame (on trunk)? If that happened, things would still work right, no? Or would this cause issues elsewhere? As for the binding change described in comment 27, XBL1 doesn't support removing a binding and changing bindings doesn't really work that well -- see bug =119078 and bug 304933 and note that there are no provisions for calling the destructor of the old binding if it's replaced by a new one.... Perhaps there should be.
will this get picked up in TB 1.5.0.10 ?
Is the bug present in 1.5.0.9? I didn't think it was.
(In reply to comment #44) > Is the bug present in 1.5.0.9? I didn't think it was. (I don't understand enough about this one so I'm sure someone can give a better answer) it's reported to be present in 1.5.0.8, no comment was made about 1.5.0.9 and the patch only just came out a couple days ago, right?
bug 352260 didn't land on the 1.5.0.x branch so in theory, this isn't needed for the branch. I'm not 100% sure that bug 352260 didn't just exacerbate an already existing condition. But I'm also not sure that the 1.5.0.8 report didn't have a different cuase.
I think the fix in bug 352260 caused the loops to continue running on the leaked progressmeters -- yay closures! -- (assuming they actually leak when the binding changes since I never see a destructor called). So I agree with comment #46 (not just because I checked in that other patch). I think the thing with trunk is that the fix in bug 352260 was already on the trunk in a different format when previous document-getting fixes went in. So I doubt we'll see the same problem but we should check (I'll pull a trunk tbird today but I don't recall actually ever seeing the performance hit -- even on branch -- so I may not be the best to report). The other XBL related issue is definitely bug 304933 (and probably bug 119078 too)
> That said, shouldn't .width on the boxObject throw if there's no frame (on > trunk)? Why should it throw? I'd expect it to return 0.
0 would mean there is actually a width and the width is 0, whereas in this case there's actually no width. I'm fine with either way, though, as long as we document it in the relevant interfaces.
We have things like scrollTop returning 0 for non-scrollable elements. I think this is well entrenched as DOM practice.
Trunk shouldn't have a problem because of bug 352260 comment #5: >the rule is simple. If the node is not in a document, it has no box object. Although, I added an assertion to nsXULElement::GetBoxObject and it seems that an element can have a box object without having a parent or a binding parent?
The dupe I just marked was a bug I opened. The symptom I saw was happening consistently: if I left my computer in standby overnight and then woke it up, with TB 2b1 running, I saw a big CPU draw. I tested the 2b1-0108 build last night, and the problem no longer occurred, so I'm pretty sure the patch here fixed my problem. Thanks, Neil and Kent! I've never seen the problem on 3a1.
I second what Mike said. My CPU is no longer at 90% when Thunderbird is running for too long.
Keywords: fixed1.8.1.2 → verified1.8.1.2
Is this related to the jpeg_fdct_islow thread (causing permanent CPU load) in any way?
No longer blocks: 362651
I just marked bug 367825 as a dupe of this bug. However, the problem I'm having is in Firefox 2.0.0.1, not in Thunderbird. I'm the developer of the FireFTP extension and my users and I started noticing major CPU slowdowns after Firefox 2.0.0.1 was released. I ran tests and found that the bug manifests itself only in Firefox 2.0.0.1 and not in 2.0. I stripped down my extension and tested to see for where the problem was coming from and found that it was the progressmeter that was doing the CPU damage. Basically, changing the "mode" attribute of the progressmeter element will gradually eat away at the CPU even if the program has stopped changing the mode. This is tied to the fact that the function is run by a window.setInterval. From my tests, I've seen that it is the combination of these two (using window.setInterval and changing 'mode' on progressmeter) that will create the problem.
I hope this fix can make into Firefox 2.0.0.2 whenever that is released. (seems like you guys were debating whether to fix this on the trunk or not)
Yes, the fix landed in Gecko 1.8.1.2 which means it fixes both Firefox 2.0.0.2 and (as noted in comment 53) Thunderbird 2.0 beta.
It's still reproducible with Mozilla/5.0 (X11; U; SunOS i86pc; en-US; rv:1.8.1.2) Gecko/20070226 Firefox/2.0.0.2 on Solaris Nevada(11) by the test case in comment 59. BTW, a bunch of people in Sun have met the problem with TB 2.0b1. After upgrading to TB 2.0b2, the bug just went away. Thanks for the patch.
I haven't
Please, do not forget about "jpeg_fdct_islow" bug in Firefox, if you correct it in Thunderbird...
fixed on trunk? Dmitry, if you still see your problem then it is not this bug.
Summary: Thunderbird is chewing up cpu cycles even when idle. → Thunderbird and Firefox chewing up cpu cycles even when idle due to continued firing of progressmeter timer
I think this bug should have been marked fixed, so I'm marking it fixed.
Status: NEW → RESOLVED
Closed: 18 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: