services/surfaceflinger/Tracing/TransactionTracing.cpp

/*
 * 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 "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<TransactionProtoParser::FlingerDataMapper>()) {
    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);

    ALOGV("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);

    ALOGV("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<uint64_t>(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<std::mutex> 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<uint64_t>(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> committedUpdates;
        std::vector<uint32_t> destroyedLayers;
        {
            std::unique_lock<std::mutex> 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>& committedUpdates,
                                  const std::vector<uint32_t>& destroyedLayers) {
    ATRACE_CALL();
    std::scoped_lock lock(mTraceLock);
    std::vector<std::string> 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<int32_t>(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<int32_t>(destroyedLayers.size()));
        for (auto& destroyedLayer : destroyedLayers) {
            entryProto.mutable_destroyed_layers()->Add(destroyedLayer);
        }
        entryProto.mutable_transactions()->Reserve(
                static_cast<int32_t>(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<int32_t>(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<int32_t>(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<uint64_t>(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<std::string> 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<std::mutex> 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<perfetto::protos::TransactionTraceEntry>
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<int32_t>(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<int32_t>(mRemovedLayerHandlesAtStart.size()));
    for (const uint32_t destroyedLayerHandleId : mRemovedLayerHandlesAtStart) {
        entryProto.mutable_destroyed_layer_handles()->Add(destroyedLayerHandleId);
    }

    entryProto.mutable_displays()->Reserve(static_cast<int32_t>(mStartingDisplayInfos.size()));
    for (auto& [layerStack, displayInfo] : mStartingDisplayInfos) {
        entryProto.mutable_displays()->Add(mProtoParser.toProto(displayInfo, layerStack.id));
    }

    return entryProto;
}

} // namespace android