libhwc2.1: add trace for setActiveConfigWithConstraints()

HWC adds trace for setActiveConfigWithConstraints() to
show the desire time and isConfigEnabled()

Bug: 280460655
Test: run vts VtsHalGraphicsComposerV2_4TargetTest -t Per
Instance/GraphicsComposerHidlTest#setActiveConfigWith
Constraints_Delayed/0_default

Change-Id: I6796d054f463982050b48a70b9e4300d1ddc9ac4

3 files changed, 44 insertions, 27 deletions

diff --git a/libhwc2.1/ExynosHWCDebug.h b/libhwc2.1/ExynosHWCDebug.h
index 37d96fd..8bc6092 100644
--- a/libhwc2.1/ExynosHWCDebug.h
+++ b/libhwc2.1/ExynosHWCDebug.h
@@ -166,4 +166,12 @@ public:
                      value);                                                                  \
     }
 
+#define DISPLAY_LOGD_AND_ATRACE_NAME(debugFlag, fmt, ...)                    \
+    if (hwcCheckDebugMessages(debugFlag) || CC_UNLIKELY(ATRACE_ENABLED())) { \
+        String8 log;                                                         \
+        log.appendFormat((fmt), ##__VA_ARGS__);                              \
+        DISPLAY_LOGD(debugFlag, "%s", log.string());                         \
+        if (CC_UNLIKELY(ATRACE_ENABLED())) ATRACE_NAME(log.string());        \
+    }
+
 #endif
diff --git a/libhwc2.1/libdevice/ExynosDisplay.cpp b/libhwc2.1/libdevice/ExynosDisplay.cpp
index a29927d..52e9faa 100644
--- a/libhwc2.1/libdevice/ExynosDisplay.cpp
+++ b/libhwc2.1/libdevice/ExynosDisplay.cpp
@@ -4077,12 +4077,12 @@ int32_t ExynosDisplay::setActiveConfigWithConstraints(hwc2_config_t config,
 {
     DISPLAY_ATRACE_CALL();
     Mutex::Autolock lock(mDisplayMutex);
+    const nsecs_t current = systemTime(SYSTEM_TIME_MONOTONIC);
+    const nsecs_t diffMs = ns2ms(vsyncPeriodChangeConstraints->desiredTimeNanos - current);
+    DISPLAY_LOGD(eDebugDisplayConfig, "config(%d->%d), seamless(%d), diff(%" PRId64 ")",
+                 mActiveConfig, config, vsyncPeriodChangeConstraints->seamlessRequired, diffMs);
 
-    DISPLAY_LOGD(eDebugDisplayConfig,
-                 "config(%d), seamless(%d), "
-                 "desiredTime(%" PRId64 ")",
-                 config, vsyncPeriodChangeConstraints->seamlessRequired,
-                 vsyncPeriodChangeConstraints->desiredTimeNanos);
+    if (CC_UNLIKELY(ATRACE_ENABLED())) ATRACE_NAME(("diff:" + std::to_string(diffMs)).c_str());
 
     if (isBadConfig(config)) return HWC2_ERROR_BAD_CONFIG;
 
@@ -4134,6 +4134,7 @@ int32_t ExynosDisplay::setActiveConfigWithConstraints(hwc2_config_t config,
     mConfigRequestState = hwc_request_state_t::SET_CONFIG_STATE_PENDING;
     mVsyncPeriodChangeConstraints = *vsyncPeriodChangeConstraints;
     mDesiredConfig = config;
+    DISPLAY_ATRACE_INT("Pending ActiveConfig", mDesiredConfig);
 
     calculateTimeline(config, vsyncPeriodChangeConstraints, outTimeline);
 
@@ -4346,6 +4347,7 @@ int32_t ExynosDisplay::doDisplayConfigInternal(hwc2_config_t config) {
 
 int32_t ExynosDisplay::doDisplayConfigPostProcess(ExynosDevice *dev)
 {
+    ATRACE_CALL();
     uint64_t current = systemTime(SYSTEM_TIME_MONOTONIC);
 
     int64_t actualChangeTime = 0;
@@ -4361,10 +4363,12 @@ int32_t ExynosDisplay::doDisplayConfigPostProcess(ExynosDevice *dev)
         DISPLAY_LOGD(eDebugDisplayConfig, "Request setActiveConfig");
         needSetActiveConfig = true;
         DISPLAY_ATRACE_INT("Pending ActiveConfig", 0);
+        DISPLAY_ATRACE_INT64("TimeToChangeConfig", 0);
     } else {
         DISPLAY_LOGD(eDebugDisplayConfig, "setActiveConfig still pending (mDesiredConfig %d)",
                      mDesiredConfig);
         DISPLAY_ATRACE_INT("Pending ActiveConfig", mDesiredConfig);
+        DISPLAY_ATRACE_INT64("TimeToChangeConfig", ns2ms(actualChangeTime - current));
     }
 
     if (needSetActiveConfig) {
diff --git a/libhwc2.1/libmaindisplay/ExynosPrimaryDisplay.cpp b/libhwc2.1/libmaindisplay/ExynosPrimaryDisplay.cpp
index fb925db..4f2adad 100644
--- a/libhwc2.1/libmaindisplay/ExynosPrimaryDisplay.cpp
+++ b/libhwc2.1/libmaindisplay/ExynosPrimaryDisplay.cpp
@@ -539,6 +539,8 @@ bool ExynosPrimaryDisplay::isConfigSettingEnabled() {
 }
 
 void ExynosPrimaryDisplay::enableConfigSetting(bool en) {
+    DISPLAY_ATRACE_INT("ConfigSettingDisabled", !en);
+
     if (!en) {
         mConfigSettingDisabled = true;
         mConfigSettingDisabledTimestamp = systemTime(SYSTEM_TIME_MONOTONIC);
@@ -761,6 +763,7 @@ void ExynosPrimaryDisplay::setLHBMRefreshRateThrottle(const uint32_t delayMs) {
     if (delayMs) {
         // make new throttle take effect
         mLastRefreshRateAppliedNanos = systemTime(SYSTEM_TIME_MONOTONIC);
+        DISPLAY_ATRACE_INT64("LastRefreshRateAppliedMs", ns2ms(mLastRefreshRateAppliedNanos));
     }
 
     setRefreshRateThrottleNanos(std::chrono::duration_cast<std::chrono::nanoseconds>(
@@ -968,6 +971,7 @@ int ExynosPrimaryDisplay::setMinIdleRefreshRate(const int fps) {
 
 int ExynosPrimaryDisplay::setRefreshRateThrottleNanos(const int64_t delayNanos,
                                                       const VrrThrottleRequester requester) {
+    ATRACE_CALL();
     ALOGI("%s() requester(%u) set delay to %" PRId64 "ns", __func__, toUnderlying(requester),
           delayNanos);
     if (delayNanos < 0) {
@@ -985,12 +989,12 @@ int ExynosPrimaryDisplay::setRefreshRateThrottleNanos(const int64_t delayNanos,
         }
     }
 
+    DISPLAY_ATRACE_INT64("RefreshRateDelay", ns2ms(maxDelayNanos));
     if (mRefreshRateDelayNanos == maxDelayNanos) {
         return NO_ERROR;
     }
 
     mRefreshRateDelayNanos = maxDelayNanos;
-
     return setDisplayIdleDelayNanos(mRefreshRateDelayNanos, DispIdleTimerRequester::VRR_THROTTLE);
 }
 
@@ -1015,6 +1019,7 @@ void ExynosPrimaryDisplay::dump(String8 &result) {
 void ExynosPrimaryDisplay::calculateTimeline(
         hwc2_config_t config, hwc_vsync_period_change_constraints_t *vsyncPeriodChangeConstraints,
         hwc_vsync_period_change_timeline_t *outTimeline) {
+    ATRACE_CALL();
     int64_t desiredUpdateTime = vsyncPeriodChangeConstraints->desiredTimeNanos;
     const int64_t origDesiredUpdateTime = desiredUpdateTime;
     const int64_t threshold = mRefreshRateDelayNanos;
@@ -1042,31 +1047,30 @@ void ExynosPrimaryDisplay::calculateTimeline(
     getConfigAppliedTime(mVsyncPeriodChangeConstraints.desiredTimeNanos, actualChangeTime,
                          outTimeline->newVsyncAppliedTimeNanos, outTimeline->refreshTimeNanos);
 
-    if (isDelayed) {
-        DISPLAY_LOGD(eDebugDisplayConfig,
-                     "requested config : %d(%d)->%d(%d) is delayed! "
-                     "delta %" PRId64 ", delay %" PRId64 ", threshold %" PRId64 ", "
-                     "desired %" PRId64 "->%" PRId64 ", newVsyncAppliedTimeNanos : %" PRId64
-                     ", refreshTimeNanos:%" PRId64,
-                     mActiveConfig, mDisplayConfigs[mActiveConfig].vsyncPeriod, config,
-                     mDisplayConfigs[config].vsyncPeriod, lastUpdateDelta,
-                     threshold - lastUpdateDelta, threshold, origDesiredUpdateTime,
-                     mVsyncPeriodChangeConstraints.desiredTimeNanos,
-                     outTimeline->newVsyncAppliedTimeNanos, outTimeline->refreshTimeNanos);
-    } else {
-        DISPLAY_LOGD(eDebugDisplayConfig,
-                     "requested config : %d(%d)->%d(%d), "
-                     "lastUpdateDelta %" PRId64 ", threshold %" PRId64 ", "
-                     "desired %" PRId64 ", newVsyncAppliedTimeNanos : %" PRId64 "",
-                     mActiveConfig, mDisplayConfigs[mActiveConfig].vsyncPeriod, config,
-                     mDisplayConfigs[config].vsyncPeriod, lastUpdateDelta, threshold,
-                     mVsyncPeriodChangeConstraints.desiredTimeNanos,
-                     outTimeline->newVsyncAppliedTimeNanos);
-    }
+    const nsecs_t now = systemTime(SYSTEM_TIME_MONOTONIC);
+    DISPLAY_LOGD_AND_ATRACE_NAME(eDebugDisplayConfig,
+                                 "requested config : %d(%d)->%d(%d), isDelay:%d,"
+                                 " delta %" PRId64 ", delay %" PRId64 ", threshold %" PRId64 ", "
+                                 "now:%" PRId64 ", desired %" PRId64 "->%" PRId64
+                                 ", newVsyncAppliedTimeNanos : %" PRId64
+                                 ", refreshTimeNanos:%" PRId64
+                                 ", mLastRefreshRateAppliedNanos:%" PRId64,
+                                 mActiveConfig, mDisplayConfigs[mActiveConfig].vsyncPeriod, config,
+                                 mDisplayConfigs[config].vsyncPeriod, isDelayed,
+                                 ns2ms(lastUpdateDelta), ns2ms(threshold - lastUpdateDelta),
+                                 ns2ms(threshold), ns2ms(now), ns2ms(origDesiredUpdateTime),
+                                 ns2ms(mVsyncPeriodChangeConstraints.desiredTimeNanos),
+                                 ns2ms(outTimeline->newVsyncAppliedTimeNanos),
+                                 ns2ms(outTimeline->refreshTimeNanos),
+                                 ns2ms(mLastRefreshRateAppliedNanos));
+
+    const int64_t diffMs = ns2ms(outTimeline->refreshTimeNanos - now);
+    DISPLAY_ATRACE_INT64("TimeToChangeConfig", diffMs);
 }
 
 void ExynosPrimaryDisplay::updateAppliedActiveConfig(const hwc2_config_t newConfig,
                                                      const int64_t ts) {
+    ATRACE_CALL();
     if (mAppliedActiveConfig == 0 ||
         getDisplayVsyncPeriodFromConfig(mAppliedActiveConfig) !=
                 getDisplayVsyncPeriodFromConfig(newConfig)) {
@@ -1075,6 +1079,7 @@ void ExynosPrimaryDisplay::updateAppliedActiveConfig(const hwc2_config_t newConf
                      " -> %" PRIu64 ")",
                      __func__, mAppliedActiveConfig, newConfig, mLastRefreshRateAppliedNanos, ts);
         mLastRefreshRateAppliedNanos = ts;
+        DISPLAY_ATRACE_INT64("LastRefreshRateAppliedMs", ns2ms(mLastRefreshRateAppliedNanos));
     }
 
     mAppliedActiveConfig = newConfig;