/* * 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" #include #include #include #include "Client.h" #include "FrontEnd/LayerCreationArgs.h" #include "TransactionDataSource.h" #include "TransactionTracing.h" namespace android { ANDROID_SINGLETON_STATIC_INSTANCE(android::TransactionTraceWriter) TransactionTracing::TransactionTracing() : mProtoParser(std::make_unique()) { std::scoped_lock lock(mTraceLock); mBuffer.setSize(CONTINUOUS_TRACING_BUFFER_SIZE); mStartingTimestamp = systemTime(); { std::scoped_lock lock(mMainThreadLock); mThread = std::thread(&TransactionTracing::loop, this); } TransactionDataSource::Initialize(*this); } TransactionTracing::~TransactionTracing() { TransactionDataSource::UnregisterTransactionTracing(); std::thread thread; { std::scoped_lock lock(mMainThreadLock); mDone = true; mTransactionsAvailableCv.notify_all(); thread = std::move(mThread); } if (thread.joinable()) { thread.join(); } } void TransactionTracing::onStart(TransactionTracing::Mode mode) { // In "active" mode write the ring buffer (starting state + following sequence of transactions) // to perfetto when tracing starts (only once). if (mode != Mode::MODE_ACTIVE) { return; } writeRingBufferToPerfetto(TransactionTracing::Mode::MODE_ACTIVE); ALOGD("Started active mode tracing (wrote initial transactions ring buffer to perfetto)"); } void TransactionTracing::onFlush(TransactionTracing::Mode mode) { // In "continuous" mode write the ring buffer (starting state + following sequence of // transactions) to perfetto when a "flush" event is received (bugreport is taken or tracing is // stopped). if (mode != Mode::MODE_CONTINUOUS) { return; } writeRingBufferToPerfetto(TransactionTracing::Mode::MODE_CONTINUOUS); ALOGD("Flushed continuous mode tracing (wrote transactions ring buffer to perfetto"); } void TransactionTracing::writeRingBufferToPerfetto(TransactionTracing::Mode mode) { // Write the ring buffer (starting state + following sequence of transactions) to perfetto // tracing sessions with the specified mode. const auto fileProto = writeToProto(); TransactionDataSource::Trace([&](TransactionDataSource::TraceContext context) { // Write packets only to tracing sessions with specified mode if (context.GetCustomTlsState()->mMode != mode) { return; } for (const auto& entryProto : fileProto.entry()) { const auto entryBytes = entryProto.SerializeAsString(); auto packet = context.NewTracePacket(); packet->set_timestamp(static_cast(entryProto.elapsed_realtime_nanos())); packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC); auto* transactionsProto = packet->set_surfaceflinger_transactions(); transactionsProto->AppendRawProtoBytes(entryBytes.data(), entryBytes.size()); } { // TODO (b/162206162): remove empty packet when perfetto bug is fixed. // It is currently needed in order not to lose the last trace entry. context.NewTracePacket(); } }); } status_t TransactionTracing::writeToFile(const std::string& filename) { auto fileProto = writeToProto(); std::string output; if (!fileProto.SerializeToString(&output)) { ALOGE("Could not serialize proto."); return UNKNOWN_ERROR; } // -rw-r--r-- const mode_t mode = S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH; if (!android::base::WriteStringToFile(output, filename, mode, getuid(), getgid(), true)) { ALOGE("Could not save the proto file %s", filename.c_str()); return PERMISSION_DENIED; } return NO_ERROR; } perfetto::protos::TransactionTraceFile TransactionTracing::writeToProto() { std::scoped_lock lock(mTraceLock); perfetto::protos::TransactionTraceFile fileProto = createTraceFileProto(); const auto startingStateProto = createStartingStateProtoLocked(); if (startingStateProto) { *fileProto.add_entry() = std::move(*startingStateProto); } mBuffer.writeToProto(fileProto); return fileProto; } void TransactionTracing::setBufferSize(size_t bufferSizeInBytes) { std::scoped_lock lock(mTraceLock); mBuffer.setSize(bufferSizeInBytes); } perfetto::protos::TransactionTraceFile TransactionTracing::createTraceFileProto() const { perfetto::protos::TransactionTraceFile proto; proto.set_magic_number( uint64_t(perfetto::protos::TransactionTraceFile_MagicNumber_MAGIC_NUMBER_H) << 32 | perfetto::protos::TransactionTraceFile_MagicNumber_MAGIC_NUMBER_L); auto timeOffsetNs = static_cast(systemTime(SYSTEM_TIME_REALTIME) - systemTime(SYSTEM_TIME_MONOTONIC)); proto.set_real_to_elapsed_time_offset_nanos(timeOffsetNs); proto.set_version(TRACING_VERSION); return proto; } void TransactionTracing::dump(std::string& result) const { std::scoped_lock lock(mTraceLock); base::StringAppendF(&result, " queued transactions=%zu created layers=%zu states=%zu\n", mQueuedTransactions.size(), mCreatedLayers.size(), mStartingStates.size()); mBuffer.dump(result); } void TransactionTracing::addQueuedTransaction(const TransactionState& transaction) { perfetto::protos::TransactionState* state = new perfetto::protos::TransactionState(mProtoParser.toProto(transaction)); mTransactionQueue.push(state); } void TransactionTracing::addCommittedTransactions(int64_t vsyncId, nsecs_t commitTime, frontend::Update& newUpdate, const frontend::DisplayInfos& displayInfos, bool displayInfoChanged) { CommittedUpdates update; update.vsyncId = vsyncId; update.timestamp = commitTime; update.transactionIds.reserve(newUpdate.transactions.size()); for (const auto& transaction : newUpdate.transactions) { update.transactionIds.emplace_back(transaction.id); } update.displayInfoChanged = displayInfoChanged; if (displayInfoChanged) { update.displayInfos = displayInfos; } update.createdLayers = std::move(newUpdate.layerCreationArgs); newUpdate.layerCreationArgs.clear(); update.destroyedLayerHandles.reserve(newUpdate.destroyedHandles.size()); for (auto& [handle, _] : newUpdate.destroyedHandles) { update.destroyedLayerHandles.push_back(handle); } mPendingUpdates.emplace_back(update); tryPushToTracingThread(); mLastUpdatedVsyncId = vsyncId; } void TransactionTracing::loop() { while (true) { std::vector committedUpdates; std::vector destroyedLayers; { std::unique_lock lock(mMainThreadLock); base::ScopedLockAssertion assumeLocked(mMainThreadLock); mTransactionsAvailableCv.wait(lock, [&]() REQUIRES(mMainThreadLock) { return mDone || !mUpdates.empty(); }); if (mDone) { mUpdates.clear(); mDestroyedLayers.clear(); break; } destroyedLayers = std::move(mDestroyedLayers); mDestroyedLayers.clear(); committedUpdates = std::move(mUpdates); mUpdates.clear(); } // unlock mMainThreadLock if (!committedUpdates.empty() || !destroyedLayers.empty()) { addEntry(committedUpdates, destroyedLayers); } } } void TransactionTracing::addEntry(const std::vector& committedUpdates, const std::vector& destroyedLayers) { std::scoped_lock lock(mTraceLock); std::vector removedEntries; perfetto::protos::TransactionTraceEntry entryProto; while (auto incomingTransaction = mTransactionQueue.pop()) { auto transaction = *incomingTransaction; mQueuedTransactions[incomingTransaction->transaction_id()] = transaction; delete incomingTransaction; } for (const CommittedUpdates& update : committedUpdates) { entryProto.set_elapsed_realtime_nanos(update.timestamp); entryProto.set_vsync_id(update.vsyncId); entryProto.mutable_added_layers()->Reserve( static_cast(update.createdLayers.size())); for (const auto& args : update.createdLayers) { entryProto.mutable_added_layers()->Add(std::move(mProtoParser.toProto(args))); } entryProto.mutable_destroyed_layers()->Reserve( static_cast(destroyedLayers.size())); for (auto& destroyedLayer : destroyedLayers) { entryProto.mutable_destroyed_layers()->Add(destroyedLayer); } entryProto.mutable_transactions()->Reserve( static_cast(update.transactionIds.size())); for (const uint64_t& id : update.transactionIds) { auto it = mQueuedTransactions.find(id); if (it != mQueuedTransactions.end()) { entryProto.mutable_transactions()->Add(std::move(it->second)); mQueuedTransactions.erase(it); } else { ALOGW("Could not find transaction id %" PRIu64, id); } } entryProto.mutable_destroyed_layer_handles()->Reserve( static_cast(update.destroyedLayerHandles.size())); for (auto layerId : update.destroyedLayerHandles) { entryProto.mutable_destroyed_layer_handles()->Add(layerId); } entryProto.set_displays_changed(update.displayInfoChanged); if (update.displayInfoChanged) { entryProto.mutable_displays()->Reserve( static_cast(update.displayInfos.size())); for (auto& [layerStack, displayInfo] : update.displayInfos) { entryProto.mutable_displays()->Add( std::move(mProtoParser.toProto(displayInfo, layerStack.id))); } } std::string serializedProto; entryProto.SerializeToString(&serializedProto); TransactionDataSource::Trace([&](TransactionDataSource::TraceContext context) { // In "active" mode write each committed transaction to perfetto. // Note: the starting state is written (once) when the perfetto "start" event is // received. if (context.GetCustomTlsState()->mMode != Mode::MODE_ACTIVE) { return; } { auto packet = context.NewTracePacket(); packet->set_timestamp(static_cast(entryProto.elapsed_realtime_nanos())); packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC); auto* transactions = packet->set_surfaceflinger_transactions(); transactions->AppendRawProtoBytes(serializedProto.data(), serializedProto.size()); } { // TODO (b/162206162): remove empty packet when perfetto bug is fixed. // It is currently needed in order not to lose the last trace entry. context.NewTracePacket(); } }); std::vector entries = mBuffer.emplace(std::move(serializedProto)); removedEntries.reserve(removedEntries.size() + entries.size()); removedEntries.insert(removedEntries.end(), std::make_move_iterator(entries.begin()), std::make_move_iterator(entries.end())); entryProto.Clear(); } perfetto::protos::TransactionTraceEntry removedEntryProto; for (const std::string& removedEntry : removedEntries) { removedEntryProto.ParseFromString(removedEntry); updateStartingStateLocked(removedEntryProto); removedEntryProto.Clear(); } mTransactionsAddedToBufferCv.notify_one(); } void TransactionTracing::flush() { { std::scoped_lock lock(mMainThreadLock); // Collect any pending transactions and wait for transactions to be added to mUpdates.insert(mUpdates.end(), std::make_move_iterator(mPendingUpdates.begin()), std::make_move_iterator(mPendingUpdates.end())); mPendingUpdates.clear(); mDestroyedLayers.insert(mDestroyedLayers.end(), mPendingDestroyedLayers.begin(), mPendingDestroyedLayers.end()); mPendingDestroyedLayers.clear(); mTransactionsAvailableCv.notify_one(); } std::unique_lock lock(mTraceLock); base::ScopedLockAssertion assumeLocked(mTraceLock); mTransactionsAddedToBufferCv.wait_for(lock, std::chrono::milliseconds(100), [&]() REQUIRES(mTraceLock) { perfetto::protos::TransactionTraceEntry entry; if (mBuffer.used() > 0) { entry.ParseFromString(mBuffer.back()); } return mBuffer.used() > 0 && entry.vsync_id() >= mLastUpdatedVsyncId; }); } void TransactionTracing::onLayerRemoved(int32_t layerId) { mPendingDestroyedLayers.emplace_back(layerId); tryPushToTracingThread(); } void TransactionTracing::tryPushToTracingThread() { // Try to acquire the lock from main thread. if (mMainThreadLock.try_lock()) { // We got the lock! Collect any pending transactions and continue. mUpdates.insert(mUpdates.end(), std::make_move_iterator(mPendingUpdates.begin()), std::make_move_iterator(mPendingUpdates.end())); mPendingUpdates.clear(); mDestroyedLayers.insert(mDestroyedLayers.end(), mPendingDestroyedLayers.begin(), mPendingDestroyedLayers.end()); mPendingDestroyedLayers.clear(); mTransactionsAvailableCv.notify_one(); mMainThreadLock.unlock(); } else { ALOGV("Couldn't get lock"); } } void TransactionTracing::updateStartingStateLocked( const perfetto::protos::TransactionTraceEntry& removedEntry) { mStartingTimestamp = removedEntry.elapsed_realtime_nanos(); // Keep track of layer starting state so we can reconstruct the layer state as we purge // transactions from the buffer. for (const perfetto::protos::LayerCreationArgs& addedLayer : removedEntry.added_layers()) { TracingLayerState& startingState = mStartingStates[addedLayer.layer_id()]; startingState.layerId = addedLayer.layer_id(); mProtoParser.fromProto(addedLayer, startingState.args); } // Merge layer states to starting transaction state. for (const perfetto::protos::TransactionState& transaction : removedEntry.transactions()) { for (const perfetto::protos::LayerState& layerState : transaction.layer_changes()) { auto it = mStartingStates.find(layerState.layer_id()); if (it == mStartingStates.end()) { // TODO(b/238781169) make this log fatal when we switch over to using new fe ALOGW("Could not find layer id %d", layerState.layer_id()); continue; } mProtoParser.mergeFromProto(layerState, it->second); } } for (const uint32_t destroyedLayerHandleId : removedEntry.destroyed_layer_handles()) { mRemovedLayerHandlesAtStart.insert(destroyedLayerHandleId); } // Clean up stale starting states since the layer has been removed and the buffer does not // contain any references to the layer. for (const uint32_t destroyedLayerId : removedEntry.destroyed_layers()) { mStartingStates.erase(destroyedLayerId); mRemovedLayerHandlesAtStart.erase(destroyedLayerId); } if (removedEntry.displays_changed()) { mProtoParser.fromProto(removedEntry.displays(), mStartingDisplayInfos); } } std::optional TransactionTracing::createStartingStateProtoLocked() { if (mStartingStates.empty()) { return std::nullopt; } perfetto::protos::TransactionTraceEntry entryProto; entryProto.set_elapsed_realtime_nanos(mStartingTimestamp); entryProto.set_vsync_id(0); entryProto.mutable_added_layers()->Reserve(static_cast(mStartingStates.size())); for (auto& [layerId, state] : mStartingStates) { entryProto.mutable_added_layers()->Add(mProtoParser.toProto(state.args)); } perfetto::protos::TransactionState transactionProto = mProtoParser.toProto(mStartingStates); transactionProto.set_vsync_id(0); transactionProto.set_post_time(mStartingTimestamp); entryProto.mutable_transactions()->Add(std::move(transactionProto)); entryProto.mutable_destroyed_layer_handles()->Reserve( static_cast(mRemovedLayerHandlesAtStart.size())); for (const uint32_t destroyedLayerHandleId : mRemovedLayerHandlesAtStart) { entryProto.mutable_destroyed_layer_handles()->Add(destroyedLayerHandleId); } entryProto.mutable_displays()->Reserve(static_cast(mStartingDisplayInfos.size())); for (auto& [layerStack, displayInfo] : mStartingDisplayInfos) { entryProto.mutable_displays()->Add(mProtoParser.toProto(displayInfo, layerStack.id)); } entryProto.set_displays_changed(true); return entryProto; } } // namespace android