Merge "surfaceflinger: add frame duration logging" (1d4f79c4) · Commits · e / os / android_frameworks_native

services/surfaceflinger/EventLog/EventLog.cpp

+11 −6

Original line number	Diff line number	Diff line
		@@ -31,17 +31,22 @@ ANDROID_SINGLETON_STATIC_INSTANCE(EventLog)
		EventLog::EventLog() {
		}

		void EventLog::doLogJank(const String8& window, int32_t value) {
		EventLog::TagBuffer buffer(LOGTAG_SF_JANK);
		buffer.startList(2);
		void EventLog::doLogFrameDurations(const String8& window,
		const int32_t* durations, size_t numDurations) {
		EventLog::TagBuffer buffer(LOGTAG_SF_FRAME_DUR);
		buffer.startList(1 + numDurations);
		buffer.writeString8(window);
		buffer.writeInt32(value);
		for (size_t i = 0; i < numDurations; i++) {
		buffer.writeInt32(durations[i]);
		}
		buffer.endList();
		buffer.log();
		}

		void EventLog::logJank(const String8& window, int32_t value) {
		EventLog::getInstance().doLogJank(window, value);
		void EventLog::logFrameDurations(const String8& window,
		const int32_t* durations, size_t numDurations) {
		EventLog::getInstance().doLogFrameDurations(window, durations,
		numDurations);
		}

		// ---------------------------------------------------------------------------

services/surfaceflinger/EventLog/EventLog.h

+5 −3

Original line number	Diff line number	Diff line
		@@ -30,7 +30,8 @@ class String8;
		class EventLog : public Singleton<EventLog> {

		public:
		static void logJank(const String8& window, int32_t value);
		static void logFrameDurations(const String8& window,
		const int32_t* durations, size_t numDurations);

		protected:
		EventLog();
		@@ -72,8 +73,9 @@ private:
		EventLog(const EventLog&);
		EventLog& operator =(const EventLog&);

		enum { LOGTAG_SF_JANK = 60100 };
		void doLogJank(const String8& window, int32_t value);
		enum { LOGTAG_SF_FRAME_DUR = 60100 };
		void doLogFrameDurations(const String8& window, const int32_t* durations,
		size_t numDurations);
		};

		// ---------------------------------------------------------------------------

services/surfaceflinger/EventLog/EventLogTags.logtags

+5 −2

Original line number	Diff line number	Diff line
		@@ -30,9 +30,12 @@
		# 5: Id
		# 6: Percent
		# Default value for data of type int/long is 2 (bytes).
		#
		# See system/core/logcat/event.logtags for the master copy of the tags.

		# 60100 - 60199 reserved for surfaceflinger

		# surfaceflinger
		60100 sf_jank (window\|3),(value\|1)
		60100 sf_frame_dur (window\|3),(dur0\|1),(dur1\|1),(dur2\|1),(dur3\|1),(dur4\|1),(dur5\|1),(dur6\|1)

		# NOTE - the range 1000000-2000000 is reserved for partners and others who
		# want to define their own log tags without conflicting with the core platform.

services/surfaceflinger/FrameTracker.cpp

+80 −1

Original line number	Diff line number	Diff line
		@@ -17,17 +17,22 @@
		// This is needed for stdint.h to define INT64_MAX in C++
		#define __STDC_LIMIT_MACROS

		#include <cutils/log.h>

		#include <ui/Fence.h>

		#include <utils/String8.h>

		#include "FrameTracker.h"
		#include "EventLog/EventLog.h"

		namespace android {

		FrameTracker::FrameTracker() :
		mOffset(0),
		mNumFences(0) {
		mNumFences(0),
		mDisplayPeriod(0) {
		resetFrameCountersLocked();
		}

		void FrameTracker::setDesiredPresentTime(nsecs_t presentTime) {
		@@ -57,8 +62,18 @@ void FrameTracker::setActualPresentFence(const sp<Fence>& readyFence) {
		mNumFences++;
		}

		void FrameTracker::setDisplayRefreshPeriod(nsecs_t displayPeriod) {
		Mutex::Autolock lock(mMutex);
		mDisplayPeriod = displayPeriod;
		}

		void FrameTracker::advanceFrame() {
		Mutex::Autolock lock(mMutex);

		// Update the statistic to include the frame we just finished.
		updateStatsLocked(mOffset);

		// Advance to the next frame.
		mOffset = (mOffset+1) % NUM_FRAME_RECORDS;
		mFrameRecords[mOffset].desiredPresentTime = INT64_MAX;
		mFrameRecords[mOffset].frameReadyTime = INT64_MAX;
		@@ -98,12 +113,19 @@ void FrameTracker::clear() {
		mFrameRecords[mOffset].actualPresentTime = INT64_MAX;
		}

		void FrameTracker::logAndResetStats(const String8& name) {
		Mutex::Autolock lock(mMutex);
		logStatsLocked(name);
		resetFrameCountersLocked();
		}

		void FrameTracker::processFencesLocked() const {
		FrameRecord* records = const_cast<FrameRecord*>(mFrameRecords);
		int& numFences = const_cast<int&>(mNumFences);

		for (int i = 1; i < NUM_FRAME_RECORDS && numFences > 0; i++) {
		size_t idx = (mOffset+NUM_FRAME_RECORDS-i) % NUM_FRAME_RECORDS;
		bool updated = false;

		const sp<Fence>& rfence = records[idx].frameReadyFence;
		if (rfence != NULL) {
		@@ -111,6 +133,7 @@ void FrameTracker::processFencesLocked() const {
		if (records[idx].frameReadyTime < INT64_MAX) {
		records[idx].frameReadyFence = NULL;
		numFences--;
		updated = true;
		}
		}

		@@ -120,9 +143,65 @@ void FrameTracker::processFencesLocked() const {
		if (records[idx].actualPresentTime < INT64_MAX) {
		records[idx].actualPresentFence = NULL;
		numFences--;
		updated = true;
		}
		}

		if (updated) {
		updateStatsLocked(idx);
		}
		}
		}

		void FrameTracker::updateStatsLocked(size_t newFrameIdx) const {
		int* numFrames = const_cast<int*>(mNumFrames);

		if (mDisplayPeriod > 0 && isFrameValidLocked(newFrameIdx)) {
		size_t prevFrameIdx = (newFrameIdx+NUM_FRAME_RECORDS-1) %
		NUM_FRAME_RECORDS;

		if (isFrameValidLocked(prevFrameIdx)) {
		nsecs_t newPresentTime =
		mFrameRecords[newFrameIdx].actualPresentTime;
		nsecs_t prevPresentTime =
		mFrameRecords[prevFrameIdx].actualPresentTime;

		nsecs_t duration = newPresentTime - prevPresentTime;
		int numPeriods = int((duration + mDisplayPeriod/2) /
		mDisplayPeriod);

		for (int i = 0; i < NUM_FRAME_BUCKETS-1; i++) {
		int nextBucket = 1 << (i+1);
		if (numPeriods < nextBucket) {
		numFrames[i]++;
		return;
		}
		}

		// The last duration bucket is a catch-all.
		numFrames[NUM_FRAME_BUCKETS-1]++;
		}
		}
		}

		void FrameTracker::resetFrameCountersLocked() {
		for (int i = 0; i < NUM_FRAME_BUCKETS; i++) {
		mNumFrames[i] = 0;
		}
		}

		void FrameTracker::logStatsLocked(const String8& name) const {
		for (int i = 0; i < NUM_FRAME_BUCKETS; i++) {
		if (mNumFrames[i] > 0) {
		EventLog::logFrameDurations(name, mNumFrames, NUM_FRAME_BUCKETS);
		return;
		}
		}
		}

		bool FrameTracker::isFrameValidLocked(size_t idx) const {
		return mFrameRecords[idx].actualPresentTime > 0 &&
		mFrameRecords[idx].actualPresentTime < INT64_MAX;
		}

		void FrameTracker::dump(String8& result) const {

services/surfaceflinger/FrameTracker.h

+37 −0

Original line number	Diff line number	Diff line
		@@ -43,6 +43,8 @@ public:
		// frame time history.
		enum { NUM_FRAME_RECORDS = 128 };

		enum { NUM_FRAME_BUCKETS = 7 };

		FrameTracker();

		// setDesiredPresentTime sets the time at which the current frame
		@@ -68,12 +70,21 @@ public:
		// at which the current frame became visible to the user.
		void setActualPresentFence(const sp<Fence>& fence);

		// setDisplayRefreshPeriod sets the display refresh period in nanoseconds.
		// This is used to compute frame presentation duration statistics relative
		// to this period.
		void setDisplayRefreshPeriod(nsecs_t displayPeriod);

		// advanceFrame advances the frame tracker to the next frame.
		void advanceFrame();

		// clear resets all the tracked frame data to zero.
		void clear();

		// logAndResetStats dumps the current statistics to the binary event log
		// and then resets the accumulated statistics to their initial values.
		void logAndResetStats(const String8& name);

		// dump appends the current frame display time history to the result string.
		void dump(String8& result) const;

		@@ -99,6 +110,21 @@ private:
		// change. This allows it to be called from the dump method.
		void processFencesLocked() const;

		// updateStatsLocked updates the running statistics that are gathered
		// about the frame times.
		void updateStatsLocked(size_t newFrameIdx) const;

		// resetFrameCounteresLocked sets all elements of the mNumFrames array to
		// 0.
		void resetFrameCountersLocked();

		// logStatsLocked dumps the current statistics to the binary event log.
		void logStatsLocked(const String8& name) const;

		// isFrameValidLocked returns true if the data for the given frame index is
		// valid and has all arrived (i.e. there are no oustanding fences).
		bool isFrameValidLocked(size_t idx) const;

		// mFrameRecords is the circular buffer storing the tracked data for each
		// frame.
		FrameRecord mFrameRecords[NUM_FRAME_RECORDS];
		@@ -115,6 +141,17 @@ private:
		// doesn't grow with NUM_FRAME_RECORDS.
		int mNumFences;

		// mNumFrames keeps a count of the number of frames with a duration in a
		// particular range of vsync periods. Element n of the array stores the
		// number of frames with duration in the half-inclusive range
		// [2^n, 2^(n+1)). The last element of the array contains the count for
		// all frames with duration greater than 2^(NUM_FRAME_BUCKETS-1).
		int32_t mNumFrames[NUM_FRAME_BUCKETS];

		// mDisplayPeriod is the display refresh period of the display for which
		// this FrameTracker is gathering information.
		nsecs_t mDisplayPeriod;

		// mMutex is used to protect access to all member variables.
		mutable Mutex mMutex;
		};