Merge "SF: Add continuous transaction tracing" (db844fb3) · Commits · e / os / platform_frameworks_native

services/surfaceflinger/Android.bp

+1 −0

Original line number	Diff line number	Diff line
		@@ -205,6 +205,7 @@ filegroup {
		"SurfaceFlingerDefaultFactory.cpp",
		"SurfaceInterceptor.cpp",
		"Tracing/LayerTracing.cpp",
		"Tracing/TransactionTracing.cpp",
		"Tracing/TransactionProtoParser.cpp",
		"TransactionCallbackInvoker.cpp",
		"TunnelModeEnabledReporter.cpp",

services/surfaceflinger/SurfaceFlinger.cpp

+47 −13

Original line number	Diff line number	Diff line
		@@ -359,10 +359,11 @@ bool callingThreadHasRotateSurfaceFlingerAccess() {

		SurfaceFlinger::SurfaceFlinger(Factory& factory, SkipInitializationTag)
		: mFactory(factory),
		mPid(getpid()),
		mInterceptor(mFactory.createSurfaceInterceptor()),
		mTimeStats(std::make_shared<impl::TimeStats>()),
		mFrameTracer(mFactory.createFrameTracer()),
		mFrameTimeline(mFactory.createFrameTimeline(mTimeStats, getpid())),
		mFrameTimeline(mFactory.createFrameTimeline(mTimeStats, mPid)),
		mCompositionEngine(mFactory.createCompositionEngine()),
		mHwcServiceName(base::GetProperty("debug.sf.hwc_service_name"s, "default"s)),
		mTunnelModeEnabledReporter(new TunnelModeEnabledReporter()),
		@@ -491,6 +492,11 @@ SurfaceFlinger::SurfaceFlinger(Factory& factory) : SurfaceFlinger(factory, SkipI
		enableSdrDimming = property_get_bool("debug.sf.enable_sdr_dimming", enable_sdr_dimming(false));

		enableLatchUnsignaledConfig = getLatchUnsignaledConfig();

		mTransactionTracingEnabled = property_get_bool("debug.sf.enable_transaction_tracing", false);
		if (mTransactionTracingEnabled) {
		mTransactionTracing.enable();
		}
		}

		LatchUnsignaledConfig SurfaceFlinger::getLatchUnsignaledConfig() {
		@@ -1989,7 +1995,7 @@ bool SurfaceFlinger::commit(nsecs_t frameTime, int64_t vsyncId, nsecs_t expected
		}

		if (mTracingEnabledChanged) {
		mTracingEnabled = mLayerTracing.isEnabled();
		mLayerTracingEnabled = mLayerTracing.isEnabled();
		mTracingEnabledChanged = false;
		}

		@@ -2007,7 +2013,7 @@ bool SurfaceFlinger::commit(nsecs_t frameTime, int64_t vsyncId, nsecs_t expected

		bool needsTraversal = false;
		if (clearTransactionFlags(eTransactionFlushNeeded)) {
		needsTraversal = flushTransactionQueues();
		needsTraversal = flushTransactionQueues(vsyncId);
		}

		const bool shouldCommit =
		@@ -2138,7 +2144,7 @@ void SurfaceFlinger::composite(nsecs_t frameTime) {
		modulateVsync(&VsyncModulator::onDisplayRefresh, usedGpuComposition);

		mLayersWithQueuedFrames.clear();
		if (mTracingEnabled) {
		if (mLayerTracingEnabled) {
		// This will block and should only be used for debugging.
		if (mVisibleRegionsDirty) {
		mLayerTracing.notify("visibleRegionsDirty");
		@@ -3441,10 +3447,11 @@ status_t SurfaceFlinger::addClientLayer(const sp<Client>& client, const sp<IBind
		client->attachLayer(handle, lbc);
		}

		int64_t transactionId = (((int64_t)mPid) << 32) \| mUniqueTransactionId++;
		return setTransactionState(FrameTimelineInfo{}, states, displays, 0 /* flags */, nullptr,
		InputWindowCommands{}, -1 /* desiredPresentTime */,
		true /* isAutoTimestamp /, {}, false / hasListenerCallbacks */, {},
		0 /* Undefined transactionId */);
		transactionId);
		}

		uint32_t SurfaceFlinger::getTransactionFlags() const {
		@@ -3467,7 +3474,7 @@ uint32_t SurfaceFlinger::setTransactionFlags(uint32_t mask, TransactionSchedule
		return old;
		}

		bool SurfaceFlinger::flushTransactionQueues() {
		bool SurfaceFlinger::flushTransactionQueues(int64_t vsyncId) {
		// to prevent onHandleDestroyed from being called while the lock is held,
		// we must keep a copy of the transactions (specifically the composer
		// states) around outside the scope of the lock
		@@ -3553,12 +3560,13 @@ bool SurfaceFlinger::flushTransactionQueues() {
		ATRACE_INT("TransactionQueue", mTransactionQueue.size());
		}

		return applyTransactions(transactions);
		return applyTransactions(transactions, vsyncId);
		}
		}
		}

		bool SurfaceFlinger::applyTransactions(std::vector<TransactionState>& transactions) {
		bool SurfaceFlinger::applyTransactions(std::vector<TransactionState>& transactions,
		int64_t vsyncId) {
		bool needsTraversal = false;
		// Now apply all transactions.
		for (const auto& transaction : transactions) {
		@@ -3576,6 +3584,10 @@ bool SurfaceFlinger::applyTransactions(std::vector<TransactionState>& transactio
		std::move(transaction.transactionCommittedSignal));
		}
		}

		if (mTransactionTracingEnabled) {
		mTransactionTracing.addCommittedTransactions(transactions, vsyncId);
		}
		return needsTraversal;
		}

		@@ -3829,6 +3841,10 @@ status_t SurfaceFlinger::setTransactionState(
		state.traverseStatesWithBuffers([&](const layer_state_t& state) {
		mBufferCountTracker.increment(state.surface->localBinder());
		});

		if (mTransactionTracingEnabled) {
		mTransactionTracing.addQueuedTransaction(state);
		}
		queueTransaction(state);

		// Check the pending state to make sure the transaction is synchronous.
		@@ -4517,10 +4533,12 @@ void SurfaceFlinger::onInitializeDisplays() {
		displays.add(d);

		nsecs_t now = systemTime();

		int64_t transactionId = (((int64_t)mPid) << 32) \| mUniqueTransactionId++;
		// It should be on the main thread, apply it directly.
		applyTransactionState(FrameTimelineInfo{}, state, displays, 0, mInputWindowCommands,
		/* desiredPresentTime / now, true, {}, / postTime */ now, true, false,
		{}, getpid(), getuid(), 0 /* Undefined transactionId */);
		{}, mPid, getuid(), transactionId);

		setPowerModeInternal(display, hal::PowerMode::ON);
		const nsecs_t vsyncPeriod =
		@@ -4719,8 +4737,9 @@ status_t SurfaceFlinger::doDump(int fd, const DumpArgs& args, bool asProto) {
		}

		status_t SurfaceFlinger::dumpCritical(int fd, const DumpArgs&, bool asProto) {
		if (asProto && mLayerTracing.isEnabled()) {
		if (asProto) {
		mLayerTracing.writeToFile();
		mTransactionTracing.writeToFile();
		}

		return doDump(fd, DumpArgs(), asProto);
		@@ -4917,7 +4936,6 @@ void SurfaceFlinger::dumpWideColorInfo(std::string& result) const {
		}

		LayersProto SurfaceFlinger::dumpDrawingStateProto(uint32_t traceFlags) const {
		// If context is SurfaceTracing thread, mTracingLock blocks display transactions on main thread.
		const auto display = ON_MAIN_THREAD(getDefaultDisplayDeviceLocked());

		LayersProto layersProto;
		@@ -5118,6 +5136,8 @@ void SurfaceFlinger::dumpAllLocked(const DumpArgs& args, std::string& result) co
		*/
		mLayerTracing.dump(result);
		result.append("\n");
		mTransactionTracing.dump(result);
		result.append("\n");

		/*
		* HWC layer minidump
		@@ -5350,9 +5370,9 @@ status_t SurfaceFlinger::CheckTransactCodeCredentials(uint32_t code) {
		code == IBinder::SYSPROPS_TRANSACTION) {
		return OK;
		}
		// Numbers from 1000 to 1040 are currently used for backdoors. The code
		// Numbers from 1000 to 1041 are currently used for backdoors. The code
		// in onTransact verifies that the user is root, and has access to use SF.
		if (code >= 1000 && code <= 1040) {
		if (code >= 1000 && code <= 1041) {
		ALOGV("Accessing SurfaceFlinger through backdoor code: %u", code);
		return OK;
		}
		@@ -5791,6 +5811,20 @@ status_t SurfaceFlinger::onTransact(uint32_t code, const Parcel& data, Parcel* r
		scheduleRepaint();
		return NO_ERROR;
		}
		case 1041: { // Transaction tracing
		if (data.readInt32()) {
		// Transaction tracing is always running but allow the user to temporarily
		// increase the buffer when actively debugging.
		mTransactionTracing.setBufferSize(
		TransactionTracing::ACTIVE_TRACING_BUFFER_SIZE);
		} else {
		mTransactionTracing.setBufferSize(
		TransactionTracing::CONTINUOUS_TRACING_BUFFER_SIZE);
		mTransactionTracing.writeToFile();
		}
		reply->writeInt32(NO_ERROR);
		return NO_ERROR;
		}
		}
		}
		return err;

services/surfaceflinger/SurfaceFlinger.h

+10 −5

Original line number	Diff line number	Diff line
		@@ -64,6 +64,7 @@
		#include "SurfaceFlingerFactory.h"
		#include "TracedOrdinal.h"
		#include "Tracing/LayerTracing.h"
		#include "Tracing/TransactionTracing.h"
		#include "TransactionCallbackInvoker.h"
		#include "TransactionState.h"

		@@ -712,7 +713,7 @@ private:
		int originPid, int originUid, uint64_t transactionId)
		REQUIRES(mStateLock);
		// flush pending transaction that was presented after desiredPresentTime.
		bool flushTransactionQueues();
		bool flushTransactionQueues(int64_t vsyncId);
		// Returns true if there is at least one transaction that needs to be flushed
		bool transactionFlushNeeded();

		@@ -748,7 +749,8 @@ private:
		bool allowedLatchUnsignaled() REQUIRES(mQueueLock, mStateLock);
		bool checkTransactionCanLatchUnsignaled(const TransactionState& transaction)
		REQUIRES(mStateLock);
		bool applyTransactions(std::vector<TransactionState>& transactions) REQUIRES(mStateLock);
		bool applyTransactions(std::vector<TransactionState>& transactions, int64_t vsyncId)
		REQUIRES(mStateLock);
		uint32_t setDisplayStateLocked(const DisplayState& s) REQUIRES(mStateLock);
		uint32_t addInputWindowCommands(const InputWindowCommands& inputWindowCommands)
		REQUIRES(mStateLock);
		@@ -1083,7 +1085,7 @@ private:

		sp<StartPropertySetThread> mStartPropertySetThread;
		surfaceflinger::Factory& mFactory;

		pid_t mPid;
		std::future<void> mRenderEnginePrimeCacheFuture;

		// access must be protected by mStateLock
		@@ -1092,6 +1094,7 @@ private:
		std::atomic<int32_t> mTransactionFlags = 0;
		std::vector<std::shared_ptr<CountDownLatch>> mTransactionCommittedSignals;
		bool mAnimTransactionPending = false;
		std::atomic<uint32_t> mUniqueTransactionId = 1;
		SortedVector<sp<Layer>> mLayersPendingRemoval;

		// global color transform states
		@@ -1182,8 +1185,10 @@ private:
		sp<SurfaceInterceptor> mInterceptor;

		LayerTracing mLayerTracing{*this};
		std::mutex mTracingLock;
		bool mTracingEnabled = false;
		bool mLayerTracingEnabled = false;

		TransactionTracing mTransactionTracing;
		bool mTransactionTracingEnabled = false;
		std::atomic<bool> mTracingEnabledChanged = false;

		const std::shared_ptr<TimeStats> mTimeStats;

services/surfaceflinger/Tracing/RingBuffer.h

+12 −6

Original line number	Diff line number	Diff line
		@@ -21,8 +21,9 @@

		#include <log/log.h>
		#include <utils/Errors.h>
		#include <utils/SystemClock.h>
		#include <utils/Timers.h>
		#include <utils/Trace.h>
		#include <chrono>
		#include <queue>

		namespace android {
		@@ -57,9 +58,7 @@ public:
		status_t writeToFile(FileProto& fileProto, std::string filename) {
		ATRACE_CALL();
		std::string output;
		flush(fileProto);
		reset(mSizeInBytes);
		if (!fileProto.SerializeToString(&output)) {
		if (!writeToString(fileProto, &output)) {
		ALOGE("Could not serialize proto.");
		return UNKNOWN_ERROR;
		}
		@@ -73,6 +72,13 @@ public:
		return NO_ERROR;
		}

		bool writeToString(FileProto& fileProto, std::string* outString) {
		ATRACE_CALL();
		flush(fileProto);
		reset(mSizeInBytes);
		return fileProto.SerializeToString(outString);
		}

		std::vector<EntryProto> emplace(EntryProto&& proto) {
		std::vector<EntryProto> replacedEntries;
		size_t protoSize = static_cast<size_t>(proto.ByteSize());
		@@ -99,8 +105,8 @@ public:
		const int64_t durationCount = duration.count();
		base::StringAppendF(&result,
		" number of entries: %zu (%.2fMB / %.2fMB) duration: %" PRIi64 "ms\n",
		frameCount(), float(used()) / 1024.f * 1024.f,
		float(size()) / 1024.f * 1024.f, durationCount);
		frameCount(), float(used()) / (1024.f * 1024.f),
		float(size()) / (1024.f * 1024.f), durationCount);
		}

		private:

services/surfaceflinger/Tracing/TransactionTracing.cpp

0 → 100644

+203 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright 2021 The Android Open Source Project
		*
		* Licensed under the Apache License, Version 2.0 (the "License");
		* you may not use this file except in compliance with the License.
		* You may obtain a copy of the License at
		*
		* http://www.apache.org/licenses/LICENSE-2.0
		*
		* Unless required by applicable law or agreed to in writing, software
		* distributed under the License is distributed on an "AS IS" BASIS,
		* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
		* See the License for the specific language governing permissions and
		* limitations under the License.
		*/

		#undef LOG_TAG
		#define LOG_TAG "TransactionTracing"
		#define ATRACE_TAG ATRACE_TAG_GRAPHICS

		#include <android-base/stringprintf.h>
		#include <log/log.h>
		#include <utils/SystemClock.h>
		#include <utils/Trace.h>

		#include "RingBuffer.h"
		#include "TransactionTracing.h"

		namespace android {

		TransactionTracing::TransactionTracing() {
		mBuffer = std::make_unique<
		RingBuffer<proto::TransactionTraceFile, proto::TransactionTraceEntry>>();
		}

		TransactionTracing::~TransactionTracing() = default;

		bool TransactionTracing::enable() {
		std::scoped_lock lock(mTraceLock);
		if (mEnabled) {
		return false;
		}
		mBuffer->setSize(mBufferSizeInBytes);
		mEnabled = true;
		{
		std::scoped_lock lock(mMainThreadLock);
		mDone = false;
		mThread = std::thread(&TransactionTracing::loop, this);
		}
		return true;
		}

		bool TransactionTracing::disable() {
		std::thread thread;
		{
		std::scoped_lock lock(mMainThreadLock);
		mDone = true;
		mTransactionsAvailableCv.notify_all();
		thread = std::move(mThread);
		}
		if (thread.joinable()) {
		thread.join();
		}

		std::scoped_lock lock(mTraceLock);
		if (!mEnabled) {
		return false;
		}
		mEnabled = false;

		proto::TransactionTraceFile fileProto = createTraceFileProto();
		mBuffer->writeToFile(fileProto, FILE_NAME);
		mQueuedTransactions.clear();
		return true;
		}

		bool TransactionTracing::isEnabled() const {
		std::scoped_lock lock(mTraceLock);
		return mEnabled;
		}

		status_t TransactionTracing::writeToFile() {
		std::scoped_lock lock(mTraceLock);
		if (!mEnabled) {
		return STATUS_OK;
		}
		proto::TransactionTraceFile fileProto = createTraceFileProto();
		return mBuffer->writeToFile(fileProto, FILE_NAME);
		}

		void TransactionTracing::setBufferSize(size_t bufferSizeInBytes) {
		std::scoped_lock lock(mTraceLock);
		mBufferSizeInBytes = bufferSizeInBytes;
		mBuffer->setSize(mBufferSizeInBytes);
		}

		proto::TransactionTraceFile TransactionTracing::createTraceFileProto() const {
		proto::TransactionTraceFile proto;
		proto.set_magic_number(uint64_t(proto::TransactionTraceFile_MagicNumber_MAGIC_NUMBER_H) << 32 \|
		proto::TransactionTraceFile_MagicNumber_MAGIC_NUMBER_L);
		return proto;
		}

		void TransactionTracing::dump(std::string& result) const {
		std::scoped_lock lock(mTraceLock);
		base::StringAppendF(&result, "Transaction tracing state: %s\n",
		mEnabled ? "enabled" : "disabled");
		base::StringAppendF(&result, " queued transactions: %d\n",
		static_cast<uint32_t>(mQueuedTransactions.size()));
		mBuffer->dump(result);
		}

		void TransactionTracing::addQueuedTransaction(const TransactionState& transaction) {
		std::scoped_lock lock(mTraceLock);
		ATRACE_CALL();
		if (!mEnabled) {
		return;
		}
		mQueuedTransactions[transaction.id] =
		TransactionProtoParser::toProto(transaction, nullptr, nullptr);
		}

		void TransactionTracing::addCommittedTransactions(std::vector<TransactionState>& transactions,
		int64_t vsyncId) {
		CommittedTransactions committedTransactions;
		committedTransactions.vsyncId = vsyncId;
		committedTransactions.timestamp = systemTime();
		committedTransactions.transactionIds.reserve(transactions.size());
		for (const auto& transaction : transactions) {
		committedTransactions.transactionIds.emplace_back(transaction.id);
		}

		// Try to acquire the lock from main thread, but don't block if we cannot acquire the lock. Add
		// it to pending transactions that we can collect later.
		if (mMainThreadLock.try_lock()) {
		// We got the lock! Collect any pending transactions and continue.
		mCommittedTransactions.insert(mCommittedTransactions.end(),
		std::make_move_iterator(mPendingTransactions.begin()),
		std::make_move_iterator(mPendingTransactions.end()));
		mPendingTransactions.clear();
		mCommittedTransactions.emplace_back(committedTransactions);
		mTransactionsAvailableCv.notify_one();
		mMainThreadLock.unlock();
		} else {
		mPendingTransactions.emplace_back(committedTransactions);
		}
		}

		void TransactionTracing::loop() {
		while (true) {
		std::vector<CommittedTransactions> committedTransactions;
		{
		std::unique_lock<std::mutex> lock(mMainThreadLock);
		base::ScopedLockAssertion assumeLocked(mMainThreadLock);
		mTransactionsAvailableCv.wait(lock, [&]() REQUIRES(mMainThreadLock) {
		return mDone \|\| !mCommittedTransactions.empty();
		});
		if (mDone) {
		mCommittedTransactions.clear();
		break;
		}
		committedTransactions = std::move(mCommittedTransactions);
		mCommittedTransactions.clear();
		} // unlock mMainThreadLock

		addEntry(committedTransactions);

		mTransactionsAddedToBufferCv.notify_one();
		}
		}

		void TransactionTracing::addEntry(const std::vector<CommittedTransactions>& committedTransactions) {
		ATRACE_CALL();
		std::scoped_lock lock(mTraceLock);
		std::vector<proto::TransactionTraceEntry> removedEntries;
		for (const CommittedTransactions& entry : committedTransactions) {
		proto::TransactionTraceEntry entryProto;
		entryProto.set_elapsed_realtime_nanos(entry.timestamp);
		entryProto.set_vsync_id(entry.vsyncId);
		entryProto.mutable_transactions()->Reserve(
		static_cast<int32_t>(entry.transactionIds.size()));
		for (const uint64_t& id : entry.transactionIds) {
		auto it = mQueuedTransactions.find(id);
		if (it != mQueuedTransactions.end()) {
		entryProto.mutable_transactions()->Add(std::move(it->second));
		mQueuedTransactions.erase(it);
		} else {
		ALOGE("Could not find transaction id %" PRIu64, id);
		}
		}
		mBuffer->emplace(std::move(entryProto));
		}
		}

		void TransactionTracing::flush() {
		std::unique_lock<std::mutex> lock(mMainThreadLock);
		base::ScopedLockAssertion assumeLocked(mMainThreadLock);
		mTransactionsAddedToBufferCv.wait(lock, [&]() REQUIRES(mMainThreadLock) {
		return mCommittedTransactions.empty();
		});
		}

		} // namespace android