757408 - Opening debugger hangs completely on large scripts

Status: RESOLVED FIXED

(DevTools :: Debugger, defect, P2)

Description

[Luke Wagner [:luke]]

STR:
 1. open http://syntensity.com/static/bb/client_5.html
 2. wait for it to load
 3. Tools -> Web Developer -> Debugger

This hangs the browser for at least the minute I waited.  It also hangs on some other large game scripts that I've tried.

Shark shows that 99% of the time is executing a regexp.  Opening it up in the debugger at one particular point, the JS stack is:

  RegExp exec
  exec (orion.js:12303)
  getNextMatch (orion.js:10865)
  parse (orion.js:10690)
  initialParse (orion.js:10584)
  onModelChanged (orion.js:10593)

On a more general note, I think we really want to support debugging these large scripts since we can expect more of them to pop up with games and, if we have the only debugger that doesn't die, we'll win the gamedevs.  Since it is easy to write code that blows up on these 1M line scripts, I think it is important to get some of these Emscripten games into automated testing: stepping, breaking, inspecting, logging, etc.

Comment 1

[Panos Astithas (he/him) [:past] (please ni?)]

From the description this sounds like the known problem with Orion's syntax highlighting engine (e.g. bug 753330), but Mihai would know for sure. However, when I tried to reproduce this on fx-team tip, I got a crash:

Assertion failure: !!script->compartment()->debugMode() == !!originalDebugMode_, at /Users/past/src/fx-team/js/src/jsanalyze.cpp:2143

Full log here:

http://past.pastebin.mozilla.org/1647946

I should note that I waited long enough for the extra downloads to finish (sound files?), before starting the debugger. If I don't wait for the downloads (start the debugger right after the throbber stops spinning), I hit your case. Launching the debugger before the throbber stops, also leads to a crash.

Mihai, in this case unconditionally using the JavaScript syntax highlighter only improves the experience slightly, so it's not just the HTML highlighter that is to blame.

Comment 2

[Luke Wagner [:luke]]

(In reply to Panos Astithas [:past] from comment #1)
Heh, I did the same thing and filed bug 757400.

Comment 3

[Panos Astithas (he/him) [:past] (please ni?)]

This is very much improved with the workaround from bug 751901.

Comment 4

[Jim Blandy :jimb]

I'm actively working on bug 757400.

Comment 5

[Victor Porof [:vporof][:vp]]

I think this is also related to bug 748512.

Comment 6

[Rob Campbell [:rc] (:robcee)]

can we get a retest on this?

Comment 7

[Luke Wagner [:luke]]

I retested on the url from comment 0.  The situation is better, but the browser hangs for a few seconds on any UI action like scrolling close the big long line that contains all code.

(Completely unrelated idea/question: are there any plans to do anything to assist debugging minified code?  It seems like inserting artificial line breaks (turning like 79 into line 79.1, 79.2, etc) would allow the developer to step through the code.)

Comment 8

[Panos Astithas (he/him) [:past] (please ni?)]

(In reply to Luke Wagner [:luke] from comment #7)
> (Completely unrelated idea/question: are there any plans to do anything to
> assist debugging minified code?  It seems like inserting artificial line
> breaks (turning like 79 into line 79.1, 79.2, etc) would allow the developer
> to step through the code.)

In bug 762761 we intend to prettify minified code and generate a source map for debugging it.

Comment 9

[Luke Wagner [:luke]]

(In reply to Panos Astithas [:past] from comment #8)
Great!

Comment 10

[Alon Zakai (:azakai)]

Here is a very large unminified program,

http://www.syntensity.com/static/night11/high_minus.html

Opening the debugger is reasonable. Resizing the debugger area is a little sluggish but not too bad.

If I add a breakpoint at 136306 for example, then stepping through is often very slow - many seconds to move forward a single line. But sometimes it is snappy. The content of the lines doesn't seem related to the speed.

Comment 11

[Rob Campbell [:rc] (:robcee)]

We could certainly benefit from some profiling on this. Thanks for the test case Alon (and for the retest, Luke).

Comment 12

[Luke Wagner [:luke]]

You're in luck, BenWa and Alex Crichton just landed JS profiling support for the SPS profiler:
  https://developer.mozilla.org/en/Performance/Profiling_with_the_Built-in_Profiler
This should show what JS is running.  (If you have any questions using it, ask BenWa on irc.)

Comment 13

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Dropping to games:p2 based on the assumption that the debugger is now fine on large scripts, and is just not fine on large *minified* scripts (e.g. single line scripts).  Is that correct?

Comment 14

[Rob Campbell [:rc] (:robcee)]

yeah, that would help performance immensely.

Note that the long lines problem comes down to gecko not dealing well with long horizontal spans of text in general. Those script files in View Source should behave just as badly.

Comment 15

[Rob Campbell [:rc] (:robcee)]

(In reply to Rob Campbell [:rc] (:robcee) from comment #14)
> yeah, that would help performance immensely.

"not concatenating the generated code into a single multi-megabyte line of JS would help performance immensely" is what I meant there.

Comment 16

[Victor Porof [:vporof][:vp]]

Yeah, this is most likely a dupe of 748512 and is not directly caused by how emscripten code looks.

Comment 17

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Is this still an issue?  There's a lot of referenced bugs here, but most unfixed (bug 751901, bug 748512).

Comment 18

[Anton Kovalyov (:anton)]

The issue was partially with our source editor and I don't remember it having any performance related updates so I'd say this is still an issue.

Comment 19

[Panos Astithas (he/him) [:past] (please ni?)]

(In reply to Vladimir Vukicevic [:vlad] [:vladv] from comment #17)
> Is this still an issue?  There's a lot of referenced bugs here, but most
> unfixed (bug 751901, bug 748512).

Note that we landed a workaround in bug 751901, but left the bug open for a more comprehensive fix. Bug 748512 depends on an Orion update that is currently set aside in favor of bug 816756.

Comment 20

[Panos Astithas (he/him) [:past] (please ni?)]

Also, it would be useful to have an updated test case since the syntensity.com URL now 404s.

Comment 21

[Alon Zakai (:azakai)]

The BananaBread demo is currently up at

https://developer.mozilla.org/en-US/demos/detail/bananabread

You can get an even larger source file in the Epic Citadel demo,

http://www.unrealengine.com/html5/

Comment 22

[Victor Porof [:vporof][:vp]]

Found a real world example where the debugger hangs forever and I had to force close Nightly. Not sure if this is related at all to source maps, but:

1. Go to http://lampwww.epfl.ch/~doeraene/presentations/scala-js-scaladays2013/#/8
2. Open debugger
3. Cry

Comment 23

[Victor Porof [:vporof][:vp]]

It seems this *is* related to source maps. While testing on fx-team tip, disabling source maps via about:config makes my debugger happy again.

With source maps enabled, however, approximately a million and one errors like these get spewed in stdout:
DBG-SERVER: JSON.parse: unexpected character:
SourceMapConsumer@resource://gre/modules/devtools/SourceMap.jsm:67
TS__fetchSourceMap/promise<@resource://gre/modules/devtools/dbg-server.jsm -> resource://gre/modules/devtools/server/actors/script.js:2685
resolve@resource://gre/modules/commonjs/sdk/core/promise.js:120
then@resource://gre/modules/commonjs/sdk/core/promise.js:45
resolve@resource://gre/modules/commonjs/sdk/core/promise.js:187
resolve@resource://gre/modules/commonjs/sdk/core/promise.js:120
then@resource://gre/modules/commonjs/sdk/core/promise.js:45
resolve@resource://gre/modules/commonjs/sdk/core/promise.js:187
fetch/streamListener.onStopRequest@resource://gre/modules/devtools/dbg-server.jsm -> resource://gre/modules/devtools/server/actors/script.js:2918

Nick, is this a known thing?

Comment 24

[Panos Astithas (he/him) [:past] (please ni?)]

I think we should file a different bug for the JSON parsing issue.

Comment 25

[Victor Porof [:vporof][:vp]]

(In reply to Panos Astithas [:past] from comment #24)
> I think we should file a different bug for the JSON parsing issue.

Yeah, totally.

Comment 26

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: v1

The reasons for the JSON.parse error are because we were getting a 404 on fetching the source map, but for whatever reason the resulting 404 html page was still being resolved in |fetch|. That isn't the real issue here though. The problem was that we are doing so much repeated work because we aren't only looking at top level scripts when we are trying to infer scripts -> sources. This is why the same message was showing up thousands and thousands of time instead of just once.

https://tbpl.mozilla.org/?tree=Try&rev=614076a69141

* s/_discoverScriptsAndSources/_discoverSources/ more accurately describes what it is doing since we don't have "scripts" packets anymore and this is only used to infer the existence of sources by the |onSources| handler.

* Only consider top level scripts in |discoverSources| since they are the only ones that can be sources

* Only create sources if the script is top level in |_addScript| and |_addScriptSync|

Comment 27

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

With this patch, the scala page goes from perma beach ball to near instant.

Comment 28

[Panos Astithas (he/him) [:past] (please ni?)]

Comment on attachment 763890 [details] [diff] [review]
v1

Review of attachment 763890 [details] [diff] [review]:
-----------------------------------------------------------------

This is a very good idea, but we need to be careful. Using this patch on G+ I get around half the sources I see in a Nightly. Not sure why, but this is scary and we need to figure it out. Also, don't forget that we take the opportunity to set stored breakpoints in onSources, so we need to make sure that we can still do that.

::: toolkit/devtools/server/actors/script.js
@@ +750,5 @@
> +
> +    let scripts = this.dbg.findScripts()
> +      // We only want to get top level scripts, because they are the only ones
> +      // that will introduce new sources.
> +      .filter(s => s.staticLevel === 0);

Filtering here means that _addScript[Sync] won't get a chance to set breakpoints on inner scripts later on.

@@ +1325,5 @@
>  
> +    // Only make sources for top level scripts.
> +    if (aScript.staticLevel === 0) {
> +      this.sources.source(aScript.url);
> +    }

Filtering here makes a ton of sense though!

@@ +2644,5 @@
>     */
>    sourcesForScript: function TS_sourcesForScript(aScript) {
> +    if (aScript.staticLevel !== 0) {
> +      return resolve([]);
> +    }

Isn't this redundant, since you've already checked before calling this method?

Comment 29

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

(In reply to Panos Astithas [:past] from comment #28)
> Comment on attachment 763890 [details] [diff] [review]
> v1
> 
> Review of attachment 763890 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> This is a very good idea, but we need to be careful. Using this patch on G+
> I get around half the sources I see in a Nightly. Not sure why, but this is
> scary and we need to figure it out.

Agreed, this doesn't make any sense whatsoever. Eval'd scripts have a higher staticLevel property, but we don't properly support them yet.

Jim, do you have any idea why we might be getting less sources if we only consider |D.Script|s with |staticLeve === 0|?

> Also, don't forget that we take the
> opportunity to set stored breakpoints in onSources, so we need to make sure
> that we can still do that.

It is completely bass ackwards that the behavior of the thread (stopping at pre-existing breakpoints) depends on a "sources" request being sent. Originally, I thought that this was handled by calling |_addScript| in |onNewScript|, but I just realized that |onNewScript| only gets passed top level scripts.

Instead of relying on the "sources" packet being sent, I think we should recurse through all the child scripts in |onNewScript| calling |_addScript| and restoring the breakpoints along the way. This way we can put off the work of restoring breakpoints until when absolutely needed and can still make |onSources| fast because it won't need to walk the whole script tree.

Or maybe we can restore breakpoints in |onEnterFrame|? Anything so that we don't have to walk the entire script tree all at once, because that is really killing us. As long as we have to do that, we won't be performant.

One other thing I noticed, is that our restoring breakpoint logic goes from the the last line of the script backwards over each line, but instead of stopping at the script's start line, keeps going to line 0. We are potentially doing a ton of unnecessary empty loops because of that.

Also, I also was wondering about the restoring breakpoints thing, before I mistakenly thought that onNewScript would handle that, and tried having only the sources filter for |staticLevel === 0| but still have the breakpoints restored on every script. It was faster than before, but nothing incredible. Perma beach ball became minute or two beach ball on the scala site.

> 
> ::: toolkit/devtools/server/actors/script.js
> @@ +750,5 @@
> > +
> > +    let scripts = this.dbg.findScripts()
> > +      // We only want to get top level scripts, because they are the only ones
> > +      // that will introduce new sources.
> > +      .filter(s => s.staticLevel === 0);
> 
> Filtering here means that _addScript[Sync] won't get a chance to set
> breakpoints on inner scripts later on.

We should restore breakpoints in |onNewScript| as mentioned above.

> 
> @@ +1325,5 @@
> >  
> > +    // Only make sources for top level scripts.
> > +    if (aScript.staticLevel === 0) {
> > +      this.sources.source(aScript.url);
> > +    }
> 
> Filtering here makes a ton of sense though!
> 
> @@ +2644,5 @@
> >     */
> >    sourcesForScript: function TS_sourcesForScript(aScript) {
> > +    if (aScript.staticLevel !== 0) {
> > +      return resolve([]);
> > +    }
> 
> Isn't this redundant, since you've already checked before calling this
> method?

Couldn't it be called elsewhere as well? I don't think we should assume that it is only called from one place, |ThreadSources| should be able to stand on its own without relying on callees. Alternatively, maybe we just need to decide that it is |ThreadSource|'s responsibility to do the filtering, or the callee's. Opinion?

Comment 30

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Hey Jim, sorry forgot to needinfo? you in the above comment. Can you reply to this:


> Jim, do you have any idea why we might be getting less sources if we only
> consider |D.Script|s with |staticLeve === 0|?

Comment 31

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: v2

https://tbpl.mozilla.org/?tree=Try&rev=e746255b4195

* Decoupled sources from breakpoint restoration, as discussed on irc

* Moved breakpoint restoration to |onAttach|, as discussed on irc

* Don't use staticLevel to filter scripts before inferring sources from them, instead just ensure that we only have one script per script url. This fixes the issue where sources weren't showing up anymore (because the top level script would be gc'd by the time we looked for it).

Comment 32

[Panos Astithas (he/him) [:past] (please ni?)]

Comment on attachment 764313 [details] [diff] [review]
v2

Review of attachment 764313 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/devtools/server/actors/script.js
@@ +217,5 @@
>          return { error: "notAttached" };
>        }
>        packet.why = { type: "attached" };
>  
> +      this._restoreBreakpoints();

It's late and I'm going to look into this more tomorrow, but I think this should be done after we spawn the nested event loop, in order to avoid delaying the pause.

@@ +1307,5 @@
>     * @param aScript Debugger.Script
>     *        The source script that will be stored.
>     * @returns true, if the script was added; false otherwise.
>     */
> +  _addScript: function TA__addScriptSync(aScript) {

Ditch the (wrong) function name.

Comment 33

[Panos Astithas (he/him) [:past] (please ni?)]

Comment on attachment 764313 [details] [diff] [review]
v2

Review of attachment 764313 [details] [diff] [review]:
-----------------------------------------------------------------

(In reply to Panos Astithas [:past] from comment #32)
> It's late and I'm going to look into this more tomorrow, but I think this
> should be done after we spawn the nested event loop, in order to avoid
> delaying the pause.

On second thought, this should be fine as it is, since SpiderMonkey isn't interruptible.

Comment 34

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

https://hg.mozilla.org/integration/fx-team/rev/feeeb2cb6a46

Comment 35

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/feeeb2cb6a46

Comment 37

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Is there any reason why this is still [leave-open]?

Comment 38

[Rob Campbell [:rc] (:robcee)]

I'll take that silence as a "no".

Anyone's guess which target milestone this was in?

Comment 39

[Panos Astithas (he/him) [:past] (please ni?)]

Looking at the release calendar, I'll say Firefox 24:

https://wiki.mozilla.org/RapidRelease/Calendar