SF: add trace points to debug 4ms jank
Bug: 346503493
Test: manual
Flag: EXEMPT logging
Change-Id: Ia2afef930b19a0833a43fe1c6cd23edaf58466c3
diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
index 6e36f02..ff360b7 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
@@ -458,7 +458,8 @@
Duration VSyncPredictor::ensureMinFrameDurationIsKept(TimePoint expectedPresentTime,
TimePoint lastConfirmedPresentTime) {
- SFTRACE_CALL();
+ SFTRACE_FORMAT("%s mNumVsyncsForFrame=%d mPastExpectedPresentTimes.size()=%zu", __func__,
+ mNumVsyncsForFrame, mPastExpectedPresentTimes.size());
if (mNumVsyncsForFrame <= 1) {
return 0ns;
@@ -470,12 +471,8 @@
auto prev = lastConfirmedPresentTime.ns();
for (auto& current : mPastExpectedPresentTimes) {
- if (CC_UNLIKELY(mTraceOn)) {
- SFTRACE_FORMAT_INSTANT("current %.2f past last signaled fence",
- static_cast<float>(current.ns() -
- lastConfirmedPresentTime.ns()) /
- 1e6f);
- }
+ SFTRACE_FORMAT_INSTANT("current %.2f past last signaled fence",
+ static_cast<float>(current.ns() - prev) / 1e6f);
const auto minPeriodViolation = current.ns() - prev + threshold < minFramePeriod.ns();
if (minPeriodViolation) {
@@ -522,11 +519,9 @@
const auto front = mPastExpectedPresentTimes.front().ns();
const bool frontIsBeforeConfirmed = front < lastConfirmedPresentTime.ns() + threshold;
if (frontIsBeforeConfirmed) {
- if (CC_UNLIKELY(mTraceOn)) {
- SFTRACE_FORMAT_INSTANT("Discarding old vsync - %.2f before last signaled fence",
- static_cast<float>(lastConfirmedPresentTime.ns() - front) /
- 1e6f);
- }
+ SFTRACE_FORMAT_INSTANT("Discarding old vsync - %.2f before last signaled fence",
+ static_cast<float>(lastConfirmedPresentTime.ns() - front) /
+ 1e6f);
mPastExpectedPresentTimes.pop_front();
} else {
break;
diff --git a/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp b/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp
index 4f16130..5019949 100644
--- a/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp
+++ b/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp
@@ -31,6 +31,7 @@
std::pair<bool /* wouldBackpressure */, FrameTarget::PresentFence>
FrameTarget::expectedSignaledPresentFence(Period vsyncPeriod, Period minFramePeriod) const {
+ SFTRACE_CALL();
if (!FlagManager::getInstance().allow_n_vsyncs_in_targeter()) {
const size_t i = static_cast<size_t>(targetsVsyncsAhead<2>(minFramePeriod));
return {true, mPresentFencesLegacy[i]};
@@ -40,17 +41,28 @@
auto expectedPresentTime = mExpectedPresentTime;
for (size_t i = mPresentFences.size(); i != 0; --i) {
const auto& fence = mPresentFences[i - 1];
+ SFTRACE_FORMAT_INSTANT("fence at idx: %zu expectedPresentTime in %.2f", i - 1,
+ ticks<std::milli, float>(fence.expectedPresentTime -
+ TimePoint::now()));
if (fence.expectedPresentTime + minFramePeriod < expectedPresentTime - vsyncPeriod / 2) {
+ SFTRACE_FORMAT_INSTANT("would not backpressure");
wouldBackpressure = false;
}
if (fence.expectedPresentTime <= mFrameBeginTime) {
+ SFTRACE_FORMAT_INSTANT("fence at idx: %zu is %.2f before frame begin "
+ "(wouldBackpressure=%s)",
+ i - 1,
+ ticks<std::milli, float>(mFrameBeginTime -
+ fence.expectedPresentTime),
+ wouldBackpressure ? "true" : "false");
return {wouldBackpressure, fence};
}
expectedPresentTime = fence.expectedPresentTime;
}
+ SFTRACE_FORMAT_INSTANT("No fence found");
return {wouldBackpressure, PresentFence{}};
}
@@ -154,6 +166,12 @@
if (pastPresentTime < 0) return false;
mLastSignaledFrameTime = {.signalTime = TimePoint::fromNs(pastPresentTime),
.expectedPresentTime = fence.expectedPresentTime};
+ SFTRACE_FORMAT_INSTANT("LastSignaledFrameTime expectedPresentTime %.2f ago, signalTime "
+ "%.2f ago",
+ ticks<std::milli, float>(mLastSignaledFrameTime.expectedPresentTime -
+ TimePoint::now()),
+ ticks<std::milli, float>(mLastSignaledFrameTime.signalTime -
+ TimePoint::now()));
const nsecs_t frameMissedSlop = vsyncPeriod.ns() / 2;
return lastScheduledPresentTime.ns() < pastPresentTime - frameMissedSlop;
}();