Closed Bug 840451 Opened 11 years ago Closed 8 years ago

Browser stop to response for a while if Error console is staying open

Categories

(Toolkit Graveyard :: Error Console, defect)

Product:
Toolkit Graveyard
Component:
Error Console
Platform:
x86_64
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox20 unaffected, firefox21- affected)

Status:
RESOLVED WONTFIX
Tracking Flags:
Tracking Status
firefox20 --- unaffected
firefox21 - affected

People

(Reporter: alice0775, Unassigned)

References

Details

(Keywords: perf, regression) 

Build Identifier:
http://hg.mozilla.org/mozilla-central/rev/5835bc763be7
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20130211 Firefox/21.0 ID:20130211031055

The bug 831020 does not solve the browser hang.

Steps to Reproduce:
1. Open Error Console
2. Open Youtube HTML5 Video
   http://www.youtube.com/watch?v=BH0BNbwqNK8&webm=1&html5=1

Actual Results:
Browser stop to response 

Expected Results:
Should not hang. 

Regression window(m-c)
Good:
http://hg.mozilla.org/mozilla-central/rev/1761f4a9081c
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20130112 Firefox/21.0 ID:20130112030947
Bad:
http://hg.mozilla.org/mozilla-central/rev/d8599591d07c
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20130112 Firefox/21.0 ID:20130112122707
Pushlog:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=1761f4a9081c&tochange=d8599591d07c


Regression window(m-i)
Good:
http://hg.mozilla.org/integration/mozilla-inbound/rev/89b72b0cda19
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20130111 Firefox/21.0 ID:20130111091111
Bad:
http://hg.mozilla.org/integration/mozilla-inbound/rev/028ce4b36b4e
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20130111 Firefox/21.0 ID:20130111092811
Pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=2bfc7fb79f78&tochange=ef384134776b

Triggered by:
028ce4b36b4e	Zack Weinberg — Bug 413958: report the text of the offending line in CSS error messages. r=dbaron
Summary: Browser stop to response if Error console is staying open → Browser stop to response for a while if Error console is staying open
Suggestion:
Opt.A. Add preferences to disable Bug 413958 .
Opt.B. Add column position where the error happened instead of CSS snips and ASCII art.
cc:ing the people from bug 831020.  Please confirm for the record that you did see this bug in a browser with that patch landed; your regression window does not indicate.
I'd really prefer to see this fixed in the error console, fwiw.
(In reply to Zack Weinberg (:zwol) from comment #2)
> Please confirm for the record that you
> did see this bug in a browser with that patch landed; your regression window
> does not indicate.

The performance problem is seen since landing Bug 413958. And improved little by bug 831020.
I haven't had any issues with the error console since bug 831020 landed.
I confirm the STR with:
User agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20100101 Firefox/21.0 SeaMonkey/2.18a1
Build identifier: 20130213171745
Since this won't affect the bulk of our users (error console) but is a regression, we would take an uplift nomination here if a low risk fix is available before 21 ships.
status-firefox20: --- → unaffected
status-firefox21: --- → affected
tracking-firefox21: ? → -
I cannot reproduce the hang with 

Mozilla/5.0 (X11; Linux x86_64; rv:21.0) Gecko/20130217 Minefield/21.0a1
Built from http://hg.mozilla.org/mozilla-central/rev/5e137a87e84f

There might've been a bit of jank when the page was loading, but it went away too fast for me to pin down.

Philip, you reproduced with SeaMonkey.  Are you sure your error console has the patch from bug 831020?  If it definitely does, then could you please do a bit of poor-man's profiling for us?  Run SM under a debugger, load the page, and when it hangs, break into the debugger and pull a stack trace.  Continue, wait a moment, break again and get another stack trace.  Do that several times, and tell us what's *most often* the top five frames or so.  Much appreciated.
Flags: needinfo?(philip.chee)
(In reply to Zack Weinberg (:zwol) from comment #8)
> I cannot reproduce the hang with 
> 

You should compare the performance between now and before landing bug 413958.
> Philip, you reproduced with SeaMonkey.  Are you sure your error console has the patch
> from bug 831020?
Oh good point I'll test again.
Flags: needinfo?(philip.chee)
> You should compare the performance between now and before landing bug 413958.
OK confirming this is fixed. Sorry for the false alarm. WORKSFORME
(In reply to Philip Chee from comment #11)
> > You should compare the performance between now and before landing bug 413958.
> OK confirming this is fixed. Sorry for the false alarm. WORKSFORME

No, the performance is noticeably down now in comparison before landing bug 413958.

Spinning icon stops for a while when loading the page.
In that time, menu does not responses.Switching tab does not responses... All UI  stops response.
This problems never happened  before landing bug 413958.
It's possible that Philip and I are just testing on computers that are too fast or have too much RAM to truly show the problem.  about:jank crashes my trunk builds if I try to actually look at the profiles, but I can see sampling events in stderr spew, and with Alice0775's test recipe, there's a burst of long pauses right when I open the error console:

++DOMWINDOW == 19 (0x7f0baab368b8) [serial = 33] [outer = (nil)]
MOZ_EVENT_TRACE sample 1361197698431 1006
MOZ_EVENT_TRACE sample 1361197699090 648
++DOMWINDOW == 20 (0x7f0baf0248b8) [serial = 34] [outer = 0x7f0baab368b8]
MOZ_EVENT_TRACE sample 1361197699466 365
MOZ_EVENT_TRACE sample 1361197699690 212

I think the last number on each MOZ_EVENT_TRACE line is milliseconds since the last time we spun the event loop. A 1006ms pause is obviously unacceptable.

As a quick-and-dirty test, I #if-ed out passing the error line text to nsIScriptError::InitWithWIndowID in layout/style/ErrorReporter.cpp -- this is enough to suppress the visible effect of bug 413958.  This reduces the jank but doesn't make it go away:

++DOMWINDOW == 19 (0x7f44b21f3cb8) [serial = 23] [outer = 0x7f44b1fefcb8]
MOZ_EVENT_TRACE sample 1361198087613 25
++DOCSHELL 0x7f44b2dbc000 == 10 [id = 10]
++DOMWINDOW == 20 (0x7f44b30e48b8) [serial = 24] [outer = (nil)]
WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file /home/zack/src/mozilla/S-mc/docshell/base/nsDocShell.cpp, line 8329
MOZ_EVENT_TRACE sample 1361198088025 401
MOZ_EVENT_TRACE sample 1361198088552 527
MOZ_EVENT_TRACE sample 1361198088641 77
++DOMWINDOW == 21 (0x7f44b10e58b8) [serial = 25] [outer = 0x7f44b30e48b8]
MOZ_EVENT_TRACE sample 1361198089029 377

A 401ms pause is better than a 1006ms pause but it's still not good enough.

I'm thinking the real problem here is that consoleBindings.xml::appendInitialItems loads up everything in one big burp; whether or not there are long error strings to be rendered, if there are a *lot* of messages, that can be a long time without allowing the event loop to spin.  I don't know XUL; how hard would it be to make that an incremental async operation?
Flags: needinfo?(jAwS)
> I don't know XUL; how hard would it be to make that an incremental async operation?
I think it is possible to use a generator/iterator to yield every /n/ appends.
(In reply to Philip Chee from comment #14)
> > I don't know XUL; how hard would it be to make that an incremental async operation?
> I think it is possible to use a generator/iterator to yield every /n/
> appends.

Yes, this approach sounds good.
Flags: needinfo?(jAwS)
I don't really see how to use generators in this context.  I tried replacing the loop at the end of appendInitialItems with

          // Populate with messages after latest "clear"
          // This can be slow; yield to the event loop after every append.
          var self = this;
          var appendNext = function appendNext() {
            if (++i >= messages.length)
              return;
            self.appendItem(messages[i]);
            window.setTimeout(appendNext, 0);
          }
          appendNext();

This works, and reduces the jank by a great deal; however, with CSS error line text enabled, there is still a 375ms pause immediately upon opening the console window.

++DOMWINDOW == 20 (0x7fcd559774b8) [serial = 24] [outer = (nil)]
WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file /home/zack/src/mozilla/S-mc/docshell/base/nsDocShell.cpp, line 8329
MOZ_EVENT_TRACE sample 1361315646925 375
MOZ_EVENT_TRACE sample 1361315646960 24
++DOMWINDOW == 21 (0x7fcd562cc4b8) [serial = 25] [outer = 0x7fcd559774b8]
MOZ_EVENT_TRACE sample 1361315647122 56
MOZ_EVENT_TRACE sample 1361315648377 20
MOZ_EVENT_TRACE sample 1361315649675 22
MOZ_EVENT_TRACE sample 1361315650083 21

Without a functional profiler I cannot investigate further, but I'm wondering if what we're seeing here is the overhead of copying a whole bunch of large nsStrings into JS string space in Services.console.getMessageArray.  If so we might need to do the windowing in the CSS parser, or in nsScriptError.
See Also: → 877773
We are having the same issue with the Web and Browser Consoles, see bug 877773. There I found a way to fix the bug - I don't read the |message| property of the nsIScriptErrors. Having looked into the Error Console implementation I believe that the same fix would work: don't read the |message| property for nsIScriptErrors - it's not used by the error console other than determining when to clear the output. You can check |message| only for nsIConsoleMessages.
The Error Console has been removed in favor of the Browser Console (see Bug 1278368), and the component is going to be removed.  If this bug is also relevant in the Browser Console, please reopen and move this into Firefox -> Developer Tools: Console.
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → WONTFIX
I am mass-reopening and re-componenting every single one of the Toolkit:Error Console bugs that appear to have been closed without anyone even *glancing* at whether they were relevant to the Browser Console.

If you want to close a whole bunch of old bugs -- FOR ANY REASON -- it is YOUR RESPONSIBILITY to check EVERY SINGLE ONE OF THEM and make sure they are no longer valid.  Do not push that work onto the bug reporters.

(It's okay to close bugs that haven't been touched in years when they don't have enough information for you to figure out whether the problem is still relevant to the current software - the reporter probably isn't coming back to clarify.  But that is the ONLY situation where it is okay.)

(I'm going to have to do this in two steps because of the way the "change several bugs at once" form works.  Apologies for the extra bugspam.)
Status: RESOLVED → REOPENED
Component: Error Console → Developer Tools: Console
Product: Toolkit → Firefox
Resolution: WONTFIX → ---
Version: 21 Branch → Trunk
Closing as per Comment 17
Status: REOPENED → RESOLVED
Closed: 8 years ago → 8 years ago
Component: Developer Tools: Console → Error Console
Product: Firefox → Toolkit
Resolution: --- → WONTFIX
Product: Toolkit → Toolkit Graveyard
You need to log in before you can comment on or make changes to this bug.