diff options
author | TreeHugger Robot <treehugger-gerrit@google.com> | 2017-09-20 23:55:09 +0000 |
---|---|---|
committer | Android (Google) Code Review <android-gerrit@google.com> | 2017-09-20 23:55:09 +0000 |
commit | d3da6150846550930b823863090559e5f8251659 (patch) | |
tree | 6880828911d5af8490bb779fd017dd1f6ccd67c4 | |
parent | f14e953f31cfbbe2457fa3098f9a464843d59318 (diff) | |
parent | b3732f08c0655998b2f31c76aac8595a343b511e (diff) | |
download | native-d3da6150846550930b823863090559e5f8251659.tar.gz |
Merge "Deal with unreliable VSYNC signals due to scheduler." into oc-mr1-dev
-rw-r--r-- | libs/vr/libvrflinger/display_manager_service.cpp | 1 | ||||
-rw-r--r-- | libs/vr/libvrflinger/display_service.cpp | 2 | ||||
-rw-r--r-- | libs/vr/libvrflinger/hardware_composer.cpp | 238 | ||||
-rw-r--r-- | libs/vr/libvrflinger/hardware_composer.h | 26 | ||||
-rw-r--r-- | libs/vr/libvrflinger/vr_flinger.cpp | 6 | ||||
-rw-r--r-- | libs/vr/libvrflinger/vsync_service.cpp | 1 |
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*>(×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<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); |