[Bug 704623] Re: Thunderbird renders system unusable / uses 100% CPU while indexing new messages

Bug Watch Updater 704623 at bugs.launchpad.net
Wed May 16 13:14:25 UTC 2012


Launchpad has imported 34 comments from the remote bug at
https://bugzilla.mozilla.org/show_bug.cgi?id=712371.

If you reply to an imported comment from within Launchpad, your comment
will be sent to the remote bug automatically. Read more about
Launchpad's inter-bugtracker facilities at
https://help.launchpad.net/InterBugTracking.

------------------------------------------------------------------------
On 2011-12-20T19:04:43+00:00 Wil Clouser wrote:

Prior to the Mozilla email troubles Thunderbird was fine.  Now it's
nearly unusable for me.  I assume something in my profile but I don't
know how to test it or what to look for.

- On start up no window is displayed and Thunderbird consumes 100% cpu
for around 60 seconds.  Soon I get a popup that says "Warning:
Unresponsive Script" for "Script:
resource://modules/iteratorUtils.jsm:117".  If I click Continue
Thunderbird launches and is usable.

- On switching windows to Thunderbird (it was running in the background)
the window is unresponsive, CPU is at 100% for about 30s.  CPU returns
to idle, Thunderbird is usuable

What can I give you that would help figure this out?  I have some local
folders, but most activity is via IMAP.  The sizes of the folders are
similar to what they were pre-catastrophe.

This is Thunderbird 8 on Linux.  I have lightning installed, but this
happens with it disabled also.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/2

------------------------------------------------------------------------
On 2011-12-22T14:16:06+00:00 Vseerror wrote:

I don't know what this means "Prior to the Mozilla email troubles".
Please explain.

What were your results with safe mode?
 http://support.mozillamessaging.com/en-US/kb/safe-mode

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/3

------------------------------------------------------------------------
On 2011-12-22T16:40:17+00:00 Wil Clouser wrote:

(In reply to Wayne Mery (:wsmwk) from comment #1)
> I don't know what this means "Prior to the Mozilla email troubles".  Please
> explain.

Mozilla had major email outages with some data loss last week.  Perhaps
unrelated but it's the only major event recently.

> What were your results with safe mode?
>  http://support.mozillamessaging.com/en-US/kb/safe-mode

No difference.  The only output when run from a command line is "Error
-> TypeError: GetSelectedMsgFolder() is undefined"

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/4

------------------------------------------------------------------------
On 2011-12-23T07:13:43+00:00 M-wada wrote:

Phenomenon reported to this bug can easily be observed by next procedure.
(1) Copy small Tb profileP1) to new profile(P2) for test.
  - Copy ...\Profiles\...P1... directory to ...\Profiles\...P2... directory
  -  Start profile manager(thunderbird.exe -ProfileManager), and add the copied
  -  profile as new profile. Create Profile, name=P2, Choose Folder, and select
  -  the copied ...\Profiles\...P2... directory.  
(2) Create many local mail folder files under Local Folders of copied P2.
    - Create file and directory for subfolders.
      file      :  ...\Profiles\...P2...\Mail\Local Folders\Test
      directory :  ...\Profiles\...P2...\Mail\Local Folders\Test.sbd
    - Create many files for mail folder under ...\Test.sbd.
      For example, create X-1 to X-9999 file for Test/X-1 to Test/X-9999 folder.
      create null file named X-0,
      Do NN=1 to 9999; Copy "X-0" "X-"||NN ; End; (Rexx like pseudo code)
(3) Delete panacea.dat in profile directory for P2.
    delete ...\Profiles\...P2...\panacea.dat
(4) Start Tb using the copied profile, P2,
    with offline mode in order to prohibit server access.
    thunderbird.exe -offline -p "P2"
    => It takes long, CPU 100%, Unresponsive Script warning
(5) Repeat step (4) several times.
    Similar slowess can be observed without deletion of panacea.dat,
    because very many local folder files are created intentionally.

panacea.dat file holds relation among mail folder name, .msf file path, mail folder file path(Inbox instead of Inbox.msf if folder of Inbox).
If panacea.dat is corrupted or lost, directory scan for mail folder file, for assciated .msf file, for associated .sbd directory, happens on any subdirectory under ...\Mail. Because directory scan is time consuming work and CPU power is consumed by OS, and because Tb produces many directory scans than manatory/minimum number of scans, it usually takes long.

Needless to say, directory scan is applicable to .msf file, offline-store file, .sbd directory for IMAP folder too(...\ImapMail directory).
And, if IMAP, sync'ed status is perhaps lost, then, re-fetch of mail headers of all mails in all mail folders, and re-download of all mail data of all offline-use folder, perhaps happens.

Bug opener, how many mail folders do you have?

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/5

------------------------------------------------------------------------
On 2011-12-23T21:20:54+00:00 Wil Clouser wrote:

Created attachment 584114
screenshot of folders

Folders are as attached.  The folders locally have been around for
months-years with no troubles.  The majority of the IMAP folders have
been around for weeks-months with no troubles.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/6

------------------------------------------------------------------------
On 2011-12-24T02:49:37+00:00 M-wada wrote:

How many files/directories are currently defined by Tb for mail
folder/newsgroups?

If Linux, you can roughly check by commad like "ls --recursive --a /Tb's-prof-dir/*.msf" and "ls --recursive --a --directory /Tb's-prof-dir/*.sbd" (see man page of ls, please. if Win, DIR "Tb's prof die path\*.msf" /S > C:\work\DIRLIST.TXT)
Note: If garbage of .sbd directory exists, it's not shown at folder pane, but such hidden directory is also scanned if panacea.dat is corrupted.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/7

------------------------------------------------------------------------
On 2011-12-24T03:12:07+00:00 Wil Clouser wrote:

Created attachment 584155
dir listing

find output is attached

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/8

------------------------------------------------------------------------
On 2011-12-24T04:50:42+00:00 M-wada wrote:

Following is seen in list.
> ./5hyolzp2.default/Mail/smart mailboxes/Trash.msf
> ./5hyolzp2.default/Mail/smart mailboxes-1/Trash.msf
It inidicates that, when hidden "smat mailboxes" account("Unified Folders") is defined, directory of "smart mailboxes" already exists, then directory with suffix of "-1" was created and used.
It may indicate something wrong happened.
However, only 15 following lines is seen in directory list,
> ./5hyolzp2.default/ImapMail/mail.mozilla.com/INBOX.sbd/xxx.msf
and subfolders under Inbox of IMAP account in screen shot is 15 too.
So, "phenomenon of bug 520437 due to something wrong" didn't occur in your environment, and garbages of files/directories due to problem don't exist.

Number of files/directories doesn't seem large in your case. So, it's hard to guess that a cause of slowness is directory scan, if local directory(and because of not-MS-Win case).
Note: slowness in this case seems one like next:
  {number of directories} * O( {number of files in a directory}**N )
  i.e. if {number of files in a directory} increases,
       slowness increases very rapidly. 
  My example is {number of files in a directory} of only one directory==9999 case

Do you mount remote drive as ./5hyolzp2.default?
If yes, slowness/high CPU usage by directory scan like "slowness when 9999 subfolders under one local mail folder on Win" may be exposed even on Linux.

If possible, can you check next, to rule out directory scan case?
1. Copy current profile, delete panacea.dat in copied profile.
2. Start Tb using the copied profile, with offline mode in order to prohibit IMAP server access upon restart of Tb.
   thunderbird.exe -offline -p

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/9

------------------------------------------------------------------------
On 2011-12-24T07:06:19+00:00 Wil Clouser wrote:

(In reply to WADA from comment #7)
> Following is seen in list.
> > ./5hyolzp2.default/Mail/smart mailboxes/Trash.msf
> > ./5hyolzp2.default/Mail/smart mailboxes-1/Trash.msf

As far as I know I don't use any smart mailboxes.  Would be fine if they
went away. :)

> Do you mount remote drive as ./5hyolzp2.default?

No, it's on a local SSD.

> If possible, can you check next, to rule out directory scan case?
> 1. Copy current profile, delete panacea.dat in copied profile.
> 2. Start Tb using the copied profile, with offline mode in order to prohibit
> IMAP server access upon restart of Tb.
>    thunderbird.exe -offline -p

I copied the profile and tried it.  The file came back and the slowness
was still present.  The panacea.dat I deleted was 415k, the one that was
created on restart was 14k.

On a whim, I restarted Thunderbird again after the 14k file was there
and it opened quickly (yay) but the IMAP folders were gone.  If I go
online I assume they'll come back but haven't done that in case there is
more I can do for this bug.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/10

------------------------------------------------------------------------
On 2011-12-24T08:20:57+00:00 M-wada wrote:

(In reply to Wil Clouser [:clouserw] from comment #8)
> > If possible, can you check next, to rule out directory scan case?
> > 1. Copy current profile, delete panacea.dat in copied profile.
> > 2. Start Tb using the copied profile, with offline mode in order to prohibit
> > IMAP server access upon restart of Tb.
> >    thunderbird.exe -offline -p
> I copied the profile and tried it.  
> The file came back and the slowness was still present.
 
Same degree of slowness as comment #0?

"Delete panace.dat" is in order to surely force re-validation of relation between mail folder file and file for mail folder which invokes directory scan work for mail folder files.
If same slowness was observed by it, main cause of slowness in comment #0 may be time consuming work such as directory scan for mail folder files, re-validation of relation between mail folder and file for mail folder etc.
Loss of sync'ed status of IMAP folder, loss of validated status of relation between mail folder and mail folder file etc. can produce time consuming re-sync process, re-validation process/directory scan process etc.

Other may invoke such time consuming process.
If 9999 files are created under .sbd for local mail folder, even when slowness in restart of Tb is not observed by helthy panacea.dat, sufficient slowness is always observed upon first rename/delete of a local mail folder after restart. This is perhaps because Message Filter tracks rename/delete of folder and rename/delete or Message Filter perhaps scans all mail folder and files for mail folder upon first rename/delete after restart of Tb.
This may be applicable to IMAP folder.
This may be caused by non-initialized .msf, because almost all 9999 mail folders were not explicitly opened by folder click. I can't click all 9999 folders in testing, althogh I'll try to do it if it's mandatory to reproduce very important and critical problem.
(Off-topic)
> but the IMAP folders were gone.

You merely saw phenomenon of bug 698321.
If you Go Online with the copied profile, server access happend, and it interferes daily use(e.g. if you have POP3 account of "Leave Messages on Server"=off, mail is downloaded to copied profile, then removed from server's Mbox.) 
It's for testing purpose only. Please be careful.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/11

------------------------------------------------------------------------
On 2011-12-24T08:32:28+00:00 Wil Clouser wrote:

Yes, deleting panacea.dat and then starting thunderbird caused the same
symptoms:  100% cpu and no window for 40 seconds, then a slow script
warning, upon continue the window appeared.  Also, the disk activity
remains near idle during the entire startup - if it were scanning
directories I wouldn't expect that.

I haven't been online again since we started this.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/12

------------------------------------------------------------------------
On 2012-01-05T08:27:48+00:00 Ludovic-mozilla wrote:

Will in which office do you seat ?

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/13

------------------------------------------------------------------------
On 2012-01-05T08:37:01+00:00 Wil Clouser wrote:

I'm a remote worker

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/14

------------------------------------------------------------------------
On 2012-01-17T06:36:38+00:00 Wil Clouser wrote:

This is affecting my productivity and I'm just going to delete my
profile and start over.  Is there anything else I can do for this bug?

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/15

------------------------------------------------------------------------
On 2012-01-17T07:59:37+00:00 M-wada wrote:

Created attachment 589116
NNTP log for "Repair Folder" of news.mozilla.org, mozilla.general("Mark newsgroup read" is already done)

NNTP log for next.
- news.mozilla.org, newsgroup=mozilla.general : 41397 articles
- Mark newsgroup read is already done
(1) Click mozilla.general
(2) Folder Properties, Repair Folder
    => download dialog for mozilla.general is shown 
       request 500 header download, with "mark others as read" 
    => second download dialog mozilla.general was shown
       request 500 header download, with "mark others as read" 

(In reply to Wil Clouser [:clouserw] from comment #6)
> Created attachment 584155
> dir listing

Your subscribed newsgroups.
./5hyolzp2.default/News/news.mozilla.org/mozilla.support.webtools.msf
./5hyolzp2.default/News/news.mozilla.org/mozilla.dev.extensions.msf
./5hyolzp2.default/News/news.mozilla.org/mozilla.dev.amo.msf
./5hyolzp2.default/News/news.mozilla.org/mozilla.general.msf
./5hyolzp2.default/News/news.mozilla.org/mozilla.dev.l10n.msf
./5hyolzp2.default/News/news.mozilla.org/mozilla.dev.planning.msf
./5hyolzp2.default/News/news.mozilla.org.msf

news.mozilla.org,rc content in my environment after "Mark newsgroup
read".

mozilla.general: 1-41397
mozilla.events: 1-212
mozilla.support.webtools: 1-1762
mozilla.dev.extensions: 1-16246
mozilla.dev.apps.dom-inspector: 1-291
mozilla.dev.general.zh: 1-23
mozilla.dev.l10n: 1-12356
mozilla.dev.planning: 1-19280

As "500 headers" only(40898-41397), five hundreds XOVER response is seen in NNTP log.
  Sending: XOVER 40898-41397
And, this was repeated twice by "Repair Folder"

When panacea.dat is deleted, re-sync may occur on news group too.
And, re-sync after lost synchronization is similar to "Repair Folder".
Following newsgroups you subscribe is relatively large, 
  mozilla.general:        1-41397
  mozilla.dev.extensions: 1-16246
  mozilla.dev.l10n:       1-12356
  mozilla.dev.planning:   1-19280
So, if re-sync process of these newsgroups happens, many XOVER reponse needs to be processed by Tb during restart.
And, problem of bug 695309 is known on News.

News may be relevant to your case.
Do you need all above newsgroups?
Do you see your problem with "large newsgrops unsubscribed"?

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/16

------------------------------------------------------------------------
On 2012-01-17T09:42:17+00:00 Wil Clouser wrote:

I deleted the news.mozilla.org account completely.  No change in
performance or size of the panacea.dat file.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/17

------------------------------------------------------------------------
On 2012-01-19T23:49:42+00:00 Vseerror wrote:

Wil, how many mail folders in "local folders"?

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/18

------------------------------------------------------------------------
On 2012-01-19T23:54:52+00:00 Wil Clouser wrote:

Directory listing is attachment 584155.  23 folders under Local Folders.

I've since copied that entire directory structure to my new profile and
the new profile is as fast as it ever was before the slowness problems.
Old profile is still laggy.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/19

------------------------------------------------------------------------
On 2012-01-19T23:56:33+00:00 Wil Clouser wrote:

It's still taking ~25s before I have a window open when starting
thunderbird but I'm no longer seeing the unresponsive script warning.
Perhaps deleting the newsgroups got it under that threshold.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/20

------------------------------------------------------------------------
On 2012-01-20T01:12:44+00:00 M-wada wrote:

(In reply to Wil Clouser [:clouserw] from comment #18)
> It's still taking ~25s before I have a window open when starting thunderbird
> but I'm no longer seeing the unresponsive script warning.  Perhaps deleting
> the newsgroups got it under that threshold.

Gain by deletion of newsgroups seems 5 sec only.
Do you have big message filter? Because msgFilterRules.dat is read one byte each(Bug 571419), big msgFilterRules.dat may affect on startup time when "new mail check upon startup" is enabled. What is file size of msgFilterRules.dat files?

Slowness is observed upon any restart of Tb? Or first restart of Tb after login or re-boot?
On Win, because Fx/Tb/Sm modules are not loaded(and cached) by re-boot, first restart after re-boot is far slower than IE, but second or later restart is not so slow because already cached. Virus scanner may affect on it too, because virus scan may be invoked on first load but it may not be upon second load.
Is this kind of slowness involved in your case?

By the way, can you use monitor tools? If you can use monitor tool for application's file access, it may help your problem analysis, because activities of Tb during restart is reflected to file access by Tb.
Bug 571419 was fortunately discovered while I was viewing Process Monitor log on Win for duplication test of other different problem. Flood of log lines for specific file/directory, too many repeated access to specific file/directory etc., is sometimes signal of something wrong around process related to the file/directory, and, by flood of log lines for msgFilterRules.dat, I was aware of the problem.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/21

------------------------------------------------------------------------
On 2012-01-20T01:16:20+00:00 Dbienvenu wrote:

MSGDB:5,timestamp NSPR logging on the slow profile might tell us if the
slow down has to do with opening db's on startup -
https://wiki.mozilla.org/MailNews:Logging

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/22

------------------------------------------------------------------------
On 2012-01-20T01:18:05+00:00 Wil Clouser wrote:

> Gain by deletion of newsgroups seems 5 sec only.
> Do you have big message filter? Because msgFilterRules.dat is read one byte
> each(Bug 571419), big msgFilterRules.dat may affect on startup time when
> "new mail check upon startup" is enabled. What is file size of
> msgFilterRules.dat files?

Two are 25 bytes, the one for ImapMail is 1.3k. 
 
> Slowness is observed upon any restart of Tb? Or first restart of Tb after
> login or re-boot?

Every time it starts and every few minutes while it is running.

> On Win, because Fx/Tb/Sm modules are not loaded(and cached) by re-boot,
> first restart after re-boot is far slower than IE, but second or later
> restart is not so slow because already cached. Virus scanner may affect on
> it too, because virus scan may be invoked on first load but it may not be
> upon second load.
> Is this kind of slowness involved in your case?

This is a linux box and there is no virus scanner.

> By the way, can you use monitor tools? If you can use monitor tool for
> application's file access, it may help your problem analysis, because
> activities of Tb during restart is reflected to file access by Tb.
> Bug 571419 was fortunately discovered while I was viewing Process Monitor
> log on Win for duplication test of other different problem. Flood of log
> lines for specific file/directory, too many repeated access to specific
> file/directory etc., is sometimes signal of something wrong around process
> related to the file/directory, and, by flood of log lines for
> msgFilterRules.dat, I was aware of the problem.

I can give you the output of anything built into linux.  Not sure what
would be helpful.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/23

------------------------------------------------------------------------
On 2012-01-20T02:13:47+00:00 M-wada wrote:

(In reply to Wil Clouser [:clouserw] from comment #21)
> Not sure what would be helpful.

Helpful for you. If special pattern is seen in log, it may be relevant
to problem.

Exmples.
(A) In temporary file creation, Tb tries to create xxx-{N}.tmp, and if already exists, Tb tries to create xxx-{N+1}.tmp. Tb execute it from 1 to X always for each tempory file, so following pattern appears in log.
> For temp file of nsmail :
>  For first temp file :
>   create nsmail-1=>fail, ..., create nsmail-100=>success
>  For second temp file :
>   create nsmail-1=>fail, ..., create nsmail-100=>fail, create nsmail-101=>success
>  For third temp file :
>   create nsmail-1=>fail, ..., create nsmail-100=>fail, create nsmail-101=>fail, create nsmail-102=>success
Because of this, if many garbages of nsmail-X.tmp remain, performace problem arise, and it can be detected by above log pattern.

(B) Similar pattern is also seen in directory scan type access.
Tb looks to check file relevant to mail folder by procedure like next.
For folder A, tries to find file A from directory list by "compare file#1 to file#N with A, and if found, stop compare". So, if A doesn't exist, all files in directory is compared.
This is done for all known folder names. So, in average, half of files in a directory is compared per one mail folder.
Above never represents actual Tb's behavior or algorythm, but log pattern like above is seen in file access log.
This kind of log pattern can be a reason why performance degradiation happens in an environment. If time to comlete above process pattern is nealy equals to slow startup time, we can consider that above access is cause of slowness.
This is reason why I asked you about number of mail folders and number of files for mail folder, and reason why asked about slowness when panacea.dat is deleted.
When I tried to catch slowness by access like above, I intentionally created 10,000 folders/files in a directory, so I could see 10,000 * "access from 1 to N(average=5000)" in log file.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/24

------------------------------------------------------------------------
On 2012-01-20T03:11:19+00:00 M-wada wrote:

FYI.
Process monitor log attached to Bug 545126 is another example.
That bug is for slowness in showing image in HTML mail due to "all folder file name scan per one image in an HTML mail", and log pattern of "all folder file name scan" is seen multiple times("number of imaes" times) in log. After fix of that bug, number of "all folder file name scan" is reduced very much, but such scan still remains(bug 563677). This is another reason why I asked about number of folders.

Another concern.
Althogh bug 599119 is already fixed in Tb, Bug 485538 remains in Core. If plugin scan is invoked for many tasks for some reasons during restart, it may affect on startup time. Even after fix of bug 599119, disabling plugin by addon manager may be a effective workaround if such issue exists in your environment.
Plugin scan is relevant or not is also known by file access log - if number of access to pluginreg.data is not so many, it's irrelevant to problem.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/25

------------------------------------------------------------------------
On 2012-01-20T06:48:40+00:00 Wil Clouser wrote:

Created attachment 590115
NSPR logging output

Here's the output from the logging

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/26

------------------------------------------------------------------------
On 2012-01-20T07:48:40+00:00 M-wada wrote:

(In reply to Wil Clouser [:clouserw] from comment #24)
> NSPR logging output

"NN open DB's" of each second. 
> 2012-01-20 01:19:53.645697 UTC - -1223960784[b6e401c0]:  0 open DB's
> 2012-01-20 01:19:54.327791 UTC - -1223960784[b6e401c0]:  3 open DB's
> 2012-01-20 01:19:55.246282 UTC - -1223960784[b6e401c0]:  5 open DB's
> 2012-01-20 01:19:56.022794 UTC - -1223960784[b6e401c0]:  5 open DB's
>   (number of opened DB doesn't increase for 8 seconds)
> 2012-01-20 01:20:04.638781 UTC - -1223960784[b6e401c0]:  5 open DB's
> 2012-01-20 01:20:05.100987 UTC - -1223960784[b6e401c0]:  5 open DB's
> 2012-01-20 01:20:06.002171 UTC - -1223960784[b6e401c0]:  7 open DB's
>   (number of opened DB increases by 14 within 1 second)
> 2012-01-20 01:20:06.884807 UTC - -1223960784[b6e401c0]: 21 open DB's
>   (number of opened DB doesn't increase 9 seconds)
> 2012-01-20 01:20:15.541239 UTC - -1223960784[b6e401c0]: 22 open DB's
> 2012-01-20 01:20:15.543044 UTC - -1223960784[b6e401c0]: 23 open DB's
> 2012-01-20 01:20:15.544233 UTC - -1223960784[b6e401c0]: 24 open DB's
> 2012-01-20 01:20:15.544889 UTC - -1223960784[b6e401c0]: 25 open DB's
> 2012-01-20 01:20:15.545236 UTC - -1223960784[b6e401c0]: 26 open DB's
> 2012-01-20 01:20:15.548396 UTC - -1223960784[b6e401c0]: 27 open DB's
> 2012-01-20 01:20:15.550835 UTC - -1223960784[b6e401c0]: 28 open DB's
> 2012-01-20 01:20:15.551328 UTC - -1223960784[b6e401c0]: 29 open DB's
> 2012-01-20 01:20:15.551832 UTC - -1223960784[b6e401c0]: 30 open DB's
> 2012-01-20 01:20:15.553258 UTC - -1223960784[b6e401c0]: 31 open DB's
> 2012-01-20 01:20:15.699753 UTC - -1223960784[b6e401c0]: 32 open DB's
> 2012-01-20 01:20:16.556996 UTC - -1223960784[b6e401c0]: 33 open DB's (first 33 open DB)

Is 01:20:16 startup completion time? (23 seconds since first log)
If so, two "no increase for 8-9 seconds" may be a reason.
Waiting for something for 8-9 seconds?

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/27

------------------------------------------------------------------------
On 2012-01-31T03:26:48+00:00 Wil Clouser wrote:

> Is 01:20:16 startup completion time? (23 seconds since first log)

I would guess 01:21:00 was about the startup time.  I started
thunderbird, let it run until it quit using 100% cpu, and then shut it
down, so that timing seems closer to me.

> If so, two "no increase for 8-9 seconds" may be a reason.
> Waiting for something for 8-9 seconds?

Sounds like it.  I don't know what it would be waiting on or how to
determine it.  I mentioned this is all on an SSD so I don't think it's
disk (disk usage isn't up at the time).  It seems CPU bound.  The box is
a quad core i7 930.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/28

------------------------------------------------------------------------
On 2012-01-31T05:48:31+00:00 M-wada wrote:

(A) Continuous "closing database" starts from next log.
    It looks start of termination after restart completion around 01:21:00.
> 2012-01-20 01:21:18.719964 UTC - -1223960784[b6e401c0]: closing database    /home/clouserw/.thunderbird/5hyolzp2.default/Mail/smart mailboxes-1/Trash.msf
(B) Following log is seen.
    Cause of two "no increase of No. of open DB for 8-9 seconds"?
> 2012-01-20 01:19:53.652355 UTC - -1223960784[b6e401c0]: error opening db 80550005
> 2012-01-20 01:19:53.652430 UTC - -1223960784[b6e401c0]: error opening db 80550006
(B) Funny log sequence is seen.
    Just before each "NN open DB's", "closing database ..." line and
    "nsMsgDatabase::Open(..." line always appears.
    Why "close a DB" and "open other DB" is executed periodically?
    Expiration of DB open time for non-selected mail folder?
    If so, why close(and re-open in future interval) is done for specific
    folders only?  Why it's not "round robin" of all mail folders?

To open all mail folders, at least "physical read data of whole .msf file for all .msf files" is required(see bug 722183 comment #5).
What is total file size of .msf files under Mail, ImapMail, News directory?

Repeatedly closed/re-opened DB in your case is /Local Folders/archive-moz.sbd/YYYY.sbd/inbox.msf or /sent.msf etc. Because such mail folder is usually large, each re-open of folder may take a few seconds. And, because such already opend DB is closed sooner or later and re-open will be required, it may takes long to reach "All DB is opened and checked" like status.
This kind of issue?

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/29

------------------------------------------------------------------------
On 2012-01-31T06:25:37+00:00 M-wada wrote:

http://mxr.mozilla.org/comm-central/source/mailnews/db/gloda/modules/index_msg.js#76
> 76 const NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE = 0x80550005;
http://mxr.mozilla.org/comm-central/source/mailnews/base/public/msgCore.h#135
> 135 #define NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE NS_MSG_GENERATE_FAILURE(5)
> 136 #define NS_MSG_ERROR_FOLDER_SUMMARY_MISSING NS_MSG_GENERATE_FAILURE(6)
http://mxr.mozilla.org/comm-central/source/mailnews/base/search/src/nsMsgLocalSearch.cpp#310
> 310         case NS_MSG_ERROR_FOLDER_SUMMARY_MISSING:
> 311         case NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE:

80550005 was NS_MSG_ERROR_FOLDER_SUMMARY_OUT_OF_DATE.
80550006 is perhaps NS_MSG_ERROR_FOLDER_SUMMARY_MISSING.

What is your mail folder which is not shown as "opened DB" in log?

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/30

------------------------------------------------------------------------
On 2012-01-31T06:39:46+00:00 M-wada wrote:

FYI.
I had mail folder file greater than 4GB for testing in a profile. After forced kill of Tb while Tb is nearly hang for testing, restart with the profile took very very long with high CPU usage, and I killed Tb before restart completion, so "restart of Tb doesn't complete" status was kept. As I knew well about intentional file of "greater than 4GB", I deleted the file of "greater than 4GB", and problem disappered immediately by the "delete file" only. 
If internal rebuild-index is invoked for large mail folder during restart of Tb, it'll take long. If internal re-build index during restart of Tb, FOLDER_SUMMARY_OUT_OF_DATE condition may not be cleard. Explicit folder open, by such as folder click, may be required.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/31

------------------------------------------------------------------------
On 2012-01-31T17:03:34+00:00 Wil Clouser wrote:

(In reply to WADA from comment #27)

> To open all mail folders, at least "physical read data of whole .msf file
> for all .msf files" is required(see bug 722183 comment #5).
> What is total file size of .msf files under Mail, ImapMail, News directory?

Most are a few K.  There are a half dozen or so that are around 5M each.
There is one outlier at 57M.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/32

------------------------------------------------------------------------
On 2012-02-01T08:41:32+00:00 M-wada wrote:

"nsMsgDatabase::Open(..." log looks written just before the open request, and "error opening db 8055000?" log looks written when "nsMsgDatabase::Open(..." request failed.
Following log is seen,
> 2012-01-20 01:19:53.652328 UTC - -1223960784[b6e401c0]: nsMsgDatabase::Open(/home/clouserw/.thunderbird/5hyolzp2.default/Mail/Local Folders/archive-moz.sbd/2010.sbd/inbox.msf, FALSE, a33f0f50, TRUE)
> 2012-01-20 01:19:53.652355 UTC - -1223960784[b6e401c0]: error opening db 80550005
> 2012-01-20 01:19:53.652393 UTC - -1223960784[b6e401c0]: closing database    /home/clouserw/.thunderbird/5hyolzp2.default/Mail/Local Folders/archive-moz.sbd/2010.sbd/inbox.msf
> 2012-01-20 01:19:53.652420 UTC - -1223960784[b6e401c0]: nsMsgDatabase::Open(/home/clouserw/.thunderbird/5hyolzp2.default/Mail/Local Folders/archive-moz.sbd/2010.sbd/inbox.msf, FALSE, a33f0f50, TRUE)
> 2012-01-20 01:19:53.652430 UTC - -1223960784[b6e401c0]: error opening db 80550006
and there is no log line for 2010.sbd/inbox.msf is seen here ater in the log file.

Above log looks for me;
1. Try to open 2010.sbd/inbox.msf -> FOLDER_SUMMARY_OUT_OF_DATE
2. Close 2010.sbd/inbox.msf -> 2010.sbd/inbox.msf is erased due to out_of_date
3. Try to open 2010.sbd/inbox.msf -> FOLDER_SUMMARY_MISSING
   -> Internal Rebuild-Index starts.
4. Rebuild-Index of 2010.sbd/inbox.msf continues, and is still running
   after folder pane display, thread pane display.
5. Terminate Tb before Rebuil-Index completes.
6. Restart Tb -> Go to step 1.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/33

------------------------------------------------------------------------
On 2012-03-16T11:26:43+00:00 Vseerror wrote:

Wil, is it possible foryou to try this profile on a non-SSD local drive?
Even if it is a different computer, but same OS.  (although one wouldn't
think SSD would cause high CPU - SSD might be making things worse)

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/37

------------------------------------------------------------------------
On 2012-03-16T15:23:44+00:00 Wil Clouser wrote:

I don't have one available.

Reply at: https://bugs.launchpad.net/thunderbird/+bug/704623/comments/38


** Changed in: thunderbird
       Status: Unknown => Confirmed

** Changed in: thunderbird
   Importance: Unknown => Medium

-- 
You received this bug notification because you are a member of Mozilla
Bugs, which is subscribed to Mozilla.
https://bugs.launchpad.net/bugs/704623

Title:
  Thunderbird renders system unusable / uses 100% CPU while indexing new
  messages

To manage notifications about this bug go to:
https://bugs.launchpad.net/thunderbird/+bug/704623/+subscriptions




More information about the Ubuntu-mozillateam-bugs mailing list