Measure how often layout queries are blocked by ongoing layout

[jdm]

Servo uses a separate thread for performing layout from the thread that runs JS. When JS code triggers a synchronous layout query (such as the getBoundingClientRectangle API) we would like to record if the query is blocked on an ongoing layout operation in the layout thread. When invoking any of the operations that cause one of these messages to be sent to the layout thread, we want to check if the layout thread is busy. We can increase a counter that we store in ScriptThread based on the result, and display statistics about the data during shutdown.

To determine if layout is busy, we can use an Arc<AtomicBoolean> value that is shared by both threads. It can be stored as a member of Window and LayoutThread, and created by the script thread and sent as part of the CreateLayoutThread message.

Code:

• components/script/script_thread.rs
• components/layout_thread/lib.rs
• components/script_layout_interface/message.rs
• components/script/dom/window.rs
• components/constellation/pipeline.rs (the initial script and layout threads created when loading a document will need to have the AtomicBool value created for them in UnprivilegedPipelineContent::start_all)

Note: this is intended as a student project. Please talk to me before starting to work on it.

[jdm]

This is available for anybody who is interested in working on it.

[aishpant]

I would like to work on this.

[jdm]

@aishpant That would be great! Please ask questions if anything is unclear!

[jdm]

@aishpant Have you made any progress with this task?

[aishpant]

Sorry, I haven't had the time to look at this :-( Please assign it to someone else.

[Gaelan]

I'll give this a shot.

[jdm]

Great!

[pandusonu2]

I know this is assigned, but can I give this a try and raise a PR if I am able to get any progress?

Upd: Sorry, I wasn't able to fix this. I will check back later to learn from the fix if anyone does it.

[Gaelan]

Go for it. I'm partially done with it, but I've been busy later.

[jdm]

This is open for anybody to work on.

[pylbrecht]

I'd like to give this a shot.

Note: this is intended as a student project. Please talk to me before starting to work on it.

@jdm, is this still relevant? If so, can I reach you on IRC?

[jdm]

It's available for anybody.

[pylbrecht]

Alright, then I'd like to work on that!

[jdm]

It's all yours! Ask questions if anything is unclear :)

[pylbrecht]

Are there any existing tests for the code involved? Should I write tests for the new code?

[jdm]

We do not have any unit tests for the code involved, and it's not clear to me that it is feasible to do so. Manual testing for these changes is fine.

[pylbrecht]

I looked into the code and just want to verify my assumptions before I continue:

Every QueryMsg has a corresponding method in script/dom/window.rs, which calls Window::layout_reflow() (side note: I didn't check all messages). So I'm thinking of putting the check, if the layout thread is busy, in layout_reflow().

LayoutThread::handle_request_helper() seems to handle messages coming from ScriptThread, so I would set/unset the busy flag in there.
[update]
Or would this match arm be a better place?
[/update]

Does this make sense?

[jdm]

Yes, those sound like reasonable choices!

[pylbrecht]

I'm still not quite sure how window/document handling is working.
As we want a global blocked query counter stored in the script thread, and we're passing it to each window created by the script thread (because the "busy check" is done in Window::layout_reflow()), do we need to use a Rc<RefCell> for that counter, because there are multiple windows sharing that state? Or would it be enough to pass a mutable reference? Or do we also need an Arc, because windows/documents are handled in their own thread(s)?

[jdm]

Storing a Rc<Cell<u32>> in Window would be fine.

[pylbrecht]

So far so good.

How can I verify, that my implementation is actually working? Is there any deterministic way of creating "blocked queries"?

And in what form should statistics be displayed during shutdown of the script thread?

[jdm]

The easiest way to trigger blocking queries is to have JS that modifies the layout of the page in some fashion (changing CSS; mutating the DOM by adding/removing a node; etc.) then immediately performing a layout query on a node that is affected by the changes (like getBoundingClientRectangle). We could start with reporting how many queries were blocked out of the total number of queries that were initiated for a given ScriptThread.

[pylbrecht]

Unfortunately I was not able to verify my code, yet.

I'm trying to trigger a blocked query with this test.html:

<!DOCTYPE html>
<html>
  <head>
    <title>Test</title>
  </head>
  <body>
    <div id="test">
      test
    </div>
    <script>
      document.getElementById("test").style.color = "blue";
      document.getElementById("test").getBoundingClientRect();
    </script>
  </body>
</html>

I'm running Servo with RUST_LOG="script::script_thread" to check for the statistics printed via debug!().
I tried placing the reporting code in:

• Drop implementation for ScriptThread
• immediately after the script_thread.start() call in ScriptThreadFactory::create()
• in ScriptThread::handle_exit_script_thread_msg()

None of which produced the desired output.
The last lines always seem look like this (I expected to find at least a "Exiting script thread" message, printed in handle_exit_script_thread()):

05.368657:  DEBUG 2018-08-20T21:22:40Z: script::script_thread: Got event.
05.368830:  DEBUG 2018-08-20T21:22:40Z: script::script_thread: Processing events.
05.368892:  DEBUG 2018-08-20T21:22:40Z: script::script_thread: Processing event FromConstellation(ConstellationControlMsg::SendEvent).
05.369359:  DEBUG 2018-08-20T21:22:40Z: script::script_thread: Issuing batched reflows.
05.369471:  DEBUG 2018-08-20T21:22:40Z: script::script_thread: Running script thread.
05.369526:  DEBUG 2018-08-20T21:22:40Z: script::script_thread: Waiting for event.
06.242025:  DEBUG 2018-08-20T21:22:41Z: script::script_thread: Got event.
06.242118:  DEBUG 2018-08-20T21:22:41Z: script::script_thread: Processing events.
06.242163:  DEBUG 2018-08-20T21:22:41Z: script::script_thread: Processing event FromConstellation(ConstellationControlMsg::ExitPipeline).
06.242199:  DEBUG 2018-08-20T21:22:41Z: script::script_thread: Exiting pipeline (0,1).
06.242373:  DEBUG 2018-08-20T21:22:41Z: script::script_thread: preparing to shut down layout for page (0,1)
06.242544:  DEBUG 2018-08-20T21:22:41Z: script::script_thread: shutting down layout for page (0,1)
06.246516:  DEBUG 2018-08-20T21:22:41Z: script::script_thread: tracing fields of ScriptThread

[pylbrecht]

I tried this on the latest master hoping to see different results, but got the same debug messages. I don't understand how the involved threads are terminated, meaning by whom and in what order, because I don't get any more debug messages coming from the script thread than those in my last comment.
Generally speaking I don't know where to look.

Somehow I don't trust the debug output, because it abruptly stops as soon as I terminate Servo. Is there a better way of running a manual test than the following?

1. RUST_LOG="debug" ./mach run -d
2. Terminate Servo by clicking the "x" in the window title bar
3. Look at the generated log

[pylbrecht]

I had long forgotten this issue, but I remember being stuck at some point.

@jdm, do you still consider this an approachable issue for a servo starter like me or would another one be better suited? The issue looks kind of abandoned at the moment, so I'm unsure if it's still a good fit.

[jdm]

@pylbrecht Oh dear. I remember adding your previous question to my list of things to investigate; I apologize for never returning to it. You're right that the script thread never receives the ExitScriptThread message; the message is definitely sent, but the main thread appears to terminate before the message is received by the script thread.

[jdm]

Ok, I have a new strategy to recommend (and I do believe it's still appropriate for a starter issue!):

• add a new field to Profiler which is a map from string (url) to u32
• add a new variant to ProfilerMsg which takes a string
• every time a layout query is blocked (per previous instructions), send this new message to the profiler
• when the profiler receives this new message, increase the appropriate counter by 1
• in Profiler::print_buckets also print the new layout blocked counters

code: components/profiler_traits/time.rs, components/profiler/time.rs

[pylbrecht]

Great, then I'll dive right back into it! I'll keep you up to date on my progress.

[pylbrecht]

So I added all neccessary fields and my code compiles without any errors.
What's still missing is the communication with the profiler, which I just skimmed over so far.

Though I am not so sure about my manual testing approach from my previous comment. I added a panic!() to the "layout thread is busy" check, but it was not triggered. So either my code is wrong or the test is insufficient.