From: Corey Tabaka Date: Sat, 16 Sep 2017 07:58:54 +0000 (-0700) Subject: Deal with unreliable VSYNC signals due to scheduler. X-Git-Tag: android-x86-8.1-r1~29^2~1^2 X-Git-Url: http://git.osdn.net/view?a=commitdiff_plain;h=b3732f08c0655998b2f31c76aac8595a343b511e;p=android-x86%2Fframeworks-native.git Deal with unreliable VSYNC signals due to scheduler. We see two sources of scheduler jank when waiting for VSYNC: - A kernfs issue that wakes up threads using a normal priority work queue that may be delayed or have other work on it. - The VSYNC callback from HWC is handled by a normal priority HwBinder thread that may be delayed by other work. Change the VrFlinger frame post thread to use an absolute timer- based dead reckoning loop. VSYNC timestamps from the display driver are reliable, even if the delivery of the value takes time. Predict the VSYNC time into the future based on the last known VSYNC time. If we see that VSYNC has not been signaled by the time we need to post a frame to HWC we assume that the driver and/or HWC was delayed so much that the previous frame is still pending and skip the upcoming frame to avoid double stuffing the driver. Bug: 65064949 Test: Extensive system tests and systraces. See bug for details. Change-Id: Iae6c4173b8eac1d179adc3fc8004d3d475b3f156 --- 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 DisplayManagerService::HandleMessage(pdx::Message& message) { + ATRACE_NAME("DisplayManagerService::HandleMessage"); auto channel = std::static_pointer_cast(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 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( 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 #include #include +#include #include #include #include #include #include #include +#include #include #include #include @@ -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 + TraceArgs(const char* format, Args&&... args) { + std::array buffer; + snprintf(buffer.data(), buffer.size(), format, std::forward(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(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 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 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 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 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 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 HardwareComposer::ComposerCallback::onRefresh( Return HardwareComposer::ComposerCallback::onVsync(Hwc2::Display display, int64_t timestamp) { - if (display == HWC_DISPLAY_PRIMARY) { - std::lock_guard 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 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 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=". + std::array 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(×tamp)); + 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 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 onHotplug(Hwc2::Display display, Connection conn) override; hardware::Return onRefresh(Hwc2::Display display) override; hardware::Return onVsync(Hwc2::Display display, int64_t timestamp) override; - const pdx::LocalHandle& GetVsyncEventFd() const; - int64_t GetVsyncTime(); + + pdx::Status 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 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 WaitForVSync(); + pdx::Status 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("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 VSyncService::HandleMessage(pdx::Message& message) { + ATRACE_NAME("VSyncService::HandleMessage"); switch (message.GetOp()) { case VSyncProtocol::Wait::Opcode: AddWaiter(message);