WebVR: fix initial vsync

third_party/WebKit/Source/modules/vr/VRDisplay.cpp

 // Copyright 2016 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "modules/vr/VRDisplay.h"
 
 #include "core/css/StylePropertySet.h"
 #include "core/dom/DOMException.h"
 #include "core/dom/FrameRequestCallback.h"
 #include "core/dom/ScriptedAnimationController.h"
 #include "core/dom/TaskRunnerHelper.h"
+#include "core/frame/Frame.h"
 #include "core/frame/FrameView.h"
 #include "core/frame/ImageBitmap.h"
 #include "core/frame/UseCounter.h"
 #include "core/inspector/ConsoleMessage.h"
 #include "core/layout/LayoutView.h"
 #include "core/layout/compositing/PaintLayerCompositor.h"
 #include "core/loader/DocumentLoader.h"
+#include "core/page/FocusController.h"
 #include "gpu/command_buffer/client/gles2_interface.h"
 #include "gpu/command_buffer/common/mailbox_holder.h"
 #include "modules/EventTargetModules.h"
 #include "modules/vr/NavigatorVR.h"
 #include "modules/vr/VRController.h"
 #include "modules/vr/VRDisplayCapabilities.h"
 #include "modules/vr/VREyeParameters.h"
 #include "modules/vr/VRFrameData.h"
 #include "modules/vr/VRLayer.h"
 #include "modules/vr/VRPose.h"
@@ skipping 68 matching lines @@
     stage_parameters_->Update(display->stageParameters);
   } else {
     stage_parameters_ = nullptr;
   }
 
   if (need_on_present_change) {
     OnPresentChange();
   }
 }
 
+bool VRDisplay::IsPresentationFocused() {
+  if (!navigator_vr_)
+    return false;
+
+  if (navigator_vr_->IsFocused())
+    return true;
+
+  auto doc = navigator_vr_->GetDocument();
+  if (!doc)
+    return false;
+
+  // Check if this is an embedded iframe without focus. If a local parent is
+  // focused, continue presenting.
+
+  Frame* frame = doc->GetFrame();
+  for (; frame; frame = frame->Tree().Parent()) {
+    if (!frame->IsLocalFrame())
+      break;
+    auto frame_doc = ToLocalFrame(frame)->GetDocument();
+    if (frame_doc && frame_doc->hasFocus()) {
+      DVLOG(3) << __FUNCTION__ << ": a parent frame is focused";
+      return true;
+    }
+  }
+
+  return false;
+}
+
 bool VRDisplay::getFrameData(VRFrameData* frame_data) {
-  if (!navigator_vr_->IsFocused() || !frame_pose_ || display_blurred_)
+  if (!IsPresentationFocused() || !frame_pose_ || display_blurred_)
     return false;
 
   if (!frame_data)
     return false;
 
   if (depth_near_ == depth_far_)
     return false;
 
   return frame_data->Update(frame_pose_, eye_parameters_left_,
                             eye_parameters_right_, depth_near_, depth_far_);
 }
 
 VREyeParameters* VRDisplay::getEyeParameters(const String& which_eye) {
   switch (StringToVREye(which_eye)) {
     case kVREyeLeft:
       return eye_parameters_left_;
     case kVREyeRight:
       return eye_parameters_right_;
     default:
       return nullptr;
   }
 }
 
 int VRDisplay::requestAnimationFrame(FrameRequestCallback* callback) {
+  DVLOG(2) << __FUNCTION__;
   Document* doc = this->GetDocument();
   if (!doc)
     return 0;
-  pending_raf_ = true;
+  pending_vrdisplay_raf_ = true;
   if (!vr_v_sync_provider_.is_bound()) {
     ConnectVSyncProvider();
   } else if (!display_blurred_ && !pending_vsync_) {
     pending_vsync_ = true;
     vr_v_sync_provider_->GetVSync(ConvertToBaseCallback(
         WTF::Bind(&VRDisplay::OnVSync, WrapWeakPersistent(this))));
   }
   callback->use_legacy_time_base_ = false;
   return EnsureScriptedAnimationController(doc).RegisterCallback(callback);
 }
 
 void VRDisplay::cancelAnimationFrame(int id) {
+  DVLOG(2) << __FUNCTION__;
   if (!scripted_animation_controller_)
     return;
   scripted_animation_controller_->CancelCallback(id);
 }
 
 void VRDisplay::OnBlur() {
+  DVLOG(1) << __FUNCTION__;
   display_blurred_ = true;
   vr_v_sync_provider_.reset();
   navigator_vr_->EnqueueVREvent(VRDisplayEvent::Create(
       EventTypeNames::vrdisplayblur, true, false, this, ""));
 }
 
 void VRDisplay::OnFocus() {
+  DVLOG(1) << __FUNCTION__;
   display_blurred_ = false;
   ConnectVSyncProvider();
   navigator_vr_->EnqueueVREvent(VRDisplayEvent::Create(
       EventTypeNames::vrdisplayfocus, true, false, this, ""));
 }
 
 void ReportPresentationResult(PresentationResult result) {
   // Note that this is called twice for each call to requestPresent -
   // one to declare that requestPresent was called, and one for the
   // result.
   DEFINE_STATIC_LOCAL(
       EnumerationHistogram, vr_presentation_result_histogram,
       ("VRDisplayPresentResult",
        static_cast<int>(PresentationResult::kPresentationResultMax)));
   vr_presentation_result_histogram.Count(static_cast<int>(result));
 }
 
 ScriptPromise VRDisplay::requestPresent(ScriptState* script_state,
                                         const HeapVector<VRLayer>& layers) {
+  DVLOG(1) << __FUNCTION__;
   ExecutionContext* execution_context = ExecutionContext::From(script_state);
   UseCounter::Count(execution_context, UseCounter::kVRRequestPresent);
   if (!execution_context->IsSecureContext()) {
     UseCounter::Count(execution_context,
                       UseCounter::kVRRequestPresentInsecureOrigin);
   }
 
   ReportPresentationResult(PresentationResult::kRequested);
 
   ScriptPromiseResolver* resolver = ScriptPromiseResolver::Create(script_state);
@@ skipping 122 matching lines @@
         kNotAllowedError, "Presentation request was denied.");
 
     while (!pending_present_resolvers_.IsEmpty()) {
       ScriptPromiseResolver* resolver = pending_present_resolvers_.TakeFirst();
       resolver->Reject(exception);
     }
   }
 }
 
 ScriptPromise VRDisplay::exitPresent(ScriptState* script_state) {
+  DVLOG(1) << __FUNCTION__;
   ScriptPromiseResolver* resolver = ScriptPromiseResolver::Create(script_state);
   ScriptPromise promise = resolver->Promise();
 
   if (!is_presenting_) {
     // Can't stop presenting if we're not presenting.
     DOMException* exception = DOMException::Create(
         kInvalidStateError, "VRDisplay is not presenting.");
     resolver->Reject(exception);
     return promise;
   }
@@ skipping 57 matching lines @@
   is_presenting_ = true;
   ReportPresentationResult(PresentationResult::kSuccess);
 
   UpdateLayerBounds();
 
   while (!pending_present_resolvers_.IsEmpty()) {
     ScriptPromiseResolver* resolver = pending_present_resolvers_.TakeFirst();
     resolver->Resolve();
   }
   OnPresentChange();
+
+  // TODO(klausw,crbug.com/710863): there appear to be cases where an embedded
+  // iframe has started presenting but isn't focused. To fix this, would need
+  // to switch focus here.
+
+  // Ensure that we get at least one vsync. It's possible that a page may
+  // have started presentation but not used vrDisplay.rAF yet, i.e. if it
+  // uses window.rAF while not yet presenting. It needs to get a chance
+  // to run its animation loop to avoid getting stuck, and to do so we
+  // need a vsync where we can run pending window.rAF callbacks.
+  if (!vr_v_sync_provider_.is_bound()) {
+    ConnectVSyncProvider();
+  } else if (!display_blurred_ && !pending_vsync_) {
+    pending_vsync_ = true;
+    vr_v_sync_provider_->GetVSync(ConvertToBaseCallback(
+        WTF::Bind(&VRDisplay::OnVSync, WrapWeakPersistent(this))));
+  }
+  if (!pending_vsync_) {
+    if (doc) {
+      doc->AddConsoleMessage(
+          ConsoleMessage::Create(kRenderingMessageSource, kWarningMessageLevel,
+                                 "Scheduling missing vsync."));

[bajones, 2017/04/27 22:02:46]

Is this something that we feel pages should be architected to avoid? If so I
think the message should be a bit more instructive about how to avoid hitting
this condition, if not then I don't feel it's appropriate to log a warning to
the console for expected behavior and a DVLOG is probably more appropriate.

[klausw, 2017/04/28 18:43:14]

Changed to DVLOG, this was only there for investigating the issue. Sorry about
that.

+    }
+    if (vr_v_sync_provider_.is_bound()) {
+      pending_vsync_ = true;
+      vr_v_sync_provider_->GetVSync(ConvertToBaseCallback(
+          WTF::Bind(&VRDisplay::OnVSync, WrapWeakPersistent(this))));
+    } else {
+      if (doc) {
+        doc->AddConsoleMessage(ConsoleMessage::Create(
+            kRenderingMessageSource, kWarningMessageLevel,
+            "Failed to schedule missing vsync. Not focused?"));
+      }
+    }
+  }
 }
 
 // Need to close service if exists and then free rendering context.
 void VRDisplay::ForceExitPresent() {
   if (display_) {
     display_->ExitPresent();
   }
   StopPresenting();
 }
 
@@ skipping 196 matching lines @@
 
 void VRDisplay::OnSubmitFrameRendered() {
   pending_previous_frame_render_ = false;
 }
 
 Document* VRDisplay::GetDocument() {
   return navigator_vr_->GetDocument();
 }
 
 void VRDisplay::OnPresentChange() {
+  DVLOG(1) << __FUNCTION__ << ": is_presenting_=" << is_presenting_;
   if (is_presenting_ && !is_valid_device_for_presenting_) {
     DVLOG(1) << __FUNCTION__ << ": device not valid, not sending event";
     return;
   }
   navigator_vr_->EnqueueVREvent(VRDisplayEvent::Create(
       EventTypeNames::vrdisplaypresentchange, true, false, this, ""));
 }
 
 void VRDisplay::OnChanged(device::mojom::blink::VRDisplayInfoPtr display) {
   Update(display);
@@ skipping 48 matching lines @@
 }
 
 void VRDisplay::ProcessScheduledWindowAnimations(double timestamp) {
   TRACE_EVENT1("gpu", "VRDisplay::window.rAF", "frame", vr_frame_id_);
   auto doc = navigator_vr_->GetDocument();
   if (!doc)
     return;
   auto page = doc->GetPage();
   if (!page)
     return;
+
+  bool had_pending_vrdisplay_raf = pending_vrdisplay_raf_;
   // TODO(klausw): update timestamp based on scheduling delay?
   page->Animator().ServiceScriptedAnimations(timestamp);
+
+  if (had_pending_vrdisplay_raf != pending_vrdisplay_raf_) {
+    LOG(INFO) << __FUNCTION__ << ": rAF fallback saved us! FIXME FIXME";
+  }
+
+  if (!pending_vrdisplay_raf_) {
+    // There wasn't any call to vrDisplay.rAF, so we won't be getting new
+    // frames from now on. TODO(klausw,crbug.com/716087): do something more
+    // useful here.
+    doc->AddConsoleMessage(ConsoleMessage::Create(
+        kRenderingMessageSource, kWarningMessageLevel,
+        "VRDisplay.requestAnimationFrame not called, presentation is broken."));

[bajones, 2017/04/27 22:02:46]

This seems drastic. o_O If the developer calls VRDisplay.requestAnimationFrame
again at some other point outside the rAF they will continue getting new frames,
right? If so, I would expect the warning should read more like "No VR frame
callback scheduled. Presentation will not resume until
VRDisplay.requestAnimationFrame is called."

[klausw, 2017/04/28 18:43:14]

I've changed it to a DVLOG. We should continue discussions here in the bug, IMHO
it shouldn't be legal to stop frame production while waiting for a timeout or
external event. (That's the only way it can resume presenting, right?)

[klausw, 2017/04/28 18:45:08]

To clarify, "the bug" in this context meant crbug.com/716087 as marked in the
TODO comment for identifying unrecoverable presentation issues, it's not one of
those addressed by these patches.

+  }
 }
 
 void VRDisplay::ProcessScheduledAnimations(double timestamp) {
+  DVLOG(2) << __FUNCTION__;
   // Check if we still have a valid context, the animation controller
   // or document may have disappeared since we scheduled this.
   Document* doc = this->GetDocument();
-  if (!doc || display_blurred_ || !scripted_animation_controller_)
+  if (!doc || display_blurred_) {
+    DVLOG(2) << __FUNCTION__ << ": early exit, doc=" << doc
+             << " display_blurred_=" << display_blurred_;
     return;
+  }
 
   TRACE_EVENT1("gpu", "VRDisplay::OnVSync", "frame", vr_frame_id_);
 
-  AutoReset<bool> animating(&in_animation_frame_, true);
-  pending_raf_ = false;
-
-  scripted_animation_controller_->ServiceScriptedAnimations(timestamp);
+  if (pending_vrdisplay_raf_ && scripted_animation_controller_) {
+    // Run the callback, making sure that in_animation_frame_ is only
+    // true for the vrDisplay rAF and not for a legacy window rAF
+    // that may be called later.
+    AutoReset<bool> animating(&in_animation_frame_, true);
+    pending_vrdisplay_raf_ = false;
+    scripted_animation_controller_->ServiceScriptedAnimations(timestamp);
+  }
 
   // For GVR, we shut down normal vsync processing during VR presentation.
   // Trigger any callbacks on window.rAF manually so that they run after
   // completing the vrDisplay.rAF processing.
   if (is_presenting_ && !capabilities_->hasExternalDisplay()) {
     Platform::Current()->CurrentThread()->GetWebTaskRunner()->PostTask(
         BLINK_FROM_HERE, WTF::Bind(&VRDisplay::ProcessScheduledWindowAnimations,
                                    WrapWeakPersistent(this), timestamp));
   }
 }
 
 void VRDisplay::OnVSync(device::mojom::blink::VRPosePtr pose,
                         mojo::common::mojom::blink::TimeDeltaPtr time,
                         int16_t frame_id,
                         device::mojom::blink::VRVSyncProvider::Status error) {
+  DVLOG(2) << __FUNCTION__;
   v_sync_connection_failed_ = false;
   switch (error) {
     case device::mojom::blink::VRVSyncProvider::Status::SUCCESS:
       break;
     case device::mojom::blink::VRVSyncProvider::Status::CLOSING:
       return;
   }
   pending_vsync_ = false;
 
   WTF::TimeDelta time_delta =
@@ skipping 14 matching lines @@
   // this is due to WaitForIncomingMethodCall receiving the OnVSync
   // but queueing it for immediate execution since it doesn't match
   // the interface being waited on.
   Platform::Current()->CurrentThread()->GetWebTaskRunner()->PostTask(
       BLINK_FROM_HERE,
       WTF::Bind(&VRDisplay::ProcessScheduledAnimations,
                 WrapWeakPersistent(this), timebase_ + time_delta.InSecondsF()));
 }
 
 void VRDisplay::ConnectVSyncProvider() {
-  if (!navigator_vr_->IsFocused() || vr_v_sync_provider_.is_bound())
+  DVLOG(1) << __FUNCTION__
+           << ": IsPresentationFocused()=" << IsPresentationFocused()
+           << " vr_v_sync_provider_.is_bound()="
+           << vr_v_sync_provider_.is_bound();
+  if (!IsPresentationFocused() || vr_v_sync_provider_.is_bound())
     return;
   display_->GetVRVSyncProvider(mojo::MakeRequest(&vr_v_sync_provider_));
   vr_v_sync_provider_.set_connection_error_handler(ConvertToBaseCallback(
       WTF::Bind(&VRDisplay::OnVSyncConnectionError, WrapWeakPersistent(this))));
-  if (pending_raf_ && !display_blurred_) {
+  if (pending_vrdisplay_raf_ && !display_blurred_) {
     pending_vsync_ = true;
     vr_v_sync_provider_->GetVSync(ConvertToBaseCallback(
         WTF::Bind(&VRDisplay::OnVSync, WrapWeakPersistent(this))));
   }
 }
 
 void VRDisplay::OnVSyncConnectionError() {
   vr_v_sync_provider_.reset();
   if (v_sync_connection_failed_)
     return;
@@ skipping 28 matching lines @@
 }
 
 bool VRDisplay::HasPendingActivity() const {
   // Prevent V8 from garbage collecting the wrapper object if there are
   // event listeners attached to it.
   return GetExecutionContext() && HasEventListeners();
 }
 
 void VRDisplay::FocusChanged() {
   // TODO(mthiesse): Blur/focus the display.
+  DVLOG(1) << __FUNCTION__;
   vr_v_sync_provider_.reset();
   ConnectVSyncProvider();
 }
 
 DEFINE_TRACE(VRDisplay) {
   EventTargetWithInlineData::Trace(visitor);
   ContextLifecycleObserver::Trace(visitor);
   visitor->Trace(navigator_vr_);
   visitor->Trace(capabilities_);
   visitor->Trace(stage_parameters_);
   visitor->Trace(eye_parameters_left_);
   visitor->Trace(eye_parameters_right_);
   visitor->Trace(layer_);
   visitor->Trace(rendering_context_);
   visitor->Trace(scripted_animation_controller_);
   visitor->Trace(pending_present_resolvers_);
 }
 
 }  // namespace blink