Merge "[TimeStats] Track per-frame CPU time." (2f9fe8d1) · Commits · e / os / android_frameworks_native

services/surfaceflinger/SurfaceFlinger.cpp

+11 −0

Original line number	Diff line number	Diff line
		@@ -1610,6 +1610,7 @@ void SurfaceFlinger::onMessageReceived(int32_t what) NO_THREAD_SAFETY_ANALYSIS {
		ATRACE_CALL();
		switch (what) {
		case MessageQueue::INVALIDATE: {
		const nsecs_t frameStart = systemTime();
		// calculate the expected present time once and use the cached
		// value throughout this frame to make sure all layers are
		// seeing this same value.
		@@ -1674,6 +1675,13 @@ void SurfaceFlinger::onMessageReceived(int32_t what) NO_THREAD_SAFETY_ANALYSIS {
		// Signal a refresh if a transaction modified the window state,
		// a new buffer was latched, or if HWC has requested a full
		// repaint
		if (mFrameStartTime <= 0) {
		// We should only use the time of the first invalidate
		// message that signals a refresh as the beginning of the
		// frame. Otherwise the real frame time will be
		// underestimated.
		mFrameStartTime = frameStart;
		}
		signalRefresh();
		}
		break;
		@@ -1752,6 +1760,9 @@ void SurfaceFlinger::handleMessageRefresh() {
		mGeometryInvalid = false;

		mCompositionEngine->present(refreshArgs);
		mTimeStats->recordFrameDuration(mFrameStartTime, systemTime());
		// Reset the frame start time now that we've recorded this frame.
		mFrameStartTime = 0;

		postFrame();
		postComposition();

+3 −0

Original line number	Diff line number	Diff line
		@@ -1152,6 +1152,9 @@ private:
		bool mPendingSyncInputWindows GUARDED_BY(mStateLock);
		Hwc2::impl::PowerAdvisor mPowerAdvisor;

		// This should only be accessed on the main thread.
		nsecs_t mFrameStartTime = 0;

		std::unique_ptr<RefreshRateOverlay> mRefreshRateOverlay;

		// Flag used to set override allowed display configs from backdoor

+18 −8

Original line number	Diff line number	Diff line
		@@ -20,14 +20,13 @@
		#include "TimeStats.h"

		#include <android-base/stringprintf.h>

		#include <log/log.h>

		#include <utils/String8.h>
		#include <utils/Timers.h>
		#include <utils/Trace.h>

		#include <algorithm>
		#include <chrono>

		namespace android {

		@@ -113,6 +112,23 @@ void TimeStats::incrementClientCompositionFrames() {
		mTimeStats.clientCompositionFrames++;
		}

		static int32_t msBetween(nsecs_t start, nsecs_t end) {
		int64_t delta = std::chrono::duration_cast<std::chrono::milliseconds>(
		std::chrono::nanoseconds(end - start))
		.count();
		delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
		return static_cast<int32_t>(delta);
		}

		void TimeStats::recordFrameDuration(nsecs_t startTime, nsecs_t endTime) {
		if (!mEnabled.load()) return;

		std::lock_guard<std::mutex> lock(mMutex);
		if (mPowerTime.powerMode == HWC_POWER_MODE_NORMAL) {
		mTimeStats.frameDuration.insert(msBetween(startTime, endTime));
		}
		}

		bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
		if (!timeRecord->ready) {
		ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerId,
		@@ -149,12 +165,6 @@ bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
		return true;
		}

		static int32_t msBetween(nsecs_t start, nsecs_t end) {
		int64_t delta = (end - start) / 1000000;
		delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
		return static_cast<int32_t>(delta);
		}

		void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) {
		ATRACE_CALL();

+9 −0

Original line number	Diff line number	Diff line
		@@ -44,6 +44,13 @@ public:
		virtual void incrementMissedFrames() = 0;
		virtual void incrementClientCompositionFrames() = 0;

		// Records the start and end times for a frame.
		// The start time is the same as the beginning of a SurfaceFlinger
		// invalidate message.
		// The end time corresponds to when SurfaceFlinger finishes submitting the
		// request to HWC to present a frame.
		virtual void recordFrameDuration(nsecs_t startTime, nsecs_t endTime) = 0;

		virtual void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
		nsecs_t postTime) = 0;
		virtual void setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) = 0;
		@@ -116,6 +123,8 @@ public:
		void incrementMissedFrames() override;
		void incrementClientCompositionFrames() override;

		void recordFrameDuration(nsecs_t startTime, nsecs_t endTime) override;

		void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
		nsecs_t postTime) override;
		void setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) override;

+7 −0

Original line number	Diff line number	Diff line
		@@ -111,6 +111,8 @@ std::string TimeStatsHelper::TimeStatsGlobal::toString(std::optional<uint32_t> m
		StringAppendF(&result, "totalP2PTime = %" PRId64 " ms\n", presentToPresent.totalTime());
		StringAppendF(&result, "presentToPresent histogram is as below:\n");
		result.append(presentToPresent.toString());
		StringAppendF(&result, "frameDuration histogram is as below:\n");
		result.append(frameDuration.toString());
		const auto dumpStats = generateDumpStats(maxLayers);
		for (const auto& ele : dumpStats) {
		result.append(ele->toString());
		@@ -158,6 +160,11 @@ SFTimeStatsGlobalProto TimeStatsHelper::TimeStatsGlobal::toProto(
		histProto->set_time_millis(histEle.first);
		histProto->set_frame_count(histEle.second);
		}
		for (const auto& histEle : frameDuration.hist) {
		SFTimeStatsHistogramBucketProto* histProto = globalProto.add_frame_duration();
		histProto->set_time_millis(histEle.first);
		histProto->set_frame_count(histEle.second);
		}
		const auto dumpStats = generateDumpStats(maxLayers);
		for (const auto& ele : dumpStats) {
		SFTimeStatsLayerProto* layerProto = globalProto.add_stats();