Do not wait for rAF to be requested in render loop #25343

Manishearth · 2019-12-19T19:56:32Z

Servo-side of servo/webxr#114

r? @jdm

highfive · 2019-12-19T19:56:38Z

Heads up! This PR modifies the following files:

@asajeffrey: components/script/dom/xrsession.rs, components/script/dom/xr.rs
@KiChjang: components/script/dom/xrsession.rs, components/script/dom/xr.rs

highfive · 2019-12-19T19:56:41Z

Warning

These commits modify script code, but no tests are modified. Please consider adding a test!

jdm · 2019-12-19T20:21:15Z

components/script/dom/xrsession.rs

-            self.raf_sender.borrow().is_none(),
-            "RAF loop already set up"
-        );
+    fn setup_raf_loop(&self, frame_receiver: IpcReceiver<Frame>) {
        let this = Trusted::new(self);
        let global = self.global();
        let window = global.as_window();
        let (task_source, canceller) = window
            .task_manager()
            .dom_manipulation_task_source_with_canceller();


To reduce the time between when we're signalled with a new frame and when we run the rAF callback, we should use a high-priority task source. The spec doesn't actually specify a particular ordering, so we should be able to get away with jumping the queue. For example, we could use a dedicated sender/receiver pair and use try_recv on it before calling select! in ScriptThread::handle_msgs.

https://github.com/jdm/servo/tree/xr-frame-prioritize

I think that's a good idea, and maybe it could be further improved by not going through the router to receive the frame.

I think it could be done through:

Whenever a callback is added:

set a awaiting_frame flag on the script-thread.

send a MainThreadScriptMsg::WakeUp to ensure the main loop doesn't block on the select

After the microtask checkpoint:

remove the awaiting_frame flag, and, if it was true:

block on the frame receiver, and

immediately run the callbacks when receiving it.

This would require also running 2(and the microtask checkpoint) if sequential is empty(in the case that the only event is the MainThreadScriptMsg::WakeUp, since it will be filtered out by the task-queue). It also requires Xr to always send a message on the frame receiver to unblock the script-thread.

So that could be a way to block directly on a IpcReceiver inside handle_msgs, with the benefit being always running the frame callbacks immediately after you receive the frame, and not going through the router.

Then I guess the script-thread could make the xr_frame_ pair an ipc-channel where the sender would be cloned inside request_new_xr_frame and send to Xr?

Ah ok I see you also need a way to call from the script-thread into the session, so instead of an awaiting_frame flag, you could have an Option<SessionAwaitingFrame> on the script-thread, which would be set by request_new_xr_frame and taken before optionally blocking on the frame receiver from within handle_msgs. I assume you can have only one active Xr session per script-thread?

Like https://github.com/gterzian/servo/tree/restructure_xr_frame_handling
If it seems like a good idea I could just open a PR as a follow-up.

You can have multiple online sessions, but only one immersive

We first need to figure out why this is breaking the tests. I bet it's because of a race between data getting sent and read from the mock device.

I think the problem with the timeouts is that with the current changes, the call to render_animation_frame from script only occurs if the session is immersive(and the changes in Xr from servo/webxr#114 makes the render loop dependent on rendering a frame).

Previously, a new frame would be requested at the end of running callbacks, regardless of whether the session was immersive.

That was indeed the issue, was poking at this earlier. Fixed now.

Opening a followup PR would be great, but we should test if it affects FPS.

Manishearth · 2019-12-19T21:57:57Z

The FPS values seem to slightly go up from 12-15 to 15-20.

Timing values (in microseconds, I forgot what a nanosecond was and divided wrong) between the time the openxr backend constructs the frame ("Frame") and the time we trigger callbacks in script ("Now") :

Now: 1720318156	 Frame: 1720311936	Delta: 6219.375
Now: 1720390996	 Frame: 1720389289	Delta: 1707.292
Now: 1720446786	 Frame: 1720442530	Delta: 4256.355
Now: 1720528122	 Frame: 1720523149	Delta: 4973.020
Now: 1720584494	 Frame: 1720575796	Delta: 8697.812
Now: 1720657133	 Frame: 1720655931	Delta: 1202.447
Now: 1720714996	 Frame: 1720713575	Delta: 1421.093
Now: 1720773981	 Frame: 1720772679	Delta: 1302.292
Now: 1720830164	 Frame: 1720828616	Delta: 1547.604
Now: 1720890760	 Frame: 1720889245	Delta: 1515.781
Now: 1720945515	 Frame: 1720943989	Delta: 1525.729
Now: 1721007255	 Frame: 1721005985	Delta: 1269.844
Now: 1721062167	 Frame: 1721059961	Delta: 2205.833
Now: 1721123669	 Frame: 1721122519	Delta: 1150.000
Now: 1721181460	 Frame: 1721178199	Delta: 3261.302
Now: 1721240545	 Frame: 1721239333	Delta: 1211.979
Now: 1721309603	 Frame: 1721303655	Delta: 5947.812
The thread 0x1a7c has exited with code 0 (0x0).
Now: 1721374806	 Frame: 1721372548	Delta: 2258.073
Now: 1721415320	 Frame: 1721413298	Delta: 2022.031
Now: 1721474244	 Frame: 1721472577	Delta: 1667.136
Now: 1721516310	 Frame: 1721515056	Delta: 1253.802

Seems like we're losing around 2-6ms on just the communication delay. Digging further into this

Manishearth · 2019-12-19T22:28:40Z

More timings. Delta is between us getting a frame from openxr and us seeing it in raf_callback in script. Delta_task is between the script process router getting the frame message and the script thread running it. Ignore the last one.

It seems like we're losing time in waiting for the script router to pick up the IPC message, which bolsters my initial hunch that IPC is slow for some reason.

Now: 30135.365	 Frame: 30133.465	Delta: 1.900	Delta_task: 0.707	Delta_rafc: 0.029
Now: 30187.074	 Frame: 30185.543	Delta: 1.530	Delta_task: 0.237	Delta_rafc: 0.015
Now: 30235.812	 Frame: 30234.467	Delta: 1.345	Delta_task: 0.171	Delta_rafc: 0.014
Now: 30287.797	 Frame: 30285.883	Delta: 1.913	Delta_task: 0.227	Delta_rafc: 0.015
Now: 30335.949	 Frame: 30334.205	Delta: 1.744	Delta_task: 0.399	Delta_rafc: 0.015
Now: 30387.547	 Frame: 30385.756	Delta: 1.789	Delta_task: 0.231	Delta_rafc: 0.016
Now: 30437.031	 Frame: 30435.457	Delta: 1.575	Delta_task: 0.188	Delta_rafc: 0.016
Now: 30487.953	 Frame: 30485.637	Delta: 2.317	Delta_task: 0.230	Delta_rafc: 0.015
Now: 30537.453	 Frame: 30535.949	Delta: 1.505	Delta_task: 0.214	Delta_rafc: 0.012
Now: 30604.316	 Frame: 30602.482	Delta: 1.835	Delta_task: 0.210	Delta_rafc: 0.015
Now: 30657.307	 Frame: 30652.455	Delta: 4.852	Delta_task: 0.705	Delta_rafc: 0.016
Now: 30737.090	 Frame: 30735.533	Delta: 1.555	Delta_task: 0.240	Delta_rafc: 0.016
Now: 30784.846	 Frame: 30783.484	Delta: 1.361	Delta_task: 0.157	Delta_rafc: 0.010

Manishearth · 2019-12-19T22:39:18Z

Hmm, there's actually a consistent 1ms gap between the time we wait() and the time we construct our frame. Something's fishy there.

That's not the only contributing factor though.

asajeffrey · 2019-12-19T22:43:15Z

2-6ms is a lot of extra time!

Manishearth · 2019-12-19T23:04:25Z

So locate_views is taking around 0.2ms, .locate() is taking around 0.15ms, sync_actions is 0.044ms, and the input .frame() calls are all together taking 0.6ms (it's a total of 4 locate() calls, essentially).

asajeffrey · 2019-12-19T23:19:46Z

Hmm, that all sounds like stuff that's out of our control? The only thing I can think of is decoupling the calls to input .frame(), since if that information is a frame late it probably won't matter so much?

Manishearth · 2019-12-19T23:33:14Z

It might be that we're using the APIs incorrectly, too. I tried using unbounded spaces as recommended, that didn't fix it. Going for jdm's scheduling patch now to see if I can at least fix the communication overhead, which is still a nontrivial chunk.

jdm · 2019-12-19T23:37:20Z

Perhaps we should look into calling begin_frame before render_animation_frame, to be more like the SDK sample at https://github.com/microsoft/OpenXR-SDK-VisualStudio/blob/4378fbda334809852331fccf2ffa9b4979e0684f/samples/BasicXrApp/OpenXrProgram.cpp#L609-L612.

Manishearth · 2019-12-20T00:09:39Z

Timings with @jdm's patch. Delta is the time between frame creation and frame reception in script, delta_task is the time between the script process receiving it and the script thread receiving it. Callback time is the time taken to execute raf callbacks (which we can expect to be somewhat large)

Now: 33839.398	 Frame: 33837.664	Delta: 1.736	Delta_task: 0.172	Callback time: 2.842
Now: 33895.418	 Frame: 33892.207	Delta: 3.213	Delta_task: 1.973	Callback time: 2.785
Now: 33939.176	 Frame: 33937.449	Delta: 1.726	Delta_task: 0.235	Callback time: 3.556
Now: 33993.762	 Frame: 33992.102	Delta: 1.660	Delta_task: 0.149	Callback time: 2.864
Now: 34055.547	 Frame: 34053.891	Delta: 1.654	Delta_task: 0.218	Callback time: 4.446
Now: 34127.477	 Frame: 34125.398	Delta: 2.076	Delta_task: 0.879	Callback time: 3.595
Now: 34187.035	 Frame: 34185.129	Delta: 1.906	Delta_task: 0.329	Callback time: 4.338
Now: 34244.059	 Frame: 34242.164	Delta: 1.893	Delta_task: 0.146	Callback time: 3.102

There are also a bunch of entries with much larger deltas sprinkled throughout. Some are in a sequence:

Now: 34850.398	 Frame: 34842.527	Delta: 7.875	Delta_task: 0.152	Callback time: 3.159
Now: 35625.762	 Frame: 35620.098	Delta: 5.662	Delta_task: 0.152	Callback time: 3.357

the larger deltas are paired with slightly higher time taken in all the openxr stuff in wait_for_animation_frame, but it doesn't fully account for it. It's possible we're doing a lot of computation elsewhere that's just slowing everything down.

(Perhaps it's because we're still rendering the webpage but not displaying it?)

jdm · 2019-12-20T01:00:51Z

Other interesting things to time include:

time from sending SwapBuffer message in script to time to process that message in the webgl thread
time taken to run handle_swap_buffers
time taken to send signal that swapping is complete back to script
time taken to complete layout after swapping buffers (https://github.com/servo/servo/blob/master/components/script/dom/window.rs#L1579)

I wonder if we could send the swap buffer message, start layout, wait for layout to complete, then join with the swap buffer completion response to avoid blocking twice sequentially...

jdm · 2019-12-20T01:03:57Z

Mmm, some of those may not actually make sense here; I didn't realize we call swap_buffers directly in immersive mode.

jdm · 2019-12-20T01:05:14Z

That being said, we do run layout, and we do dirty the canvas, and both of those involve blocking the script thread on receiving a response from another thread, so they could contribute to the deltas.

asajeffrey · 2019-12-20T04:58:04Z

Running layout should only block if the document is dirty or animations are running? Which hopefully pages aren't doing once they've entered immersive mode.

jdm · 2019-12-20T05:28:38Z

We mark the canvas dirty right after we swap the base layer's buffer:

servo/components/script/dom/xrsession.rs

Lines 366 to 372 in bac9903

    
           // If the canvas element is attached to the DOM, it is now dirty, 
        
           // and we need to trigger a reflow. 
        
           base_layer 
        
               .Context() 
        
               .Canvas() 
        
               .upcast::<Node>() 
        
               .dirty(NodeDamage::OtherNodeDamage);

Manishearth · 2019-12-20T07:37:02Z

which makes sense for the test backend, and not for any other.

asajeffrey · 2019-12-20T14:51:38Z

Ah, that's a holdover from the pre-surfman days.

Manishearth · 2019-12-20T22:07:17Z

We should probably merge these since I was seeing an improvement from 12-15FPS to 15-20FPS.

Manishearth · 2019-12-23T21:42:00Z

Removing the dirty-marking does not impact FPS visibly. Worth doing anyway.

jdm · 2019-12-24T00:38:44Z

This is still marked as a draft, fyi.


        Auto merge of #114 - Manishearth:autoraf, r=jdm

@jdm

Do not wait for rAF to be requested This does not make the render loop _completely_ independent of script: it still waits for script to submit a frame. If we don't, frames will be dropped (and I'm not sure what strategy to use there). I'm going to test this soon and see if it actually improves our framerate. Servo side: servo/servo#25343 r? @jdm

Manishearth · 2019-12-24T01:36:45Z

Hm? doesn't seem to be.

But i need to update this to deal with the other one landing

bors-servo · 2019-12-24T17:43:23Z

💔 Test failed - status-taskcluster

jdm · 2019-12-24T17:52:18Z

Oops:

  ▶ TIMEOUT [expected OK] /webxr/xrSession_requestAnimationFrame_getViewerPose.https.html
  │ 
  │ 
  │ 
  └ 
  ▶ Unexpected subtest result in /webxr/xrSession_requestAnimationFrame_getViewerPose.https.html:
  │ TIMEOUT [expected PASS] XRFrame getViewerPose updates on the next frame for non-immersive sessions
  └   → Test timed out
  ▶ Unexpected subtest result in /webxr/xrSession_requestAnimationFrame_getViewerPose.https.html:
  └ NOTRUN [expected PASS] XRFrame getViewerPose updates on the next frame for immersive sessions
  ▶ TIMEOUT [expected OK] /webxr/render_state_vertical_fov_inline.https.html
  │ 
  │ 
  │ 
  └ 
  ▶ Unexpected subtest result in /webxr/render_state_vertical_fov_inline.https.html:
  │ TIMEOUT [expected PASS] inlineVerticalFieldOfView is set appropriately on inline sessions
  └   → Test timed out
  ▶ TIMEOUT [expected OK] /webxr/xrStationaryReferenceSpace_floorlevel_updates.https.html
  │ 
  │ 
  │ 
  └ 
  ▶ Unexpected subtest result in /webxr/xrStationaryReferenceSpace_floorlevel_updates.https.html:
  │ TIMEOUT [expected FAIL] 'floor-level' XRStationaryReferenceSpace updates properly when the transform changes for non-immersive sessions
  └   → Test timed out
  ▶ TIMEOUT [expected OK] /webxr/xrSession_viewer_referenceSpace.https.html

Manishearth · 2019-12-24T20:23:12Z

Oh, it's possible that the synchronization of mock data no longer works with this.


        Do not wait for rAF to be requested in render loop


        Kick the raf loop in inline sessions

Manishearth · 2020-01-02T08:26:29Z

@bors-servo r=jdm

bors-servo · 2020-01-02T08:26:30Z

💡 This pull request was already approved, no need to approve it again.

This pull request previously failed. You should add more commits to fix the bug, or use retry to trigger a build again.

bors-servo · 2020-01-02T08:26:31Z

📌 Commit 1b5f0ed has been approved by jdm

bors-servo · 2020-01-02T08:26:38Z

⌛ Testing commit 1b5f0ed with merge fc92b13...


        Auto merge of #25343 - Manishearth:autoraf, r=jdm

@jdm

Do not wait for rAF to be requested in render loop Servo-side of servo/webxr#114 r? @jdm

Manishearth · 2020-01-02T08:29:57Z

@bors-servo r-

oops, push didn't work

Manishearth · 2020-01-02T08:30:52Z

@bors-servo try- retry r=jdm

bors-servo · 2020-01-02T08:30:53Z

📌 Commit 666ee5c has been approved by jdm

bors-servo · 2020-01-02T08:30:58Z

⌛ Testing commit 666ee5c with merge 7281336...


        Auto merge of #25343 - Manishearth:autoraf, r=jdm

@jdm

Do not wait for rAF to be requested in render loop Servo-side of servo/webxr#114 r? @jdm

bors-servo · 2020-01-02T10:00:32Z

☀️ Test successful - status-taskcluster
Approved by: jdm
Pushing 7281336 to master...

highfive assigned jdm Dec 19, 2019

highfive added the S-awaiting-review label Dec 19, 2019

jdm reviewed Dec 19, 2019

View changes

Manishearth mentioned this pull request Dec 23, 2019

Do not wait for rAF to be requested servo/webxr#114

Merged

Manishearth marked this pull request as ready for review Dec 23, 2019

jdm approved these changes Dec 24, 2019

View changes

Manishearth force-pushed the Manishearth:autoraf branch from 6cfd2cd to 5a23e6d Dec 24, 2019

highfive added S-awaiting-merge and removed S-tests-failed labels Dec 24, 2019

highfive added S-tests-failed and removed S-awaiting-merge labels Dec 24, 2019

Manishearth added 2 commits Dec 19, 2019

Do not wait for rAF to be requested in render loop

01f27e9

Kick the raf loop in inline sessions

Loading status checks…

666ee5c

highfive added S-awaiting-merge and removed S-tests-failed labels Jan 2, 2020

Manishearth force-pushed the Manishearth:autoraf branch from 1b5f0ed to 666ee5c Jan 2, 2020

highfive added S-awaiting-review and removed S-awaiting-merge labels Jan 2, 2020

highfive added S-awaiting-merge and removed S-awaiting-review labels Jan 2, 2020

bors-servo merged commit 666ee5c into servo:master Jan 2, 2020
2 checks passed

2 checks passed

Community-TC (pull_request) TaskGroup: success
Details

homu Test successful
Details

highfive removed the S-awaiting-merge label Jan 2, 2020

jdm mentioned this pull request Jan 3, 2020

Immersive mode doesn't reach 60fps #25425

Closed

servo / servo

Join GitHub today

Do not wait for rAF to be requested in render loop #25343

Do not wait for rAF to be requested in render loop #25343

Conversation

Manishearth commented Dec 19, 2019

highfive commented Dec 19, 2019

highfive commented Dec 19, 2019

This comment has been minimized.

jdm Dec 19, 2019

This comment has been minimized.

jdm Dec 19, 2019

This comment has been minimized.

gterzian Jan 1, 2020 • edited

This comment has been minimized.

gterzian Jan 1, 2020 • edited

This comment has been minimized.

gterzian Jan 1, 2020

This comment has been minimized.

Manishearth Jan 1, 2020

This comment has been minimized.

gterzian Jan 2, 2020 • edited

This comment has been minimized.

Manishearth Jan 2, 2020

Manishearth commented Dec 19, 2019

Manishearth commented Dec 19, 2019 • edited by jdm

Manishearth commented Dec 19, 2019

asajeffrey commented Dec 19, 2019

Manishearth commented Dec 19, 2019

asajeffrey commented Dec 19, 2019

Manishearth commented Dec 19, 2019

jdm commented Dec 19, 2019

Manishearth commented Dec 20, 2019

jdm commented Dec 20, 2019

jdm commented Dec 20, 2019 • edited

jdm commented Dec 20, 2019

asajeffrey commented Dec 20, 2019

jdm commented Dec 20, 2019

Manishearth commented Dec 20, 2019

asajeffrey commented Dec 20, 2019

Manishearth commented Dec 20, 2019

Manishearth commented Dec 23, 2019

jdm commented Dec 24, 2019

Manishearth commented Dec 24, 2019

bors-servo commented Dec 24, 2019

jdm commented Dec 24, 2019

Manishearth commented Dec 24, 2019

Manishearth commented Jan 2, 2020

bors-servo commented Jan 2, 2020

bors-servo commented Jan 2, 2020

bors-servo commented Jan 2, 2020

Manishearth commented Jan 2, 2020

Manishearth commented Jan 2, 2020

bors-servo commented Jan 2, 2020

bors-servo commented Jan 2, 2020

bors-servo commented Jan 2, 2020

gterzian Jan 1, 2020 •

edited

gterzian Jan 1, 2020 •

edited

gterzian Jan 2, 2020 •

edited

Manishearth commented Dec 19, 2019 •

edited by jdm

jdm commented Dec 20, 2019 •

edited