488681 - Thunderbird 3 Beta 2 with Gloda enabled uses 2.5 GB of memory

Status: RESOLVED WORKSFORME

(Thunderbird :: General, defect)

Description

[TGOS]

Attachment: vmmap output showing all memory allocations of process

I have the latest Beta (Beta 2) of Thunderbird 3 in use on my Mac. I have a single IMAP E-mail account with about 500 MB of messages. When I start Thunderbird it uses about 25 MB of privat memory - this value grows constantly (within seconds) and finally stops at 2.5 GB private memory (2.85 GB virtual address space are used, 25.19 MB of that are shared memory). I ran vmmap on it. IOKit alone uses > 250 MB of private memory

IOKit                  029c5000-129c5000 [256.0M] rw-/rw- SM=NUL  

Another 31 MB for font caching (even though 99% of my mails are plain-text only using a single font):

ATS (font support)     12b00000-14a80000 [ 31.5M] rw-/rwx SM=COW 

A couple of large mallocs:

MALLOC_LARGE           15f22000-16d96000 [ 14.5M] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000
MALLOC_LARGE           16e4c000-17d54000 [ 15.0M] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000
ALLOC_LARGE           1bbcb000-1c763000 [ 11.6M] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000
MALLOC_LARGE           1c769000-1d29f000 [ 11.2M] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000
MALLOC_LARGE           1d2b5000-1d800000 [ 5420K] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000
MALLOC_SMALL           1d800000-1e000000 [ 8192K] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000
MALLOC_LARGE           1e000000-1e675000 [ 6612K] rw-/rwx SM=COW  DefaultMallocZone_0x1200000
MALLOC_LARGE           1e675000-1ef26000 [ 8900K] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000
MALLOC_REALLOC         1ef26000-51ca0000 [813.5M] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000
MALLOC_LARGE           51ca0000-819a7000 [765.0M] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000

Holy cow, mallocs of the size 813 and 765 MB??? And what is that, I never saw a MALLOC_HUGE at any process so far:

MALLOC_HUGE            c0000000-f3ca0000 [828.6M] rw-/rwx SM=PRV  DefaultMallocZone_0x1200000

828 MB malloc'ed memory?

No wonder memory load goes crazy. I upload the full vmmap output as txt file.

Comment 1

[Ludovic Hirlimann [:Usul]]

Hum is this with an old profile ? what version of Tb were you running prior to testing with TB3b2 ?

Comment 2

[TGOS]

Sorry for not mentioning that:

No, not with an old profile. All caches and the whole profile folder were deleted before I started Thunderbird 3 Beta 2 for the first time. I also never had Beta 1 on my system. The last version was the latest Thunderbird 2 release. However, as I said, the profile were deleted (no caches, no settings, totally clean) and all messages were redownloaded from the server (IMAP).

Comment 3

[Ludovic Hirlimann [:Usul]]

TGOS if you delete your cache again can you reproduce and if you can can you try to give us some logs on what's going on ? The instructions for gettings logs out of Thunderbird are available at : https://wiki.mozilla.org/MailNews:Logging (I'm thinking imap here as that's obviously what you are doing first), you can also use all for the log but that will make a huge log.

Comment 4

[TGOS]

Okay, I deleted the folders in ImapMail for this account. Those got re-created - before they were 200 MB, now they are just 2.5 MB (probably cause most messages are not cached yet). Interesting observation:

Before I deleted it, there were two items in the folder, one named after my server (a directory) and one named after my server with the extension .msf, a file. After re-creation there are now 3 items. The two of before and another one named after my server with the extension .sbd (also a directory). This last directory only contains my INBOX... strage.

I also deleted the file global-messages-db.sqlite. Before it was 14.7 MB, now it is just 540 kb. Current memory consumption is about 27 MB. I will now mark all folders for offline usage and go offline, so my whole account is cached again.

Okay, after the sync I'm back at 2.5 GB memory usage. sqlite file is only 3 MB, the imap folders on disk are now 159 MB.

Do you still want my IMAP log? As I doubt it has to do with IMAP data exchange. It only depends on the amount of data cached locally on my disk. I can actually start Thunderdbird without my network cable plugged in and it will go up to 2.5 GB. IMHO this is either a memory hole, or if the data is intentionally in memory, there is way too much memory caching used. BTW I never did anything with the settings. Except for my account settings; all settings regarding disk and/or memory cache are default. BTW I just restarted Thunderbird, the sqlite file is now at 7 MB, memory usage grows within a couple of seconds to 2.5 GB again.

Comment 5

[Ludovic Hirlimann [:Usul]]

is by any chance gloda turned on your machine (https://wiki.mozilla.org/Thunderbird:Using_Gloda) ?

I don't need the imap logs for now.

Comment 6

[TGOS]

Wow, you are right, that is enabled -  I think checked it in the normal prefs a while ago. I just disabled it and it now stays constantly at 20 MB memory usage. Do you want me to re-enable it again and also set mailnews.database.global.logging.dump to create a logging dump of it? Would that be of any help or is this a known issue already?

Comment 7

[Ludovic Hirlimann [:Usul]]

(In reply to comment #6)

> mailnews.database.global.logging.dump to create a logging dump of it? Would
> that be of any help or is this a known issue already?

No - gloda is being rewritten and should come in the nightly builds by next week. We will certainly blog about it or announce it on the thunderbird-testers mailing list (https://mail.mozilla.org/listinfo/thunderbird-testers). Then It would make sense to do that if you still see the issue. In the meantime I'm going to close this issue as WONTFIX. I'll try to ping you personnaly when gloda lands so you can test the new gloda.

Comment 8

[Joe Sabash [:JoeS1]]

I don't agree with the disposition of this bug.
Gloda landed a long time ago on trunk, an whether the posters experience was inadvertent or not, it seems to be a valid observation of using Gloda.

IMO ignoring issues with new features as observed by testers is ill-advised.

If we are going to make features like Gloda work, we can't afford to ignore users experiences.

Comment 9

[Andrew Sutherland [:asuth] (he/him)]

The gloda-related things happening right now are about new UI; the core indexing logic is not undergoing any changes that would involve memory leaks.

It sounds like the initial indexing sweep is somehow managing to leak or induce memory leaks.  Based on the amount of memory leaked, I expect the leak is O(n) for message headers (rather than folders) and involves javascript.

I would be interested to know what other javascript code is active:
- Is the spotlight indexing support enabled?
- What extensions are installed and active?

Also, TGOS, how is Thunderbird's processor utilization when this problem happens?  Do you have enough RAM to actually cover the 2.5G growth, or are things getting paged to disk?  Gloda should be triggering garbage collection sweeps periodically, so if the problem is a multitude of JS objects, I would expect performance to be quite bad as long-duration GC passes are continually triggered.

If you enable gloda debugging as described on
https://wiki.mozilla.org/Thunderbird:Using_Gloda
and run from a console so you can see the output, do you see any interesting error spew?

One other potential explanation for the problem is that we are somehow repeatedly opening the same folder multiple times, but I find that harder to imagine.

Comment 10

[TGOS]

@Andrew: If you want to debug this issue, I'm willing to help in every aspect I can :-)

Regarding spotlight indexing (you are refering to OS X spotlight here, correct?): "Mail Messages" are not checked for indexing on my system (I don't like these to appear in my spotlight search results). 

Regarding extensions: there are no extensions installed at all, it's a plain Thunderbird 3 installation (as I said, I made everything clean before starting to test Thunderbird 3, I didn't want any old stuff still hanging around).

Regarding processor utilization: When re-enabling the feature, there is constantly some CPU time used, up to 100%. Since my system has 4 cores (so maximum CPU time is 400%) I won't notice that much (3 cores are still idle). Once the memory usage is up to 2.5 GB there is no further CPU usage any longer (except for less than 1% ever couple of seconds).

Regarding the RAM usage: The RAM growth is no issue, my system has 6 GB of physical RAM, thus no swapping takes place. I'm rather worried that the virtual address space runs out of addresses as almost 3 GB of virtual address space are in use in the end.

Regarding GC and performance: I see no GC taking place. I don't see the private memory to ever drop of the 2.5 GB and I also don't see bigger CPU utilizations that would hint towards "work" being actually performed (see CPU utilization above).

So I enabled all debugging as described in the article and started Thunderbird from Terminal (I also enabled mail.spotlight.logging.dump, which is not mentioned on the page). There was no setting browser.dom.window.dump.enabled, so I created one with the value set to true.

There is a lot of DEBUG and INFO output, don't know if that is interesting. Some interesting output includes a warning:

2009-04-17 13:23:53	gloda.indexer	WARN	Problem during job, trying to recover.  Problem was at undefined:undefined: [object StopIteration]

and an error right before it:

2009-04-17 13:23:53	gloda.fundattr	ERROR	Message with subject 'domaindiscount24.com  Newsflash' somehow lacks a valid author.  Bailing.

In the end is an interesting output, right after it stopped at 2.5 GB:

thunderbird-bin(544,0xa0105720) malloc: *** mmap(size=256585728) failed (error code=12)
*** error: can't allocate region
*** set a breakpoint in malloc_error_break to debug

So it looks like it was actually trying to alloc even more memory than 2.5 GB, however the last alloc was already so big that it probably did not fit into the process space any longer, at least not in one piece (~244 MB). You don't happen to have a 64 bit OS X version somewhere ready for testing, do you? As I would like to see if this was going to alloc even more memory than 2.5 GB

BTW there is not a lot output anyway. I would have expected a lot more output. E.g. "indexing message" is seen only twice in the whole output. So it only tries to index two messages before it runs into the malloc error. The last query before the malloc failure is:

QUERY FROM QUERY: SELECT * FROM identities WHERE id IN (SELECT id FROM identities WHERE (contactID IN (362))) ARGS: 

The last two INFO lines are

2009-04-17 13:24:12	gloda.NS	INFO	  * provider: gloda.explattr
2009-04-17 13:24:12	gloda.NS	INFO	  * optimizer: gloda.fundattr

I'll attach the full logging output, but I want to censor my e-mail address (the one shown is one I keep secret so it doesn't end up as SPAM contaminated as the addresses I don't hide in public) - so don't be too surprised to see "[...censored...]" in the log. There was just one of my e-mail addresses that I replaced.

Comment 11

[TGOS]

Attachment: Output after enabling Gloda debugging

Comment 12

[Andrew Sutherland [:asuth] (he/him)]

Thank you for the logs and willingness to help debug!

It looks like this message:
*** Indexing message: 6085 : Super-Schn?ppchen bei LCD-TV-Ger?ten   (611148)
is causing gloda to explode in the optimize pass.

I'd appreciate it if you could send me a copy of the message (my bugmail address is fine) or post a copy on the bug, whichever you are most comfortable with.  I suspect the message content; the headers are unlikely to be a problem.  So if you want to nuke some of the transit headers and censor the actual e-mail addresses, that should not affect its usefulness.  (Please leave the e-mail address-bearing headers there but just censor the e-mail addresses within the line.)

Comment 13

[TGOS]

Attachment: The mail that seems to cause Gloda some headache

I exported the mail as .eml file, I hope this is okay (it seems to contain all mail headers and the whole mail MIME body). As suggested, I kept the header completely unaltered other than replacing my e-mail address with [e-mail] (that means all headers of my mail provider and anything else are still there, there's nothing "secret" about this information).

BTW if anyone cares, that is a HTML newsletter (with embedded CSS) sent by a shopping site (I'm on their newsletter to get updates about current discount offerings). It contains a lot of embedded (Content-Disposition: inline) images that are referenced within the HTML code. With 336 KB it is no small mail, but it's also not huge, I have much bigger mails than that one.

Comment 14

[TGOS]

BTW this mail is not important to me. As long as it helps debugging I will keep it; however if you want me to remove it (temporarily, I guess I could re-import it at any time), just let me know. This would be an easy test to find out if Gloda works normally without this mail.

Comment 15

[Andrew Sutherland [:asuth] (he/him)]

Can you try using a nightly?  The mail message does not explode for me using a trunk build.
http://ftp.mozilla.org/pub/mozilla.org/thunderbird/nightly/latest-trunk/

Comment 16

[TGOS]

No, it does not explode for me either. Have you tried it with the official beta 2 to verify that it explodes for you as well?

You might say "Hey, it's fixed, whatever it was", but being a developer myself I know that just because it is now not happening anymore does not mean it was "fixed"; there could be some stupid incident that caused this issue to appear in the beta 2 and because of some code changes (possibly totally unrelated to the real problem) it now "incidentally" won't happen anymore with a trunk build, at least not with that one specific mail. Therefor a slightly different mail may still cause it to explode nonetheless (as the real reason for memory explosion may not have been fixed). I'm not sure where I can search commit messages on Mozilla.org if there are any commits that point towards a fix for a memory issue in Thunderbird (gloda).

The trunk build also has much more gloda log output than before. The memory stabilizes at around 42 MB private mem, 17 MB shared, real physical mem in use by the process slightly below 70 MB (430 MB virtual address space) - so these numbers are much more "sane" then before.

Comment 17

[TGOS]

Maybe an important update: Now that the trunk build seem to have finally indexed the problematic mail, when I go back to the Beta 2, it uses even less memory than the trunk build (25 MB private memory). So the problem seem to really have been in the indexing process of the mail; something was going terribly wrong when indexing this one mail I guess.

Comment 18

[Andrew Sutherland [:asuth] (he/him)]

Yeah, it explodes on beta 2 for me.  Assuming it was multipart/related or general emitter trouble, it was probably fixed by bug 482416.  If the problem was character-set related, probably bug 479214.

I would stick with the nightly if I were you.

Comment 19

[Erik Purins]

Hey team, I'm using released thunderbird 3.0.3 on win7 x64 with 4 cores and 8gb of ram. I pointed local folders account at my old thunderbird mailboxes from tbird 2 winxp, and indexing of folders with ~5k mails thrashes processor between 20-50% usage, and disc usage spikes. All of this and indexing of items does not complete indexing of messages at reasonable speed. 30 minutes of thrashing has indexed 241 of 4671 messages. Gloda had to be disabled to regain use of my computer.

Is this possibly the same bug, or do you want me to reopen a new one? How do should I proceed?

Comment 20

[Andrew Sutherland [:asuth] (he/him)]

Erik, please log a new bug in this instance adding ":asuth" to the CC line.  In the new bug please characterize the memory usage.  Since you have 4 cores and Thunderbird should really only be able to meaningfully dominate 2 of them and should not be able to allocate enough memory to cause VM swappage, I'd be interested if you could also elaborate on how it is managing to make your computer unusable.  Just a lot of I/O?

Also and most importantly, please turn on gloda debugging output and attach it:
https://wiki.mozilla.org/Thunderbird:Debugging_Gloda

Comment 21

[Erik Purins]

Thanks Andrew, I'll do that and follow up in the new issue.