Merge "SF: Move DispSync systrace logging to shell variable." (37972d4c) · Commits · e / os / platform_frameworks_native

services/surfaceflinger/Scheduler/DispSync.cpp

+28 −23

Original line number	Original line	Diff line number	Diff line
	@@ -44,10 +44,6 @@ DispSync::~DispSync() = default;

	namespace impl {		namespace impl {

	// Setting this to true enables verbose tracing that can be used to debug
	// vsync event model or phase issues.
	static const bool kTraceDetailedInfo = false;

	// Setting this to true adds a zero-phase tracer for correlating with hardware		// Setting this to true adds a zero-phase tracer for correlating with hardware
	// vsync events		// vsync events
	static const bool kEnableZeroPhaseTracer = false;		static const bool kEnableZeroPhaseTracer = false;
	@@ -62,19 +58,20 @@ static const nsecs_t kErrorThreshold = 160000000000; // 400 usec squared
	#define LOG_TAG "DispSyncThread"		#define LOG_TAG "DispSyncThread"
	class DispSyncThread : public Thread {		class DispSyncThread : public Thread {
	public:		public:
	explicit DispSyncThread(const char* name)		DispSyncThread(const char* name, bool showTraceDetailedInfo)
	: mName(name),		: mName(name),
	mStop(false),		mStop(false),
	mPeriod(0),		mPeriod(0),
	mPhase(0),		mPhase(0),
	mReferenceTime(0),		mReferenceTime(0),
	mWakeupLatency(0),		mWakeupLatency(0),
	mFrameNumber(0) {}		mFrameNumber(0),
			mTraceDetailedInfo(showTraceDetailedInfo) {}

	virtual ~DispSyncThread() {}		virtual ~DispSyncThread() {}

	void updateModel(nsecs_t period, nsecs_t phase, nsecs_t referenceTime) {		void updateModel(nsecs_t period, nsecs_t phase, nsecs_t referenceTime) {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	Mutex::Autolock lock(mMutex);		Mutex::Autolock lock(mMutex);
	mPeriod = period;		mPeriod = period;
	mPhase = phase;		mPhase = phase;
	@@ -86,7 +83,7 @@ public:
	}		}

	void stop() {		void stop() {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	Mutex::Autolock lock(mMutex);		Mutex::Autolock lock(mMutex);
	mStop = true;		mStop = true;
	mCond.signal();		mCond.signal();
	@@ -104,7 +101,7 @@ public:
	{ // Scope for lock		{ // Scope for lock
	Mutex::Autolock lock(mMutex);		Mutex::Autolock lock(mMutex);

	if (kTraceDetailedInfo) {		if (mTraceDetailedInfo) {
	ATRACE_INT64("DispSync:Frame", mFrameNumber);		ATRACE_INT64("DispSync:Frame", mFrameNumber);
	}		}
	ALOGV("[%s] Frame %" PRId64, mName, mFrameNumber);		ALOGV("[%s] Frame %" PRId64, mName, mFrameNumber);
	@@ -128,7 +125,7 @@ public:
	bool isWakeup = false;		bool isWakeup = false;

	if (now < targetTime) {		if (now < targetTime) {
	if (kTraceDetailedInfo) ATRACE_NAME("DispSync waiting");		if (mTraceDetailedInfo) ATRACE_NAME("DispSync waiting");

	if (targetTime == INT64_MAX) {		if (targetTime == INT64_MAX) {
	ALOGV("[%s] Waiting forever", mName);		ALOGV("[%s] Waiting forever", mName);
	@@ -154,7 +151,7 @@ public:
	if (isWakeup) {		if (isWakeup) {
	mWakeupLatency = ((mWakeupLatency * 63) + (now - targetTime)) / 64;		mWakeupLatency = ((mWakeupLatency * 63) + (now - targetTime)) / 64;
	mWakeupLatency = min(mWakeupLatency, kMaxWakeupLatency);		mWakeupLatency = min(mWakeupLatency, kMaxWakeupLatency);
	if (kTraceDetailedInfo) {		if (mTraceDetailedInfo) {
	ATRACE_INT64("DispSync:WakeupLat", now - targetTime);		ATRACE_INT64("DispSync:WakeupLat", now - targetTime);
	ATRACE_INT64("DispSync:AvgWakeupLat", mWakeupLatency);		ATRACE_INT64("DispSync:AvgWakeupLat", mWakeupLatency);
	}		}
	@@ -172,7 +169,7 @@ public:
	}		}

	status_t addEventListener(const char* name, nsecs_t phase, DispSync::Callback* callback) {		status_t addEventListener(const char* name, nsecs_t phase, DispSync::Callback* callback) {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	Mutex::Autolock lock(mMutex);		Mutex::Autolock lock(mMutex);

	for (size_t i = 0; i < mEventListeners.size(); i++) {		for (size_t i = 0; i < mEventListeners.size(); i++) {
	@@ -198,7 +195,7 @@ public:
	}		}

	status_t removeEventListener(DispSync::Callback* callback) {		status_t removeEventListener(DispSync::Callback* callback) {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	Mutex::Autolock lock(mMutex);		Mutex::Autolock lock(mMutex);

	for (std::vector<EventListener>::iterator it = mEventListeners.begin();		for (std::vector<EventListener>::iterator it = mEventListeners.begin();
	@@ -214,7 +211,7 @@ public:
	}		}

	status_t changePhaseOffset(DispSync::Callback* callback, nsecs_t phase) {		status_t changePhaseOffset(DispSync::Callback* callback, nsecs_t phase) {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	Mutex::Autolock lock(mMutex);		Mutex::Autolock lock(mMutex);

	for (auto& eventListener : mEventListeners) {		for (auto& eventListener : mEventListeners) {
	@@ -254,7 +251,7 @@ private:
	};		};

	nsecs_t computeNextEventTimeLocked(nsecs_t now) {		nsecs_t computeNextEventTimeLocked(nsecs_t now) {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	ALOGV("[%s] computeNextEventTimeLocked", mName);		ALOGV("[%s] computeNextEventTimeLocked", mName);
	nsecs_t nextEventTime = INT64_MAX;		nsecs_t nextEventTime = INT64_MAX;
	for (size_t i = 0; i < mEventListeners.size(); i++) {		for (size_t i = 0; i < mEventListeners.size(); i++) {
	@@ -270,7 +267,7 @@ private:
	}		}

	std::vector<CallbackInvocation> gatherCallbackInvocationsLocked(nsecs_t now) {		std::vector<CallbackInvocation> gatherCallbackInvocationsLocked(nsecs_t now) {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	ALOGV("[%s] gatherCallbackInvocationsLocked @ %" PRId64, mName, ns2us(now));		ALOGV("[%s] gatherCallbackInvocationsLocked @ %" PRId64, mName, ns2us(now));

	std::vector<CallbackInvocation> callbackInvocations;		std::vector<CallbackInvocation> callbackInvocations;
	@@ -293,7 +290,7 @@ private:
	}		}

	nsecs_t computeListenerNextEventTimeLocked(const EventListener& listener, nsecs_t baseTime) {		nsecs_t computeListenerNextEventTimeLocked(const EventListener& listener, nsecs_t baseTime) {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	ALOGV("[%s] [%s] computeListenerNextEventTimeLocked(%" PRId64 ")", mName, listener.mName,		ALOGV("[%s] [%s] computeListenerNextEventTimeLocked(%" PRId64 ")", mName, listener.mName,
	ns2us(baseTime));		ns2us(baseTime));

	@@ -344,7 +341,7 @@ private:
	}		}

	void fireCallbackInvocations(const std::vector<CallbackInvocation>& callbacks) {		void fireCallbackInvocations(const std::vector<CallbackInvocation>& callbacks) {
	if (kTraceDetailedInfo) ATRACE_CALL();		if (mTraceDetailedInfo) ATRACE_CALL();
	for (size_t i = 0; i < callbacks.size(); i++) {		for (size_t i = 0; i < callbacks.size(); i++) {
	callbacks[i].mCallback->onDispSyncEvent(callbacks[i].mEventTime);		callbacks[i].mCallback->onDispSyncEvent(callbacks[i].mEventTime);
	}		}
	@@ -365,6 +362,9 @@ private:

	Mutex mMutex;		Mutex mMutex;
	Condition mCond;		Condition mCond;

			// Flag to turn on logging in systrace.
			const bool mTraceDetailedInfo;
	};		};

	#undef LOG_TAG		#undef LOG_TAG
	@@ -383,8 +383,13 @@ private:
	bool mParity;		bool mParity;
	};		};

	DispSync::DispSync(const char* name)		DispSync::DispSync(const char* name) : mName(name), mRefreshSkipCount(0) {
	: mName(name), mRefreshSkipCount(0), mThread(new DispSyncThread(name)) {}		// This flag offers the ability to turn on systrace logging from the shell.
			char value[PROPERTY_VALUE_MAX];
			property_get("debug.sf.dispsync_trace_detailed_info", value, "0");
			mTraceDetailedInfo = atoi(value);
			mThread = new DispSyncThread(name, mTraceDetailedInfo);
			}

	DispSync::~DispSync() {}		DispSync::~DispSync() {}

	@@ -403,7 +408,7 @@ void DispSync::init(bool hasSyncFramework, int64_t dispSyncPresentTimeOffset) {
	reset();		reset();
	beginResync();		beginResync();

	if (kTraceDetailedInfo && kEnableZeroPhaseTracer) {		if (mTraceDetailedInfo && kEnableZeroPhaseTracer) {
	mZeroPhaseTracer = std::make_unique<ZeroPhaseTracer>();		mZeroPhaseTracer = std::make_unique<ZeroPhaseTracer>();
	addEventListener("ZeroPhaseTracer", 0, mZeroPhaseTracer.get());		addEventListener("ZeroPhaseTracer", 0, mZeroPhaseTracer.get());
	}		}
	@@ -588,7 +593,7 @@ void DispSync::updateModelLocked() {
	ALOGV("[%s] Adjusting mPhase -> %" PRId64, mName, ns2us(mPhase));		ALOGV("[%s] Adjusting mPhase -> %" PRId64, mName, ns2us(mPhase));
	}		}

	if (kTraceDetailedInfo) {		if (mTraceDetailedInfo) {
	ATRACE_INT64("DispSync:Period", mPeriod);		ATRACE_INT64("DispSync:Period", mPeriod);
	ATRACE_INT64("DispSync:Phase", mPhase + mPeriod / 2);		ATRACE_INT64("DispSync:Phase", mPhase + mPeriod / 2);
	}		}
	@@ -647,7 +652,7 @@ void DispSync::updateErrorLocked() {
	"No present times for model error.");		"No present times for model error.");
	}		}

	if (kTraceDetailedInfo) {		if (mTraceDetailedInfo) {
	ATRACE_INT64("DispSync:Error", mError);		ATRACE_INT64("DispSync:Error", mError);
	}		}
	}		}

services/surfaceflinger/Scheduler/DispSync.h

+3 −0

Original line number	Original line	Diff line number	Diff line
	@@ -241,6 +241,9 @@ private:
	bool mIgnorePresentFences;		bool mIgnorePresentFences;

	std::unique_ptr<Callback> mZeroPhaseTracer;		std::unique_ptr<Callback> mZeroPhaseTracer;

			// Flag to turn on logging in systrace.
			bool mTraceDetailedInfo = false;
	};		};

	} // namespace impl		} // namespace impl