729504 - mail.check_all_imap_folders_for_new enabled and low value for "check for new messages every" yields high mork activity and frequent short hangs when writing mail.

Status: NEW

(MailNews Core :: Database, defect)

Description

[[e-mail] (:bhearsum)]

For as long as I can remember now I've been getting frequent hangs in Thunderbird, most noticeably when I'm trying to write mail. The entire application will freeze up for 3-5s every 10-15s or so. With some help, I managed to get some stack traces and 3 different ones showed the hangs to be in mork. Here's the topmost parts of each:
#0  0x00007fcb0dccd8ec in morkMap::find (this=0x7fcae7d7ed20, ev=0x7fcac33ed800, inKey=0x7fff5bad2c68, inHash=<optimized out>) at /buildbot/linux64_build_beta/build/db/mork/src/morkMap.cpp:268
#1  0x00007fcb0dcce15a in morkMap::Get (this=0x7fcae7d7ed20, ev=0x7fcac33ed800, inKey=0x7fff5bad2c68, outKey=0x7fff5bad2c78, outVal=0x0, outChange=0x0) at /buildbot/linux64_build_beta/build/db/mork/src/morkMap.cpp:693
#2  0x00007fcb0dcc80fb in morkAtomBodyMap::GetAtom (this=<optimized out>, ev=<optimized out>, inAtom=0x7fcadbd80a60) at /buildbot/linux64_build_beta/build/db/mork/src/morkAtomMap.cpp:427
#3  0x00007fcb0dcd62ea in morkStore::YarnToAtom (this=0x7fcadbd80000, ev=0x7fcac33ed800, inYarn=0x7fff5bad2cf0, createIfMissing=true) at /buildbot/linux64_build_beta/build/db/mork/src/morkStore.cpp:722
#4  0x00007fcb0dcc90e5 in morkBuilder::OnValue (this=0x7fcaf5338800, ev=0x7fcac33ed800, inSpan=<optimized out>, inBuf=<optimized out>) at /buildbot/linux64_build_beta/build/db/mork/src/morkBuilder.cpp:855
#5  0x00007fcb0dcd094d in morkParser::ReadCell (this=0x7fcaf5338800, ev=0x7fcac33ed800) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:591
#6  0x00007fcb0dcd0cb3 in morkParser::ReadRow (this=0x7fcaf5338800, ev=0x7fcac33ed800, c=40) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:677
#7  0x00007fcb0dcd0ef3 in morkParser::ReadTable (this=0x7fcaf5338800, ev=0x7fcac33ed800) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:788
#8  0x00007fcb0dcd1437 in morkParser::ReadContent (this=0x7fcaf5338800, ev=0x7fcac33ed800, inInsideGroup=0 '\000') at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1434
#9  0x00007fcb0dcd1697 in morkParser::OnPortState (this=0x7fcaf5338800, ev=0x7fcac33ed800) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1480
#10 0x00007fcb0dcd1814 in morkParser::ParseMore (this=0x7fcaf5338800, ev=0x7fcac33ed800, outPos=0x7fff5bad2e7c, outDone=0x7fcaf74ef7e4 "", outBroken=0x7fcaf74ef7e5 "")
    at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1574
#11 0x00007fcb0dcdbc87 in morkThumb::DoMore_OpenFileStore (this=0x7fcaf74ef790, ev=<optimized out>) at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:472
#12 0x00007fcb0dcdbd70 in morkThumb::DoMore (this=0x7fcaf74ef790, ev=<optimized out>, outTotal=0x7fff5bad2ff8, outCurrent=0x7fff5bad2fc8, outDone=0x7fff5bad2fff "", outBroken=0x7fff5bad2ffe "")
    at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:395
#13 0x00007fcb0dcdbe04 in morkThumb::DoMore (this=0x7fcaf74ef790, mev=<optimized out>, outTotal=<optimized out>, outCurrent=<optimized out>, outDone=<optimized out>, outBroken=<optimized out>)
    at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:189
#14 0x00007fcb0dbb8605 in nsMsgDatabase::OpenMDB (this=0x7fcadb1b4540, dbName=<optimized out>, create=<optimized out>, sync=<optimized out>) at /buildbot/linux64_build_beta/build/mailnews/db/msgdb/src/nsMsgDatabase.cpp:1293


#0  0x00007fcb0dcd18ec in morkStream::Getc (this=0x7fcae0c27f20, ev=0x7fcad6546380) at /buildbot/linux64_build_beta/build/db/mork/src/morkStream.h:225
#1  0x00007fcb0dcd01af in morkParser::NextChar (this=0x7fcaf53f1800, ev=0x7fcad6546380) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:419
#2  0x00007fcb0dcd024f in morkParser::ReadHex (this=<optimized out>, ev=0x7fcad6546380, outNextChar=0x7fff5bad2d3c) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:833
#3  0x00007fcb0dcd04bf in morkParser::ReadMid (this=0x7fcaf53f1800, ev=0x7fcad6546380, outMid=0x7fcaf53f1860) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:514
#4  0x00007fcb0dcd088d in morkParser::ReadCell (this=0x7fcaf53f1800, ev=0x7fcad6546380) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:559
#5  0x00007fcb0dcd0cb3 in morkParser::ReadRow (this=0x7fcaf53f1800, ev=0x7fcad6546380, c=40) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:677
#6  0x00007fcb0dcd1427 in morkParser::ReadContent (this=0x7fcaf53f1800, ev=0x7fcad6546380, inInsideGroup=1 '\001') at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1429
#7  0x00007fcb0dcd1697 in morkParser::OnPortState (this=0x7fcaf53f1800, ev=0x7fcad6546380) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1480
#8  0x00007fcb0dcd1814 in morkParser::ParseMore (this=0x7fcaf53f1800, ev=0x7fcad6546380, outPos=0x7fff5bad2e7c, outDone=0x7fcad60f6124 "", outBroken=0x7fcad60f6125 "")
    at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1574
#9  0x00007fcb0dcdbc87 in morkThumb::DoMore_OpenFileStore (this=0x7fcad60f60d0, ev=<optimized out>) at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:472
#10 0x00007fcb0dcdbd70 in morkThumb::DoMore (this=0x7fcad60f60d0, ev=<optimized out>, outTotal=0x7fff5bad2ff8, outCurrent=0x7fff5bad2fc8, outDone=0x7fff5bad2fff "", outBroken=0x7fff5bad2ffe "")
    at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:395
#11 0x00007fcb0dcdbe04 in morkThumb::DoMore (this=0x7fcad60f60d0, mev=<optimized out>, outTotal=<optimized out>, outCurrent=<optimized out>, outDone=<optimized out>, outBroken=<optimized out>)
    at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:189
#12 0x00007fcb0dbb8605 in nsMsgDatabase::OpenMDB (this=0x7fcadb1b4540, dbName=<optimized out>, create=<optimized out>, sync=<optimized out>) at /buildbot/linux64_build_beta/build/mailnews/db/msgdb/src/nsMsgDatabase.cpp:1293



#0  0x00007fcb0dccde12 in morkMap::grow (this=0x7fcaf05e6c70, ev=0x7fcade414400) at /buildbot/linux64_build_beta/build/db/mork/src/morkMap.cpp:547
#1  0x00007fcb0dccdec7 in morkMap::Put (this=0x7fcaf05e6c70, ev=0x7fcade414400, inKey=0x7fff5bad2d08, inVal=0x0, outKey=0x0, outVal=0x0, outChange=0x0) at /buildbot/linux64_build_beta/build/db/mork/src/morkMap.cpp:579
#2  0x00007fcb0dcc8094 in morkAtomBodyMap::AddAtom (this=<optimized out>, ev=0x7fcade414400, ioAtom=0x7fcae02cf740) at /buildbot/linux64_build_beta/build/db/mork/src/morkAtomMap.cpp:398
#3  0x00007fcb0dcc8442 in morkAtomSpace::MakeBookAtomCopyWithAid (this=0x7fcaf05e6bc0, ev=0x7fcade414400, inAtom=<optimized out>, inAid=590549) at /buildbot/linux64_build_beta/build/db/mork/src/morkAtomSpace.cpp:213
#4  0x00007fcb0dcc8929 in morkBuilder::OnAlias (this=<optimized out>, ev=<optimized out>, inSpan=<optimized out>, inMid=<optimized out>) at /buildbot/linux64_build_beta/build/db/mork/src/morkBuilder.cpp:648
#5  0x00007fcb0dcd0afb in morkParser::ReadAlias (this=0x7fcaf9bdf000, ev=0x7fcade414400) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1053
#6  0x00007fcb0dcd11d4 in morkParser::ReadDict (this=0x7fcaf9bdf000, ev=0x7fcade414400) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1336
#7  0x00007fcb0dcd1447 in morkParser::ReadContent (this=0x7fcaf9bdf000, ev=0x7fcade414400, inInsideGroup=0 '\000') at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1439
#8  0x00007fcb0dcd1697 in morkParser::OnPortState (this=0x7fcaf9bdf000, ev=0x7fcade414400) at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1480
#9  0x00007fcb0dcd1814 in morkParser::ParseMore (this=0x7fcaf9bdf000, ev=0x7fcade414400, outPos=0x7fff5bad2e7c, outDone=0x7fcaddb15bd4 "", outBroken=0x7fcaddb15bd5 "")
    at /buildbot/linux64_build_beta/build/db/mork/src/morkParser.cpp:1574
#10 0x00007fcb0dcdbc87 in morkThumb::DoMore_OpenFileStore (this=0x7fcaddb15b80, ev=<optimized out>) at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:472
#11 0x00007fcb0dcdbd70 in morkThumb::DoMore (this=0x7fcaddb15b80, ev=<optimized out>, outTotal=0x7fff5bad2ff8, outCurrent=0x7fff5bad2fc8, outDone=0x7fff5bad2fff "", outBroken=0x7fff5bad2ffe "")
    at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:395
#12 0x00007fcb0dcdbe04 in morkThumb::DoMore (this=0x7fcaddb15b80, mev=<optimized out>, outTotal=<optimized out>, outCurrent=<optimized out>, outDone=<optimized out>, outBroken=<optimized out>)
    at /buildbot/linux64_build_beta/build/db/mork/src/morkThumb.cpp:189
#13 0x00007fcb0dbb8605 in nsMsgDatabase::OpenMDB (this=0x7fcadb1b48c0, dbName=<optimized out>, create=<optimized out>, sync=<optimized out>) at /buildbot/linux64_build_beta/build/mailnews/db/msgdb/src/nsMsgDatabase.cpp:1293



My profile has a few accounts set-up:
* IMAP to mail.mozilla.com
* RSS/News with 6 feeds
* NNTP to news.mozilla.org

I'm running 11.0b2 at the moment, on 64-bit Linux.

Comment 1

[Ludovic Hirlimann [:Usul]]

David Ideas ?

Comment 2

[David :Bienvenu]

We're opening a database - turning on MSGDB:4 logging - https://wiki.mozilla.org/MailNews:Logging and looking at the log right after the hang happens will tell you exactly which msf file(s) it's trying to open.

Do you have check all folders for new mail set? It's a hidden pref, or you can set it for individual folders via folder properties.

Comment 3

[[e-mail] (:bhearsum)]

(In reply to David :Bienvenu from comment #2)
> We're opening a database - turning on MSGDB:4 logging -
> https://wiki.mozilla.org/MailNews:Logging and looking at the log right after
> the hang happens will tell you exactly which msf file(s) it's trying to open.

OK, I did this and found that the hangs always happen at:
2012-02-22 15:15:24.300113 UTC - 471504896[7fa219158040]: nsMsgDatabase::Open(/home/bhearsum/.thunderbird/8kiq7lol.December 12, 2011/ImapMail/mail.mozilla.com/Bugzilla.sbd/Archive.msf, FALSE, 7fa1fadcbd00, FALSE)

Unsurprisingly, this is my largest folder at 154,000 messages.

> Do you have check all folders for new mail set? It's a hidden pref, or you
> can set it for individual folders via folder properties.

Yup, I've got that on for all folders, of which I have ~30 or so.

Comment 4

[David :Bienvenu]

How big is that .msf file? And how often are you checking for new messages? If you add "timestamp" to the msgdb logging, do you see it opening and closing the large .msf file every 10 or 15 seconds?

Comment 5

[[e-mail] (:bhearsum)]

(In reply to David :Bienvenu from comment #4)
> How big is that .msf file? And how often are you checking for new messages?
> If you add "timestamp" to the msgdb logging, do you see it opening and
> closing the large .msf file every 10 or 15 seconds?

The file is 77M, by far the largest. (The next largest is 22M.)

All accounts were set to check every 1min. It looks like it was being opening twice or so every minute.

I've since turned down the frequency of the checks to every 15min. With that done it looks to be being opening twice or so every 15min.

Comment 6

[Mark Hammond [:markh] [:mhammond]]

FWIW, I had similar problems for quite a while, and it slowed things down so much that the "conversations" addon was completely useless - sometimes took around 30 seconds to show a conversation.  I disabled that addon but was still plagued with the original symptoms outlined here.  I ended up nuking every .msf file in my profile - that made the problem far less noticeable and I was able to re-enable conversations.

Comment 7

[Wayne Mery (:wsmwk)]

Ben, the combination you describe typically induces very high, sustained CPU. Do you recall the processor usage?  I imagine bug 347837 (lazy closes) might help.

cameleon, xenos, do you recall seeing this on gsfn?  I recently had someone cite terrible performance with low value for "check for new messages every". Pretty sure it was in getsatisfaction (Encountered it myself a ways back)

Comment 8

[Wayne Mery (:wsmwk)]

(In reply to Mark Hammond (:markh) from comment #6)
> I ended up nuking every .msf file in my profile 

Mark, Unfortunately then we may not get to understand why your msf files were helping cause this. OTOH, it probably means your issue is different from Ben's.  Do you have mail.check_all_imap_folders_for_new enabled and/or low value for "check for new messages every" ?

Comment 9

[[e-mail] (:bhearsum)]

(In reply to Wayne Mery (:wsmwk) from comment #7)
> Ben, the combination you describe typically induces very high, sustained
> CPU. Do you recall the processor usage?  I imagine bug 347837 (lazy closes)
> might help.

I don't remember. I'll see if I can repro by changing the prefs again though.

Comment 10

[Wayne Mery (:wsmwk)]

(In reply to Wayne Mery (:wsmwk) from comment #7)
> cameleon, xenos, do you recall seeing this on gsfn?  I recently
> had someone cite terrible performance with low value for "check for new
> messages every". Pretty sure it was in getsatisfaction (Encountered it
> myself a ways back)

bah, the issue I personally experienced was Bug 485524 - Frequent freezing during composition with ... low value for preference Auto Save every N minute - though the impact is similar to the current bug

Comment 11

[Mark Hammond [:markh] [:mhammond]]

(In reply to Wayne Mery (:wsmwk) from comment #8)
> Do you have mail.check_all_imap_folders_for_new enabled 

Yep - that is true.

> and/or low value for "check for new messages every" ?

That is set to 10 minutes.

Comment 12

[Wayne Mery (:wsmwk)]

(In reply to Mark Hammond (:markh) from comment #11)
> (In reply to Wayne Mery (:wsmwk) from comment #8)
> > Do you have mail.check_all_imap_folders_for_new enabled 
> 
> Yep - that is true.

Mark, do you have very large folder(s) in imap?  gmail account(s)?

is your problem still gone?  (since you deleted the .msf files)

Comment 13

[Mark Hammond [:markh] [:mhammond]]

I do have a fairly large gmail account.  I've been running without the conversations addon for the last few months due to general slowness - I've just re-enabled it and I'll see how it goes now...

Comment 14

[Wayne Mery (:wsmwk)]

(In reply to Mark Hammond (:markh) from comment #13)
> I do have a fairly large gmail account.  I've been running without the
> conversations addon for the last few months due to general slowness - I've
> just re-enabled it and I'll see how it goes now...

Mark, how did that go?


And, perhaps we should profile the effect of mail.check_all_imap_folders_for_new enable - it does cause some unpleasantness for big messages stores.

Comment 15

[Mark Hammond [:markh] [:mhammond]]

I still find the conversations addon performs too slowly, so I re-disabled it many months ago and have been working since without it.

Comment 16

[Ludovic Hirlimann [:Usul]]

Removing myslef on all the bugs I'm cced on. Please NI me if you need something on MailNews Core bugs from me.

Comment 17

[Wayne Mery (:wsmwk)]

(In reply to Mark Hammond [:markh] from comment #15)
> I still find the conversations addon performs too slowly, so I re-disabled
> it many months ago and have been working since without it.

If I'm not confusing it with something else, I think I read that they recently improved the performance.

Regardless, is your performance now totally acceptable without the addon?

Comment 18

[Mark Hammond [:markh] [:mhammond]]

(In reply to Wayne Mery (:wsmwk, NI for questions) from comment #17)
> (In reply to Mark Hammond [:markh] from comment #15)
> > I still find the conversations addon performs too slowly, so I re-disabled
> > it many months ago and have been working since without it.
> 
> If I'm not confusing it with something else, I think I read that they
> recently improved the performance.
> 
> Regardless, is your performance now totally acceptable without the addon?

I'm not quite sure what you are asking, but yes, the performance issue I reported with the addon is still not a problem without the addon :)

Comment 19

[Worcester12345]

see also bug 1669589

Comment 20

[Wayne Mery (:wsmwk)]

Ben, does this still reproduce for you?

Comment 21

[[e-mail] (:bhearsum)]

I'm not sure, I haven't used Thunderbird in awhile.