763267 - Startup TB since upgrade to version 13 is slow, with "Unresponsive script. A script on this page may be busy, or it may have stopped responding. ... iteratorUtils.jsm:128"

Status: RESOLVED WORKSFORME

(Thunderbird :: General, defect)

Description

[Andrei Boros]

User Agent: Mozilla/5.0 (Windows NT 5.1; rv:13.0) Gecko/20100101 Firefox/13.0
Build ID: 20120601045813

Steps to reproduce:

Thunderbird, configured with 7 accounts, one POP3, the rest IMAP, each has 10 to 30 folders. system is xp32, P4, 3GHz. All worked fine. 
Then I upgraded to TB13.

The same happens on another system, Core 2 duo @ 2GHz with more RAM and one account less. 


Actual results:

Each time I start TB, I get the "unresponsive script" warning with IteratorUtils.jsm:128.
TB startup is slow, takes a long time and CPU usage goes pretty high. 
After I press "continue", finally, TB finishes the startup sequence. Also, while this dialog is shown, TB does not yet have a button on the taskbar. 

While the dialog was shown, I left it like this for about 10 minutes, searching bugzilla and writing this report. During this time TB also played the audio file warning of new mail received. 

I have found 2 similar bugs, but they refer to somewhat different circumstances and the point in IteratorUtils.jsm is different. #712371 and #587417. 

This warning happens every time I start TB since I upgraded to version 13. 



Expected results:

IteratorUtils.jsm apparently has some performance issues since I upgraded from TB12 to T13. 
At startup TB shouldn't get stuck like this.

Comment 1

[Hashem Masoud]

(In reply to Andrei Boros from comment #0)
Disable all add-ons then start Thunderbird just to check.

Comment 2

[Wayne Mery (:wsmwk)]

And if safe mode doesn't help please work through https://wiki.mozilla.org/Thunderbird:Testing:Memory_Usage_Problems

In either case please post you results

Comment 3

[Andrei Boros]

Installed add-ons : attachment extractor, display mail user agent, enigmail. 

Any combination of enabled or disabled add-ons has no influence. 

However, repeated restarts on an idle system show that this issue does not happen when TB and it's data is already cached by the OS and very little actual disk is needed.

Comment 4

[Andrei Boros]

global indexer is disabled (I don't use it ever since was implemented)
Memory usage according to task manager is about 110MB. (system has 2GB)
No calendar. No antivirus. No OS indexing service. 
About 5 folsers between 800MB and 1.3Gb. The rest smaller and much smaller. 
Mailcheck at 15min. (not all accounts check for mail)
A few IMAP folders set to check for new mail (on a yahoo account)
updater.exe not running. 
Profile and mail on local hdd. 

Below is what appears in the error console with 
javascript.options.mem.log = true
------------------------------------------------------
GC(T+0.0) TotalTime: 23.0ms, Type: global, MMU(20ms): 0%, MMU(50ms): 53%, Reason: SET_NEW_DOCUMENT, NonIncrementalReason: GC mode, +chunks: 0, -chunks: 0
mark: 12.2, mark-roots: 1.7, mark-other: 1.5, sweep: 9.2, sweep-obj: 2.5, sweep-string: 0.0, sweep-script: 0.1, sweep-shape: 1.5, discard-code: 0.6, discard-analysis: 1.0, xpconnect: 0.9, deallocate: 0.1

GC(T+32.8) TotalTime: 84.4ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: MAYBEGC, NonIncrementalReason: GC mode, +chunks: 0, -chunks: 0
mark: 20.4, mark-roots: 2.3, mark-other: 4.0, sweep: 62.8, sweep-obj: 2.0, sweep-string: 0.1, sweep-script: 0.4, sweep-shape: 2.5, discard-code: 0.9, discard-analysis: 1.0, xpconnect: 1.9, deallocate: 0.1

CC(T+36.8) duration: 0ms, suspected: 2118, visited: 4744 RCed and 1294 GCed, collected: 304 RCed and 0 GCed (304 waiting for GC)
ForgetSkippable 5 times before CC, min: 0 ms, max: 16 ms, avg: 3 ms, total: 16 ms, removed: 6059

GC(T+36.9) TotalTime: 27.0ms, Type: global, MMU(20ms): 0%, MMU(50ms): 45%, Reason: SET_NEW_DOCUMENT, NonIncrementalReason: GC mode, +chunks: 0, -chunks: 0
mark: 19.4, mark-roots: 4.0, mark-other: 2.4, sweep: 7.0, sweep-obj: 0.5, sweep-string: 0.0, sweep-script: 0.1, sweep-shape: 0.8, discard-code: 0.7, discard-analysis: 0.8, xpconnect: 1.1, deallocate: 0.1

CC(T+43.0) duration: 0ms, suspected: 150, visited: 842 RCed and 1637 GCed, collected: 54 RCed and 342 GCed (396 waiting for GC)
ForgetSkippable 2 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 78

GC(T+47.1) TotalTime: 27.6ms, Type: global, MMU(20ms): 0%, MMU(50ms): 44%, Reason: CC_WAITING, NonIncrementalReason: GC mode, +chunks: 0, -chunks: 0
mark: 19.3, mark-roots: 2.7, mark-other: 2.7, sweep: 7.4, sweep-obj: 0.6, sweep-string: 0.0, sweep-script: 0.1, sweep-shape: 0.9, discard-code: 0.6, discard-analysis: 0.8, xpconnect: 1.1, deallocate: 0.1

CC(T+53.1) duration: 0ms, suspected: 2, visited: 628 RCed and 1296 GCed, collected: 0 RCed and 0 GCed (0 waiting for GC)
ForgetSkippable 1 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 1

GC(T+148.5) TotalTime: 37.1ms, Type: global, MMU(20ms): 0%, MMU(50ms): 25%, Reason: PAGE_HIDE, NonIncrementalReason: GC mode, +chunks: 0, -chunks: 0
mark: 20.6, mark-roots: 3.2, mark-other: 2.7, sweep: 14.7, sweep-obj: 2.6, sweep-string: 3.6, sweep-script: 0.1, sweep-shape: 0.9, discard-code: 1.0, discard-analysis: 0.8, xpconnect: 1.7, deallocate: 0.1

CC(T+150.6) duration: 0ms, suspected: 214, visited: 1314 RCed and 2414 GCed, collected: 212 RCed and 969 GCed (1181 waiting for GC)
ForgetSkippable 3 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 751

GC(T+154.6) TotalTime: 48.5ms, Type: global, MMU(20ms): 0%, MMU(50ms): 2%, Reason: CC_WAITING, NonIncrementalReason: GC mode, +chunks: 0, -chunks: 0
mark: 19.4, mark-roots: 2.5, mark-other: 2.3, sweep: 8.4, sweep-obj: 0.8, sweep-string: 0.2, sweep-script: 0.1, sweep-shape: 0.8, discard-code: 0.7, discard-analysis: 0.8, xpconnect: 1.5, deallocate: 0.1


CC(T+160.7) duration: 0ms, suspected: 437, visited: 1479 RCed and 1443 GCed, collected: 43 RCed and 0 GCed (43 waiting for GC)
ForgetSkippable 3 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 724

GC(T+164.1) TotalTime: 30.2ms, Type: global, MMU(20ms): 0%, MMU(50ms): 39%, Reason: SET_NEW_DOCUMENT, NonIncrementalReason: GC mode, +chunks: 0, -chunks: 0
mark: 20.5, mark-roots: 2.6, mark-other: 3.0, sweep: 9.1, sweep-obj: 0.9, sweep-string: 0.4, sweep-script: 0.1, sweep-shape: 0.9, discard-code: 0.8, discard-analysis: 0.8, xpconnect: 1.5, deallocate: 0.1

CC(T+170.2) duration: 0ms, suspected: 60, visited: 1011 RCed and 1475 GCed, collected: 26 RCed and 3 GCed (29 waiting for GC)
ForgetSkippable 2 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 183

GC(T+214.9) TotalTime: 35.5ms, Type: global, MMU(20ms): 0%, MMU(50ms): 29%, Reason: MAYBEGC, NonIncrementalReason: GC mode, +chunks: 0, -chunks: 0
mark: 20.9, mark-roots: 2.9, mark-other: 3.3, sweep: 13.2, sweep-obj: 0.9, sweep-string: 4.5, sweep-script: 0.1, sweep-shape: 0.8, discard-code: 0.8, discard-analysis: 0.8, xpconnect: 1.6, deallocate: 0.1

CC(T+220.9) duration: 0ms, suspected: 55, visited: 1113 RCed and 1492 GCed, collected: 0 RCed and 0 GCed (0 waiting for GC)
ForgetSkippable 10 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 712

Comment 5

[Bernie]

running tb 16.0.1. win7 home prem. 64bit and having the exact same indications as andrei boros reports to originate this thread except that the code after "...jsm:" is 123 or 96. stopping the script, ending tb, and restarting tb gets rid of the script error. this is no joke to have this bug still existing in v16. if you google search "iteratorUtils.jsm" you will find dozens if not hundreds of people complaining about the same thing. and each person complaining probably represents a few dozen who don't know how to complain and just grin and bear it. SHAME.
let me quote andrei: "At startup TB shouldn't get stuck like this." NO KIDDING.

Comment 6

[Andrei Boros]

Probably related, perhaps I should open a new bug for it : 
Closing TB quite often yields "unresponsive script" errors as well. System has no load but TB and shows this : 
Script: resource:///modules/dbViewWrapper.js:249

Actually this is the second warning I managed to catch for this report, the first in another script I already passed with "continue". This is the same installation as the one I tested the initial issue.

It is a processing problem somewhere, because a similar installation on another system performs slightly better, as in it gives these warnings less often.

Comment 7

[Andrei Boros]

Another warning at TB close is issued by 
Script: chrome://calendar/content/calendar-invitations-manager.js:35

I have lightning extension installed, but I haven't used it yet. This extension just exists, it has NO DATA.

Comment 8

[Wayne Mery (:wsmwk)]

Andrei, Bernie, Do you still see this problem? And if you do 
1. are you starting TB while windows startup is still in progress, or other applications?
2. what is size of your largest Inbox?
3. please try windows safe mode and post results
4. please try TB21.0b1 from http://www.mozilla.org/en-US/thunderbird/channel/  and post your results

Bernie, did you go through https://wiki.mozilla.org/Thunderbird:Testing:Memory_Usage_Problems ?

Andrei, can you elaborate on "this issue does not happen when ... very little actual disk is needed."?  What do you mean by this?  Put another way, what do you think causes high disk needs?


Footnote, the problem is not in dbViewWrapper.js nor iteratorUtils.jsm. These scripts are the *victim*. The message indication is simply that the script is running longer than might be expected. The cause is typically elsewhere.

Often the cause is *external* factors. For example:
AV
disk contention
cpu contention

Of course factors internal to TB can cause this, on their own or in combination with external factors. Some examples
large folder like Inbox
addon
high volume of new messages, with or without combination of having many filters

Comment 9

[Andrei Boros]

@Wayne: 
Before I answer with those tests (which I will try next week), let me explain my experience a bit better. 

I have in TB configured : 
1 POP3 account, local storage, server is under my control
5 IMAP accounts, 3 on one server, 2 on another, both under my control
2 IMAP accounts, yahoo and gmail. 

INBOX contains between 100 and 1500 messages, size is between 30 and 300MB. 
I have only about 10 filters for the POP3 account, none for the rest (they are done server side)

I have been using TB since version 1.x with these accounts. Perhaps I added one since. The volume of emails is pretty much the same over time. Usually 10-50 new mails overall, per day. 

My experience is a comparison on the same system, (CPU, RAM, disk), same accounts, same/similar mail traffic, and progressive upgrades to TB. I keep it updated pretty soon as a new version appears. 

No AV software is running. 
There are several addons, like attachment extractor, enigmail, smart fodlers, display mail user agent. smart folders is a recent (<2 months) addition. 

The problem at startup, with those warnings of unresponsive scripts (ie consequence) appears mostly when, after system startup (and system stabilizes), I start TB and FF almost simultaneously. (one or two other programs don't count because they start within a second or two at most). 

The problem did not occur if I started TB standalone. 
The problem did occur if I started TB while there was some other CPU load, so I equate this with running TB on a slower computer. 

Problem occured before full UI got displayed, and before any new mail got to be checked. 

The problem started with upgrade to TB 13 and was quite a shock. Overall, TB responded much slower. This also included things like right click on a message and when mouse got to the "Move to folder" it takes ages for the submenu to expand.

I have a nearly identical setup on a different computer, as in same accounts, except for the POP3 one. That computer is faster and has more RAM. I noticed the problem once or twice on it, but much rarely. TB is also slower to repond, but a bit faster then on my regular system. 
The slugishness is proportional to the system speed. 

I've set TB to continue, and not warn me about unresponsive scripts, so I can't say for certain about more recent versions, though the slugishness is the same. 

======================================
I will try the instructions indicated and get back to you.

Comment 10

[Wayne Mery (:wsmwk)]

(In reply to Andrei Boros from comment #9)
> The problem at startup, with those warnings of unresponsive scripts (ie
> consequence) appears mostly when, after system startup (and system
> stabilizes), I start TB and FF almost simultaneously. (one or two other
> programs don't count because they start within a second or two at most). 
> 
> The problem did not occur if I started TB standalone. 
> The problem did occur if I started TB while there was some other CPU load,
> so I equate this with running TB on a slower computer. 

This explains the situation clearly.  Thunderbird startup is IO intensive. Against other activity like firefox start Thunderbird startup will be dramatically affected. Not a slouch in CPU usage either - in my 10 second startup (not including login) it used ~6 cpu seconds.

I look forward to your tests.

p.s. to regain the timeout prompt reset dom.max_script_run_time to default in about:config

Comment 11

[be1310]

(In reply to Bernie from comment #5)
> running tb 16.0.1. win7 home prem. 64bit and having the exact same
> indications as andrei boros reports to originate this thread except that the
> code after "...jsm:" is 123 or 96. stopping the script, ending tb, and
> restarting tb gets rid of the script error. this is no joke to have this bug
> still existing in v16. if you google search "iteratorUtils.jsm" you will
> find dozens if not hundreds of people complaining about the same thing. and
> each person complaining probably represents a few dozen who don't know how
> to complain and just grin and bear it. SHAME.
> let me quote andrei: "At startup TB shouldn't get stuck like this." NO
> KIDDING.

now running tb 17.0.5 and the problem has almost entirely disappeared! what a relief! it has only happened once or twice in the last two months. i'm happy enough... but the traces of the problem remain. thanks for the hard work.

Comment 12

[Wayne Mery (:wsmwk)]

(In reply to Andrei Boros from comment #9)
> @Wayne: 
> Before I answer with those tests (which I will try next week), let me
> explain my experience a bit better. 
>...
> The problem started with upgrade to TB 13 and was quite a shock. Overall, TB
> responded much slower. This also included things like right click on a
> message and when mouse got to the "Move to folder" it takes ages for the
> submenu to expand.
>...
> ======================================
> I will try the instructions indicated and get back to you.

Andrei

3. please try windows safe mode and post results
4. please try TB21.0b1 from http://www.mozilla.org/en-US/thunderbird/channel/  and post your results
5. is 17.0.5 better (per be1310)?  Or 17.0.6?

Comment 13

[Andrei Boros]

will be back with test results between aug 1st and 10th. thank you.

Comment 14

[be1310]

i am running tb 17.0.7. i still have that script problem occasionally, so
just a few days ago i had unresponsive script  ... modules/iteratorUtils.jsm123.

after hitting "stop script" the "folder pane view switcher" add-on is
missing, so i closed tb. btw, in case this helps, i also use "advanced
unread folder"...

after i restart tb, it loads properly and all is well.

it does not make any sense to run tb in safe mode to reproduce these script errors because these errors do not always occur. for example, today tb came up rapidly with no errors.

Comment 15

[Wayne Mery (:wsmwk)]

(In reply to Wayne Mery (:wsmwk) from comment #12)
> 
> 3. please try windows safe mode and post results
> 4. please try TB21.0b1 from
> http://www.mozilla.org/en-US/thunderbird/channel/  and post your results
> 5. is 17.0.5 better (per be1310)?  Or 17.0.6?

Or skip the above and use version 24

Comment 16

[Andrei Boros]

I'm using 24.1.1 at this time. 
I do not experience slow startups at this time. The issue might have been solved indirectly. 
IMO I can consider this as SOLVED->WORKSFORME. 

Thank you. 

Sorry for not performing steps 3,4,5, I was unable to *properly* replicate my environment for testing purposes.