blob: 696f3489bf2a0f279197daa29d74217137aefed9 [file] [log] [blame]
/*
* 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 <android-base/stringprintf.h>
#include <log/log.h>
#include <utils/SystemClock.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);
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<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) {
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));
}
entryProto.set_displays_changed(true);
return entryProto;
}
} // namespace android