Closed Bug 1548379 Opened 5 years ago Closed 5 years ago

Support more eager script compilation by removing requirement that element be available before compilation

Categories

(Core :: JavaScript Engine, enhancement, P1)

enhancement

Tracking

()

RESOLVED DUPLICATE of bug 1501608
Tracking Status
firefox68 --- affected

People

(Reporter: mgaudet, Unassigned)

References

Details

Attachments

(1 obsolete file)

Right now the only way that the element and elementAttributes, used by the debugger, can be set, is on the compilation options before a compile begins.

There's no reason this needs to be that way, and in fact, for Modules, it is already not the case.

This bug extends the modules case to support scripts in general.

In order to support more eager compilation of scripts, this patch decouples
script compilation from the settting of elements and element attributes.

In support of this change, the shell functions offThreadCompileScript and
runOffThreadScript are tweaked: Previously elements would be associated at the
call to offThreadCompileScript, now they're associated at runOffThreadScript.

Attachment #9062016 - Attachment description: Bug 1548379 - Decouple elements from script compilation → Bug 1548379 - Decouple elements from script compilation r?baku!,tcampbell!
Priority: -- → P1
Attachment #9062016 - Attachment description: Bug 1548379 - Decouple elements from script compilation r?baku!,tcampbell! → Bug 1548379 - Decouple elements from script compilation r=tcampbell

Status update: Still battling a test case failure.

Originally my take on this was that the test is broken. I am not so sure now. Here's the story.

This test case https://searchfox.org/mozilla-central/source/devtools/client/debugger/test/mochitest/browser_dbg-navigation.js#31,40 fails the assertion on line 40. There's also a time out.

Irksomely, these failures only occur if you run ./mach mochitest devtools/client/debugger/test/mochitest/ rather than the specific failing file browser_dbg-navigation.js

After spending some time trying to figure out these APIs, I am confused why the assertion on line 40 would be valid. The reason is that the call to navigate on line 31 only asks for simple.js to be available. So it seems to me that 5 sources being available after that point would be luck of the draw (otherwise, why would you have to ask for a specific set of sources).

Instrumenting the code, I found that long.js was always the missing source where the assertion was failing. However, if I add long.js to the navigate call on line 31, I still get a timeout.

Now, Investigating the time out, I get more confused. To figure out where we time out, I have this debug patch applied:

diff --git a/devtools/client/debugger/test/mochitest/browser_dbg-navigation.js b/devtools/client/debugger/test/mochitest/browser_dbg-navigation.js
--- a/devtools/client/debugger/test/mochitest/browser_dbg-navigation.js
+++ b/devtools/client/debugger/test/mochitest/browser_dbg-navigation.js
@@ -1,16 +1,20 @@
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at <http://mozilla.org/MPL/2.0/>. */
 
 function countSources(dbg) {
   return dbg.selectors.getSourceCount();
 }
 
+function getSourceList(dbg) {
+  return dbg.selectors.getSourceList().map((x) => x.relativeUrl);
+}
+
 const sources = [
   "simple1.js",
   "simple2.js",
   "simple3.js",
   "long.js",
   "scripts.html"
 ];
 
@@ -20,36 +24,49 @@ const sources = [
  */
 add_task(async function() {
   const dbg = await initDebugger("doc-script-switching.html");
   const {
     selectors: { getSelectedSource, getIsPaused, getCurrentThread },
     getState
   } = dbg;
 
+  info("AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA");
+
   invokeInTab("firstCall");
   await waitForPaused(dbg);
 
-  await navigate(dbg, "doc-scripts.html", "simple1.js");
+  info("BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB");
+  await navigate(dbg, "doc-scripts.html", "simple1.js", "long.js");
+  info("CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC");
   await selectSource(dbg, "simple1");
+  info("DDDDDDDDDDDDDDDDDDDDDDDDDDDDDD");
   await addBreakpoint(dbg, "simple1.js", 4);
+  info("EEEEEEEEEEEEEEEEEEEEEEEEEEEEEE");
   invokeInTab("main");
+  info("FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF");
   await waitForPaused(dbg);
+  info("GGGGGGGGGGGGGGGGGGGGGGGGGGGGGG");
   await waitForLoadedSource(dbg, "simple1");
+  info("HHHHHHHHHHHHHHHHHHHHHHHHHHHHHH");
   toggleScopes(dbg);
+  info("IIIIIIIIIIIIIIIIIIIIIIIIIIIIII");
 
   assertPausedLocation(dbg);
-  is(countSources(dbg), 5, "5 sources are loaded.");
+  info("Source list is" + getSourceList(dbg));
+  is(countSources(dbg), 5, "5 sources are loaded (doc-scripts.html).");
 
   await navigate(dbg, "doc-scripts.html", ...sources);
-  is(countSources(dbg), 5, "5 sources are loaded.");
+  info("Source list is" + getSourceList(dbg));
+  is(countSources(dbg), 5, "5 sources are loaded (waited for sources)");
   ok(!getIsPaused(getCurrentThread()), "Is not paused");
 
   await navigate(dbg, "doc-scripts.html", ...sources);
-  is(countSources(dbg), 5, "5 sources are loaded.");
+  info("Source list is" + getSourceList(dbg));
+  is(countSources(dbg), 5, "5 sources are loaded. (waited for sources after pause)");
 
   // Test that the current select source persists across reloads
   await selectSource(dbg, "long.js");
   await reload(dbg, "long.js");
   await waitForSelectedSource(dbg, "long.js");
 
   ok(getSelectedSource().url.includes("long.js"), "Selected source is long.js");
 });

This allows me to figure out where the hang happens by looking at the info logs.

What I am seeing is is we never get to info("CCC..."). In the navigate call it hangs trying to load the sources.

Here's the log output from that point forward to the test failure:

 3:09.21 INFO BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
 3:09.21 INFO Navigating to doc-scripts.html
 3:09.24 GECKO(119312) [ACTION] RESUME  - {"type":"RESUME","thread":"server1.conn46.child1/context18","wasStepping":false}
 3:09.28 GECKO(119312) [ACTION] EVALUATE_EXPRESSIONS  - {"type":"EVALUATE_EXPRESSIONS","cx":{"navigateCounter":0,"thread":"server1.conn46.child1/context18","isPaused":false,"pauseCounter":2},"inputs":[],"results":[]}
 3:09.30 GECKO(119312) [ACTION] NAVIGATE  - {"type":"NAVIGATE","mainThread":{"url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-scripts.html","actor":"server1.conn46.child1/context18","type":-1,"name":"Main Thread"}}
 3:09.33 GECKO(119312) [ACTION] SET_VIEWPORT  - {"type":"SET_VIEWPORT","viewport":{"start":{"line":0,"column":0},"end":{"line":1,"column":105}}}
 3:09.35 INFO Waiting on sources: simple1.js, long.js
 3:09.35 INFO Waiting for state change: source simple1.js exists
 3:09.35 INFO Waiting for state change: source long.js exists
 3:09.43 GECKO(119312) [ACTION] ADD_SOURCES  - {"type":"ADD_SOURCES","cx":{"navigateCounter":1},"sources":[{"id":"sourceURL-http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple1.js","url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple1.js","relativeUrl":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple1.js","isPrettyPrinted":false,"sourceMapURL":null,"introductionUrl":null,"introductionType":"scriptElement","isBlackBoxed":false,"isWasm":false,"isExtension":false}]}
 3:09.44 INFO Finished waiting for state change: source simple1.js exists
 3:09.44 GECKO(119312) [ACTION] INSERT_SOURCE_ACTORS  - {"type":"INSERT_SOURCE_ACTORS","items":[{"id":"server1.conn46.child1/source34","actor":"server1.conn46.child1/source34","thread":"server1.conn46.child1/context18","source":"sourceURL-http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple1.js","isBlackBoxed":false,"sourceMapURL":null,"url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple1.js","introductionUrl":null,"introductionType":"scriptElement"}]}
 3:09.46 GECKO(119312) [ACTION] SET_EXPANDED_STATE  - {"type":"SET_EXPANDED_STATE","expanded":{}}
 3:09.46 GECKO(119312) [ACTION] SET_EXPANDED_STATE  - {"type":"SET_EXPANDED_STATE","expanded":{}}
 3:09.53 GECKO(119312) [ACTION] ADD_SOURCES  - {"type":"ADD_SOURCES","cx":{"navigateCounter":1},"sources":[{"id":"sourceURL-http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple2.js","url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple2.js","relativeUrl":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple2.js","isPrettyPrinted":false,"sourceMapURL":null,"introductionUrl":null,"introductionType":"scriptElement","isBlackBoxed":false,"isWasm":false,"isExtension":false},{"id":"sourceURL-http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple3.js","url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple3.js","relativeUrl":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple3.js","isPrettyPrinted":false,"sourceMapURL":null,"introductionUrl":null,"introductionType":"scriptElement","isBlackBoxed":false,"isWasm":false,"isExtension":false},{"id":"sourceURL-http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-scripts.html","url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-scripts.html","relativeUrl":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-scripts.html","isPrettyPrinted":false,"sourceMapURL":null,"introductionUrl":null,"introductionType":"scriptElement","isBlackBoxed":false,"isWasm":false,"isExtension":false}]}
 3:09.54 GECKO(119312) [ACTION] SET_EXPANDED_STATE  - {"type":"SET_EXPANDED_STATE","expanded":{}}
 3:09.55 GECKO(119312) [ACTION] INSERT_SOURCE_ACTORS  - {"type":"INSERT_SOURCE_ACTORS","items":[{"id":"server1.conn46.child1/source35","actor":"server1.conn46.child1/source35","thread":"server1.conn46.child1/context18","source":"sourceURL-http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple2.js","isBlackBoxed":false,"sourceMapURL":null,"url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple2.js","introductionUrl":null,"introductionType":"scriptElement"},{"id":"server1.conn46.child1/source36","actor":"server1.conn46.child1/source36","thread":"server1.conn46.child1/context18","source":"sourceURL-http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple3.js","isBlackBoxed":false,"sourceMapURL":null,"url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/simple3.js","introductionUrl":null,"introductionType":"scriptElement"},{"id":"server1.conn46.child1/source37","actor":"server1.conn46.child1/source37","thread":"server1.conn46.child1/context18","source":"sourceURL-http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-scripts.html","isBlackBoxed":false,"sourceMapURL":null,"url":"http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-scripts.html","introductionUrl":null,"introductionType":"scriptElement"}]}
 3:09.56 GECKO(119312) [ACTION] SET_EXPANDED_STATE  - {"type":"SET_EXPANDED_STATE","expanded":{}}
 3:52.78 INFO Not taking screenshot here: see the one that was previously logged
 3:52.93 GECKO(119312) console.warn: "Error while detaching the thread front: 'detach' request packet to 'server1.conn46.child1/context18' can't be sent as the connection is closed."
 3:53.08 INFO Removing tab.
 3:53.08 INFO Waiting for event: 'TabClose' on [object XULElement].
 3:53.09 INFO Got event: 'TabClose' on [object XULElement].
 3:53.10 INFO Tab removed and finished closing
 3:53.13 GECKO(119312) MEMORY STAT | vsize 2885MB | residentFast 355MB | heapAllocated 146MB
 3:53.13 TEST_END: Test OK. Subtests passed 0/1. Unexpected 1
FAIL Test timed out - 

If the sources loaded, we should have seen a log message Finished waiting for state change: source simple1.js exists for each of simple1.js and long.js. We see the message for the former at 3:09.44; but we never see it for long.js and so we timeout.

I don't understand why though.

Next step is to try this debugging patch without my patch, making sure it is my patch triggering this, and not unfortunately something else.

Ok; as of this morning I have confirmation that the issue is in my patch, as I am freely able to select which sources to wait for in the first navigate call with no restriction (ok, I mean, I tried long.js and ...sources).

Next up... why... and why does this only fail when the whole suite is being run, not when the individual test is being run.

Ok, so I think I have a bit of understanding of what's going wrong, and I think it reflects a fundamental design issue with this patch's approach.

Right now, the patch removes the ability to pass the element and element attributes along the CompileOptions, and instead sets the element and element attributes when the compilation of the script is done. In order to avoid the debugger inspecting the script before the element is set, we hide the script from the debugger, the reveal it to the debugger once the script compilation is done.

The only place we are sure the script compilation is done is during ExecuteScript, via the nsJSUtils::ExecutionContext.

The problem I think we're running into is asynchronous script compilation. (My evidence for this is a little circumstantial; if I choose not to hide the script in AttemptAsyncScriptCompile, the test case seems to pass reliably. As well, the fact that this only fails in a longer run suggests there's some sort of heuristic firing here. )

The issue is what happens if the debugger is waiting for a script that has yet to be processed; we end up in a deadlock of sorts. I don't event think this so much has to do with the element! I don't think we ever end up setting the element for the deadlocking script, as if I don't hide the script from the debugger, the test case passes and it doesn't trip the assertion in nsJSUtils::SetScriptSourceElement that checks the ScriptIsHiddenFromDebugger

One option here is to relax one aspect of the contract the patch applied: We no longer hide scripts from the debugger for async scripts. What I don't seem to understand is -why- async scripts seem to -never- get their elements set. Though, I guess I haven't done a full try run, so perhaps I need to do that first.

I’m wondeirng what kind of requirements the act of script loading + the debugger imposes.

Assume you have a debugger test with

await navigate(“test.html”, “source1.js”) 

It appears that today, when navigate happens, the debugger seems to look for the list of sources before async scripts have had a chance to execute. This means that the patch attached to this bug is broken because it changes the behaviour to attach elements to scripts at execution time rather than before script compilation (via the CompileOptions) .

jimb: Is this a fundamental aspect of the ordering of page load under the debugger? Or should the debugger be waiting till everything on the page is done executing before interrogation?

Flags: needinfo?(jimb)

(in hindsight... this does seem pretty fundamental to debugging.... which bodes ill for this patch)

Even for an off-thread parse, we complete the operation on main thread. It seems like it should be quite possible in the scriptloader to set the element when both the off-thread has finished and when the dom element exists. I don't even think any scaring synchronization is needed.

Hypothesis: The reason the test case only fails when run as part of the whole suite has something to do with long.js being used in another test case that runs earlier, triggering the async path, which we know to be broken.

Experiment: Copy long.js as long-1.js, and doc-scripts.html as doc-scripts-1 .html. Edit doc-scripts-1.html to load long-1.js, then edit browser_dbg-navigation.js to load doc-scripts-1.html, and expect long-1.js

Result: Test times out. This disproves the hypothesis that there was something special about previous usage of long.js and doc-scripts.html that triggers the Async path which is broken.

Note to self: I believe this patch also breaks the TRACE_FOR_TEST here, as the element is null, and so we don't ever actually emit the events after this patch.

Depends on: 1560365

Duping this to 1501608 which will obviate this work, and provide better results.

Status: NEW → RESOLVED
Closed: 5 years ago
Flags: needinfo?(jimb)
Resolution: --- → DUPLICATE
Attachment #9062016 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: