720264 - 100% processor/high CPU (but UI responsive), nsImapMailFolder::HeaderFetchCompleted dominating event loop due to extra/too frequent full sync scan of headers

Status: RESOLVED WORKSFORME

(MailNews Core :: Networking: IMAP, defect)

Description

[Wayne Mery (:wsmwk)]

Attachment: XPERF of thunderbird looping

Mozilla/5.0 (Windows NT 6.0; rv:12.0a1) Gecko/20120118 Thunderbird/12.0a1

a couple days ago I noticed my laptop thunderbird pegged the cpu. I last restarted it on 20120118, probably after installing the 20120118 build. Since then, I've hibernated the system a couple times, switched networks, and also manually taken thunderbird offline.  I didn't notice the condition early so it's hard to say what triggered this. 

but I got xperf data, and I haven't restarted thunderbid.

Comment 1

[Wayne Mery (:wsmwk)]

Attachment: csv of XPERF data

took tbird offline - cpu drops to nominal
took tbird online  - cpu back at 100%

Comment 2

[Wayne Mery (:wsmwk)]

perhaps related ...

CC(T+341875.8) collected: 1414 (1414 waiting for GC), suspected: 1632, duration: 2592 ms.
GC(T+341894.7) Type:Glob, Total:848.9, Wait:1.6, Mark:660.9, Sweep:178.9, FinObj:16.0, FinStr:6.4, FinScr:1.6, FinShp:27.5, DisCod:6.3, DisAnl:8.2, XPCnct:24.2, Destry:0.7, End:28.0, +Chu:0, -Chu:0, Reason:  API
Timestamp: 1/22/2012 10:21:00 PM
Error: aFolder is undefined
Source File: chrome://messenger/content/folderWidgets.xml
Line: 691

Comment 3

[Wayne Mery (:wsmwk)]

It hung this evening, so I had to restart.
But hopefully profile will be of some use.

I can now say I've seen bad performance on a laptop.

Comment 4

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

It looks like nsImapMailFolder::HeaderFetchCompleted was dominating the event loop; presumably with a lot of I/O thrown in because the sample count does not show it being totally CPU bound.  Did the activity manager suggest anything suspicious, like re-download of all headers?  Did the task manager show a lot of system CPU usage(the red lines on the performance manager)?

Comment 5

[Wayne Mery (:wsmwk)]

> nsImapMailFolder::HeaderFetchCompleted was dominating the event loop; presumably with a lot of I/O thrown in because the sample count does not show it being totally CPU bound

I'm not sure why a discrepancy, but anecdotally, I seem to recall taskmgr show CPU pegged by thunderbird.


> Did the activity manager suggest anything suspicious, like re-download of all headers?

I had deleted panacea.dat but that downloading and reindex finished within a day. For several days the activity manager showed nothing unusual.


>  Did the task manager show a lot of system CPU usage(the red lines on the performance manager)?

no flashing disk light (laptop).  I can't definitively recall if system CPU was high. also I didn't have imap logging enabled.

Comment 6

[David :Bienvenu]

Whenever we finish an update of an imap folder, we iterate over the headers in the db to see if any of them need to be downloaded for offline use. If you have giant folders, that could take a little bit of time. Most of the code in that xperf sample looks to be related to that iteration. We used to only do this if you'd set the folder to automatically download all message bodies when we download headers, but autosync changed this so that it does this as well, and passes the headers to the download code. This is definitely sub-optimal. We could be a lot smarter about doing this full sync a lot less often, but it doesn't seem to be causing normal users much pain.

Comment 7

[Yaniv Kaul]

Happens to me as well and since the stack is different in every gdb run, I suspect it's indeed the case as noted above. However, it's been taking several hours (at least two so far) to complete.

Here's the top of the stack of the 100% CPU consuming thread:
(gdb) bt
#0  PL_DHashTableOperate (table=0x7f3cd576cdc0, key=0x9fe0b, op=<optimized out>) at /usr/src/debug/thunderbird-11.0.1/comm-release/mozilla/xpcom/build/pldhash.cpp:670
#1  0x00007f3d20ef8f52 in nsMsgDatabase::AddHdrToCache (this=0x7f3d05654d00, hdr=0x7f3cd5206d00, key=<optimized out>) at nsMsgDatabase.cpp:460
#2  0x00007f3d20ef9286 in CreateMsgHdr (result=0x7fff37aff700, key=654859, hdrRow=0x7f3cd5206c20, this=0x7f3d05654d00) at nsMsgDatabase.cpp:769
#3  nsMsgDatabase::CreateMsgHdr (this=0x7f3d05654d00, hdrRow=0x7f3cd5206c20, key=654859, result=0x7fff37aff700) at nsMsgDatabase.cpp:753
#4  0x00007f3d20ef91fa in GetMsgHdrForKey (pmsgHdr=0x7fff37aff700, key=654859, this=0x7f3d05654d00) at nsMsgDatabase.cpp:1833
#5  nsMsgDatabase::GetMsgHdrForKey (this=0x7f3d05654d00, key=654859, pmsgHdr=0x7fff37aff700) at nsMsgDatabase.cpp:1798
#6  0x00007f3d20e67a8d in GetMsgHdrForViewIndex (msgHdr=0x7fff37aff700, index=93170, this=0x7f3cd55c2000) at nsMsgSearchDBView.cpp:411
#7  nsMsgSearchDBView::GetMsgHdrForViewIndex (this=0x7f3cd55c2000, index=93170, msgHdr=0x7fff37aff700) at nsMsgSearchDBView.cpp:398
#8  0x00007f3d20e676e5 in nsMsgSearchDBView::FindHdr (this=0x7f3cd55c2000, msgHdr=0x7f3cd513cb20, startIndex=<optimized out>, allowDummy=false) at nsMsgSearchDBView.cpp:1276
#9  0x00007f3d20e528d6 in nsMsgDBView::OnHdrDeleted (this=0x7f3cd55c2000, aHdrChanged=<optimized out>, aParentKey=<optimized out>, aFlags=<optimized out>, aInstigator=<optimized out>) at nsMsgDBView.cpp:5964
#10 0x00007f3d20e68ae4 in nsMsgSearchDBView::OnHdrDeleted (this=0x7f3cd55c2000, aHdrDeleted=0x7f3cd513cb20, aParentKey=<optimized out>, aFlags=<optimized out>, aInstigator=<optimized out>)
    at nsMsgSearchDBView.cpp:315


Running on Fedora16/x64, thunderbird-11.0.1-1.fc16.x86_64

Comment 8

[Wayne Mery (:wsmwk)]

(In reply to David :Bienvenu from comment #6)
> Whenever we finish an update of an imap folder, we iterate over the headers
> in the db to see if any of them need to be downloaded for offline use. If
> you have giant folders, that could take a little bit of time. Most of the
> code in that xperf sample looks to be related to that iteration. We used to
> only do this if you'd set the folder to automatically download all message
> bodies when we download headers, but autosync changed this so that it does
> this as well, and passes the headers to the download code. This is
> definitely sub-optimal. We could be a lot smarter about doing this full sync
> a lot less often, but it doesn't seem to be causing normal users much pain.

depends what you mean by "big", and "normal". I'm not sure I am either of these :) 
imap inboxes: 
 account-A ~500  
 account-B ~2,000  
 account-C (gmail) 600 (I suspect not very big for gmail users)
other folders set to "check for new messages": 
 account-A 3,000  
 account-A 1,500  
 (note - I didn't check all folders in eery account because there's no function to show all folders settings)


More generally, where on the curve performance might "not normal" hit to become less or non-performant?  For example, would you expect this to be worse for people with large folder and high frequency (low minutes) for checking for new mail?  What about users with mail.check_all_imap_folders_for_new set non-default true?


Yaniv, do you see this problem every day? I haven't noticed this high cpu usage since I reported the bug.

Comment 9

[Wayne Mery (:wsmwk)]

> What about users with  mail.check_all_imap_folders_for_new set non-default true?

xref Bug 729504

Comment 10

[David :Bienvenu]

Yaniv's stack and issue are completely different from the one your xperf data shows, Wayne. For your issue, Wayne, I would expect you would have to have 10's of thousands of messages to see it at all, and even then, only on cpu-bound systems. Yaniv's stack makes me think there's some sort of vicious cycle in the delete code from search results, *or* he deleted thousands of messages.

Comment 11

[Wayne Mery (:wsmwk)]

(In reply to Yaniv Kaul from comment #7)
> Happens to me as well and since the stack is different in every gdb run, I
> suspect it's indeed the case as noted above. However, it's been taking
> several hours (at least two so far) to complete.

Yaniv, can you still reproduce and have a testcase with newer version of tbird?

Comment 12

[Yaniv Kaul]

(In reply to Wayne Mery (:wsmwk) from comment #11)
> (In reply to Yaniv Kaul from comment #7)
> > Happens to me as well and since the stack is different in every gdb run, I
> > suspect it's indeed the case as noted above. However, it's been taking
> > several hours (at least two so far) to complete.
> 
> Yaniv, can you still reproduce and have a testcase with newer version of
> tbird?

No, haven't seen it for quite some time.

Comment 13

[Wayne Mery (:wsmwk)]

summary is hopefullly better and accurrate

Comment 14

[Wayne Mery (:wsmwk)]

I haven't seen this for ages, so WFM