Merge "Deal with unreliable VSYNC signals due to scheduler." into oc-mr1-dev

6 files changed, 215 insertions, 59 deletions

diff --git a/libs/vr/libvrflinger/display_manager_service.cpp b/libs/vr/libvrflinger/display_manager_service.cpp
index 40396b90c5..ef8cca38dd 100644
--- a/libs/vr/libvrflinger/display_manager_service.cpp
+++ b/libs/vr/libvrflinger/display_manager_service.cpp
@@ -65,6 +65,7 @@ void DisplayManagerService::OnChannelClose(
 }
 
 pdx::Status<void> DisplayManagerService::HandleMessage(pdx::Message& message) {
+  ATRACE_NAME("DisplayManagerService::HandleMessage");
   auto channel = std::static_pointer_cast<DisplayManager>(message.GetChannel());
 
   switch (message.GetOp()) {
diff --git a/libs/vr/libvrflinger/display_service.cpp b/libs/vr/libvrflinger/display_service.cpp
index 10abc5efa3..ac68a5e3a4 100644
--- a/libs/vr/libvrflinger/display_service.cpp
+++ b/libs/vr/libvrflinger/display_service.cpp
@@ -124,6 +124,8 @@ void DisplayService::OnChannelClose(pdx::Message& message,
 // surface-specific messages to the per-instance handlers.
 Status<void> DisplayService::HandleMessage(pdx::Message& message) {
   ALOGD_IF(TRACE, "DisplayService::HandleMessage: opcode=%d", message.GetOp());
+  ATRACE_NAME("DisplayService::HandleMessage");
+
   switch (message.GetOp()) {
     case DisplayProtocol::GetMetrics::Opcode:
       DispatchRemoteMethod<DisplayProtocol::GetMetrics>(
diff --git a/libs/vr/libvrflinger/hardware_composer.cpp b/libs/vr/libvrflinger/hardware_composer.cpp
index 0bf1d2b5a7..de6477b1ef 100644
--- a/libs/vr/libvrflinger/hardware_composer.cpp
+++ b/libs/vr/libvrflinger/hardware_composer.cpp
@@ -5,12 +5,14 @@
 #include <fcntl.h>
 #include <log/log.h>
 #include <poll.h>
+#include <stdint.h>
 #include <sync/sync.h>
 #include <sys/eventfd.h>
 #include <sys/prctl.h>
 #include <sys/resource.h>
 #include <sys/system_properties.h>
 #include <sys/timerfd.h>
+#include <sys/types.h>
 #include <time.h>
 #include <unistd.h>
 #include <utils/Trace.h>
@@ -30,7 +32,9 @@
 
 using android::hardware::Return;
 using android::hardware::Void;
+using android::pdx::ErrorStatus;
 using android::pdx::LocalHandle;
+using android::pdx::Status;
 using android::pdx::rpc::EmptyVariant;
 using android::pdx::rpc::IfAnyOf;
 
@@ -82,6 +86,29 @@ bool SetThreadPolicy(const std::string& scheduler_class,
   return true;
 }
 
+// Utility to generate scoped tracers with arguments.
+// TODO(eieio): Move/merge this into utils/Trace.h?
+class TraceArgs {
+ public:
+  template <typename... Args>
+  TraceArgs(const char* format, Args&&... args) {
+    std::array<char, 1024> buffer;
+    snprintf(buffer.data(), buffer.size(), format, std::forward<Args>(args)...);
+    atrace_begin(ATRACE_TAG, buffer.data());
+  }
+
+  ~TraceArgs() { atrace_end(ATRACE_TAG); }
+
+ private:
+  TraceArgs(const TraceArgs&) = delete;
+  void operator=(const TraceArgs&) = delete;
+};
+
+// Macro to define a scoped tracer with arguments. Uses PASTE(x, y) macro
+// defined in utils/Trace.h.
+#define TRACE_FORMAT(format, ...) \
+  TraceArgs PASTE(__tracer, __LINE__) { format, ##__VA_ARGS__ }
+
 }  // anonymous namespace
 
 HardwareComposer::HardwareComposer()
@@ -411,14 +438,12 @@ void HardwareComposer::PostLayers() {
     retire_fence_fds_.erase(retire_fence_fds_.begin());
   }
 
-  const bool is_frame_pending = IsFramePendingInDriver();
   const bool is_fence_pending = static_cast<int32_t>(retire_fence_fds_.size()) >
                                 post_thread_config_.allowed_pending_fence_count;
 
-  if (is_fence_pending || is_frame_pending) {
+  if (is_fence_pending) {
     ATRACE_INT("frame_skip_count", ++frame_skip_count_);
 
-    ALOGW_IF(is_frame_pending, "Warning: frame already queued, dropping frame");
     ALOGW_IF(is_fence_pending,
              "Warning: dropping a frame to catch up with HWC (pending = %zd)",
              retire_fence_fds_.size());
@@ -587,18 +612,28 @@ int HardwareComposer::PostThreadPollInterruptible(
   }
 }
 
+Status<int64_t> HardwareComposer::GetVSyncTime() {
+  auto status = composer_callback_->GetVsyncTime(HWC_DISPLAY_PRIMARY);
+  ALOGE_IF(!status,
+           "HardwareComposer::GetVSyncTime: Failed to get vsync timestamp: %s",
+           status.GetErrorMessage().c_str());
+  return status;
+}
+
 // Waits for the next vsync and returns the timestamp of the vsync event. If
 // vsync already passed since the last call, returns the latest vsync timestamp
 // instead of blocking.
-int HardwareComposer::WaitForVSync(int64_t* timestamp) {
-  int error = PostThreadPollInterruptible(composer_callback_->GetVsyncEventFd(),
-                                          POLLIN, /*timeout_ms*/ 1000);
-  if (error == kPostThreadInterrupted || error < 0) {
+Status<int64_t> HardwareComposer::WaitForVSync() {
+  const int64_t predicted_vsync_time =
+      last_vsync_timestamp_ +
+      display_metrics_.vsync_period_ns * vsync_prediction_interval_;
+  const int error = SleepUntil(predicted_vsync_time);
+  if (error < 0) {
+    ALOGE("HardwareComposer::WaifForVSync:: Failed to sleep: %s",
+          strerror(-error));
     return error;
-  } else {
-    *timestamp = composer_callback_->GetVsyncTime();
-    return 0;
   }
+  return {predicted_vsync_time};
 }
 
 int HardwareComposer::SleepUntil(int64_t wakeup_timestamp) {
@@ -704,26 +739,41 @@ void HardwareComposer::PostThread() {
         thread_policy_setup =
             SetThreadPolicy("graphics:high", "/system/performance");
       }
+
+      // Initialize the last vsync timestamp with the current time. The
+      // predictor below uses this time + the vsync interval in absolute time
+      // units for the initial delay. Once the driver starts reporting vsync the
+      // predictor will sync up with the real vsync.
+      last_vsync_timestamp_ = GetSystemClockNs();
     }
 
     int64_t vsync_timestamp = 0;
     {
-      std::array<char, 128> buf;
-      snprintf(buf.data(), buf.size(), "wait_vsync|vsync=%d|",
-               vsync_count_ + 1);
-      ATRACE_NAME(buf.data());
+      TRACE_FORMAT("wait_vsync|vsync=%u;last_timestamp=%" PRId64
+                   ";prediction_interval=%d|",
+                   vsync_count_ + 1, last_vsync_timestamp_,
+                   vsync_prediction_interval_);
 
-      const int error = WaitForVSync(&vsync_timestamp);
+      auto status = WaitForVSync();
       ALOGE_IF(
-          error < 0,
+          !status,
           "HardwareComposer::PostThread: Failed to wait for vsync event: %s",
-          strerror(-error));
-      // Don't bother processing this frame if a pause was requested
-      if (error == kPostThreadInterrupted)
+          status.GetErrorMessage().c_str());
+
+      // If there was an error either sleeping was interrupted due to pausing or
+      // there was an error getting the latest timestamp.
+      if (!status)
         continue;
+
+      // Predicted vsync timestamp for this interval. This is stable because we
+      // use absolute time for the wakeup timer.
+      vsync_timestamp = status.get();
     }
 
-    ++vsync_count_;
+    // Advance the vsync counter only if the system is keeping up with hardware
+    // vsync to give clients an indication of the delays.
+    if (vsync_prediction_interval_ == 1)
+      ++vsync_count_;
 
     const bool layer_config_changed = UpdateLayerConfig();
 
@@ -773,6 +823,38 @@ void HardwareComposer::PostThread() {
       }
     }
 
+    {
+      auto status = GetVSyncTime();
+      if (!status) {
+        ALOGE("HardwareComposer::PostThread: Failed to get VSYNC time: %s",
+              status.GetErrorMessage().c_str());
+      }
+
+      // If we failed to read vsync there might be a problem with the driver.
+      // Since there's nothing we can do just behave as though we didn't get an
+      // updated vsync time and let the prediction continue.
+      const int64_t current_vsync_timestamp =
+          status ? status.get() : last_vsync_timestamp_;
+
+      const bool vsync_delayed =
+          last_vsync_timestamp_ == current_vsync_timestamp;
+      ATRACE_INT("vsync_delayed", vsync_delayed);
+
+      // If vsync was delayed advance the prediction interval and allow the
+      // fence logic in PostLayers() to skip the frame.
+      if (vsync_delayed) {
+        ALOGW(
+            "HardwareComposer::PostThread: VSYNC timestamp did not advance "
+            "since last frame: timestamp=%" PRId64 " prediction_interval=%d",
+            current_vsync_timestamp, vsync_prediction_interval_);
+        vsync_prediction_interval_++;
+      } else {
+        // We have an updated vsync timestamp, reset the prediction interval.
+        last_vsync_timestamp_ = current_vsync_timestamp;
+        vsync_prediction_interval_ = 1;
+      }
+    }
+
     PostLayers();
   }
 }
@@ -860,14 +942,28 @@ void HardwareComposer::SetBacklightBrightness(int brightness) {
   }
 }
 
-HardwareComposer::ComposerCallback::ComposerCallback() {
-  vsync_event_fd_.Reset(eventfd(0, EFD_CLOEXEC | EFD_NONBLOCK));
-  LOG_ALWAYS_FATAL_IF(!vsync_event_fd_, "Failed to create vsync event fd : %s",
-                      strerror(errno));
-}
-
 Return<void> HardwareComposer::ComposerCallback::onHotplug(
-    Hwc2::Display /*display*/, IComposerCallback::Connection /*conn*/) {
+    Hwc2::Display display, IComposerCallback::Connection /*conn*/) {
+  // See if the driver supports the vsync_event node in sysfs.
+  if (display < HWC_NUM_PHYSICAL_DISPLAY_TYPES &&
+      !displays_[display].driver_vsync_event_fd) {
+    std::array<char, 1024> buffer;
+    snprintf(buffer.data(), buffer.size(),
+             "/sys/class/graphics/fb%" PRIu64 "/vsync_event", display);
+    if (LocalHandle handle{buffer.data(), O_RDONLY}) {
+      ALOGI(
+          "HardwareComposer::ComposerCallback::onHotplug: Driver supports "
+          "vsync_event node for display %" PRIu64,
+          display);
+      displays_[display].driver_vsync_event_fd = std::move(handle);
+    } else {
+      ALOGI(
+          "HardwareComposer::ComposerCallback::onHotplug: Driver does not "
+          "support vsync_event node for display %" PRIu64,
+          display);
+    }
+  }
+
   return Void();
 }
 
@@ -878,29 +974,81 @@ Return<void> HardwareComposer::ComposerCallback::onRefresh(
 
 Return<void> HardwareComposer::ComposerCallback::onVsync(Hwc2::Display display,
                                                          int64_t timestamp) {
-  if (display == HWC_DISPLAY_PRIMARY) {
-    std::lock_guard<std::mutex> lock(vsync_mutex_);
-    vsync_time_ = timestamp;
-    int error = eventfd_write(vsync_event_fd_.Get(), 1);
-    LOG_ALWAYS_FATAL_IF(error != 0, "Failed writing to vsync event fd");
+  TRACE_FORMAT("vsync_callback|display=%" PRIu64 ";timestamp=%" PRId64 "|",
+               display, timestamp);
+  if (display < HWC_NUM_PHYSICAL_DISPLAY_TYPES) {
+    displays_[display].callback_vsync_timestamp = timestamp;
+  } else {
+    ALOGW(
+        "HardwareComposer::ComposerCallback::onVsync: Received vsync on "
+        "non-physical display: display=%" PRId64,
+        display);
   }
   return Void();
 }
 
-const pdx::LocalHandle& HardwareComposer::ComposerCallback::GetVsyncEventFd()
-    const {
-  return vsync_event_fd_;
-}
+Status<int64_t> HardwareComposer::ComposerCallback::GetVsyncTime(
+    Hwc2::Display display) {
+  if (display >= HWC_NUM_PHYSICAL_DISPLAY_TYPES) {
+    ALOGE(
+        "HardwareComposer::ComposerCallback::GetVsyncTime: Invalid physical "
+        "display requested: display=%" PRIu64,
+        display);
+    return ErrorStatus(EINVAL);
+  }
+
+  // See if the driver supports direct vsync events.
+  LocalHandle& event_fd = displays_[display].driver_vsync_event_fd;
+  if (!event_fd) {
+    // Fall back to returning the last timestamp returned by the vsync
+    // callback.
+    std::lock_guard<std::mutex> autolock(vsync_mutex_);
+    return displays_[display].callback_vsync_timestamp;
+  }
+
+  // When the driver supports the vsync_event sysfs node we can use it to
+  // determine the latest vsync timestamp, even if the HWC callback has been
+  // delayed.
+
+  // The driver returns data in the form "VSYNC=<timestamp ns>".
+  std::array<char, 32> data;
+  data.fill('\0');
+
+  // Seek back to the beginning of the event file.
+  int ret = lseek(event_fd.Get(), 0, SEEK_SET);
+  if (ret < 0) {
+    const int error = errno;
+    ALOGE(
+        "HardwareComposer::ComposerCallback::GetVsyncTime: Failed to seek "
+        "vsync event fd: %s",
+        strerror(error));
+    return ErrorStatus(error);
+  }
+
+  // Read the vsync event timestamp.
+  ret = read(event_fd.Get(), data.data(), data.size());
+  if (ret < 0) {
+    const int error = errno;
+    ALOGE_IF(error != EAGAIN,
+             "HardwareComposer::ComposerCallback::GetVsyncTime: Error "
+             "while reading timestamp: %s",
+             strerror(error));
+    return ErrorStatus(error);
+  }
+
+  int64_t timestamp;
+  ret = sscanf(data.data(), "VSYNC=%" PRIu64,
+               reinterpret_cast<uint64_t*>(&timestamp));
+  if (ret < 0) {
+    const int error = errno;
+    ALOGE(
+        "HardwareComposer::ComposerCallback::GetVsyncTime: Error while "
+        "parsing timestamp: %s",
+        strerror(error));
+    return ErrorStatus(error);
+  }
 
-int64_t HardwareComposer::ComposerCallback::GetVsyncTime() {
-  std::lock_guard<std::mutex> lock(vsync_mutex_);
-  eventfd_t event;
-  eventfd_read(vsync_event_fd_.Get(), &event);
-  LOG_ALWAYS_FATAL_IF(vsync_time_ < 0,
-                      "Attempt to read vsync time before vsync event");
-  int64_t return_val = vsync_time_;
-  vsync_time_ = -1;
-  return return_val;
+  return {timestamp};
 }
 
 Hwc2::Composer* Layer::composer_{nullptr};
diff --git a/libs/vr/libvrflinger/hardware_composer.h b/libs/vr/libvrflinger/hardware_composer.h
index 793c3e887c..8131e50989 100644
--- a/libs/vr/libvrflinger/hardware_composer.h
+++ b/libs/vr/libvrflinger/hardware_composer.h
@@ -142,9 +142,7 @@ class Layer {
   bool operator<(const Layer& other) const {
     return GetSurfaceId() < other.GetSurfaceId();
   }
-  bool operator<(int surface_id) const {
-    return GetSurfaceId() < surface_id;
-  }
+  bool operator<(int surface_id) const { return GetSurfaceId() < surface_id; }
 
   // Sets the composer instance used by all Layer instances.
   static void SetComposer(Hwc2::Composer* composer) { composer_ = composer; }
@@ -340,19 +338,23 @@ class HardwareComposer {
 
   class ComposerCallback : public Hwc2::IComposerCallback {
    public:
-    ComposerCallback();
+    ComposerCallback() = default;
     hardware::Return<void> onHotplug(Hwc2::Display display,
                                      Connection conn) override;
     hardware::Return<void> onRefresh(Hwc2::Display display) override;
     hardware::Return<void> onVsync(Hwc2::Display display,
                                    int64_t timestamp) override;
-    const pdx::LocalHandle& GetVsyncEventFd() const;
-    int64_t GetVsyncTime();
+
+    pdx::Status<int64_t> GetVsyncTime(Hwc2::Display display);
 
    private:
     std::mutex vsync_mutex_;
-    pdx::LocalHandle vsync_event_fd_;
-    int64_t vsync_time_ = -1;
+
+    struct Display {
+      pdx::LocalHandle driver_vsync_event_fd;
+      int64_t callback_vsync_timestamp{0};
+    };
+    std::array<Display, HWC_NUM_PHYSICAL_DISPLAY_TYPES> displays_;
   };
 
   HWC::Error Validate(hwc2_display_t display);
@@ -392,11 +394,10 @@ class HardwareComposer {
   // can be interrupted by a control thread. If interrupted, these calls return
   // kPostThreadInterrupted.
   int ReadWaitPPState();
-  int WaitForVSync(int64_t* timestamp);
+  pdx::Status<int64_t> WaitForVSync();
+  pdx::Status<int64_t> GetVSyncTime();
   int SleepUntil(int64_t wakeup_timestamp);
 
-  bool IsFramePendingInDriver() { return false; }
-
   // Reconfigures the layer stack if the display surfaces changed since the last
   // frame. Called only from the post thread.
   bool UpdateLayerConfig();
@@ -463,6 +464,9 @@ class HardwareComposer {
   // The timestamp of the last vsync.
   int64_t last_vsync_timestamp_ = 0;
 
+  // The number of vsync intervals to predict since the last vsync.
+  int vsync_prediction_interval_ = 1;
+
   // Vsync count since display on.
   uint32_t vsync_count_ = 0;
 
diff --git a/libs/vr/libvrflinger/vr_flinger.cpp b/libs/vr/libvrflinger/vr_flinger.cpp
index fcf94f0865..85dc586eae 100644
--- a/libs/vr/libvrflinger/vr_flinger.cpp
+++ b/libs/vr/libvrflinger/vr_flinger.cpp
@@ -64,9 +64,6 @@ bool VrFlinger::Init(Hwc2::Composer* hidl,
 
   ALOGI("Starting up VrFlinger...");
 
-  setpriority(PRIO_PROCESS, 0, android::PRIORITY_URGENT_DISPLAY);
-  set_sched_policy(0, SP_FOREGROUND);
-
   // We need to be able to create endpoints with full perms.
   umask(0000);
 
@@ -100,6 +97,9 @@ bool VrFlinger::Init(Hwc2::Composer* hidl,
     prctl(PR_SET_NAME, reinterpret_cast<unsigned long>("VrDispatch"), 0, 0, 0);
     ALOGI("Entering message loop.");
 
+    setpriority(PRIO_PROCESS, 0, android::PRIORITY_URGENT_DISPLAY);
+    set_sched_policy(0, SP_FOREGROUND);
+
     int ret = dispatcher_->EnterDispatchLoop();
     if (ret < 0) {
       ALOGE("Dispatch loop exited because: %s\n", strerror(-ret));
diff --git a/libs/vr/libvrflinger/vsync_service.cpp b/libs/vr/libvrflinger/vsync_service.cpp
index 3098b43318..fdeb899f66 100644
--- a/libs/vr/libvrflinger/vsync_service.cpp
+++ b/libs/vr/libvrflinger/vsync_service.cpp
@@ -110,6 +110,7 @@ void VSyncService::UpdateClients() {
 }
 
 pdx::Status<void> VSyncService::HandleMessage(pdx::Message& message) {
+  ATRACE_NAME("VSyncService::HandleMessage");
   switch (message.GetOp()) {
     case VSyncProtocol::Wait::Opcode:
       AddWaiter(message);