[sf] Add traces with log fatals
If we have to abort flinger, capture a transaction trace to
disk as well. This will help us understand what lead to the
unexpected state.
Test: presubmit
Bug: 238781169
Change-Id: I3ba9004ef8fc3cc2b9f7f431f9ceefafda858db7
diff --git a/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp b/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp
index ab4c15d..962dc09 100644
--- a/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp
+++ b/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp
@@ -60,9 +60,9 @@
return;
}
}
- if (traversalPath.hasRelZLoop()) {
- LOG_ALWAYS_FATAL("Found relative z loop layerId:%d", traversalPath.invalidRelativeRootId);
- }
+
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(traversalPath.hasRelZLoop(), "Found relative z loop layerId:%d",
+ traversalPath.invalidRelativeRootId);
for (auto& [child, childVariant] : mChildren) {
ScopedAddToTraversalPath addChildToTraversalPath(traversalPath, child->mLayer->id,
childVariant);
@@ -104,9 +104,7 @@
[child](const std::pair<LayerHierarchy*, Variant>& x) {
return x.first == child;
});
- if (it == mChildren.end()) {
- LOG_ALWAYS_FATAL("Could not find child!");
- }
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(it == mChildren.end(), "Could not find child!");
mChildren.erase(it);
}
@@ -119,11 +117,8 @@
[hierarchy](std::pair<LayerHierarchy*, Variant>& child) {
return child.first == hierarchy;
});
- if (it == mChildren.end()) {
- LOG_ALWAYS_FATAL("Could not find child!");
- } else {
- it->second = variant;
- }
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(it == mChildren.end(), "Could not find child!");
+ it->second = variant;
}
const RequestedLayerState* LayerHierarchy::getLayer() const {
@@ -422,9 +417,8 @@
LayerHierarchy* LayerHierarchyBuilder::getHierarchyFromId(uint32_t layerId, bool crashOnFailure) {
auto it = mLayerIdToHierarchy.find(layerId);
if (it == mLayerIdToHierarchy.end()) {
- if (crashOnFailure) {
- LOG_ALWAYS_FATAL("Could not find hierarchy for layer id %d", layerId);
- }
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(crashOnFailure, "Could not find hierarchy for layer id %d",
+ layerId);
return nullptr;
};
@@ -460,7 +454,7 @@
}
LayerHierarchy::TraversalPath LayerHierarchy::TraversalPath::getMirrorRoot() const {
- LOG_ALWAYS_FATAL_IF(!isClone(), "Cannot get mirror root of a non cloned node");
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(!isClone(), "Cannot get mirror root of a non cloned node");
TraversalPath mirrorRootPath = *this;
mirrorRootPath.id = mirrorRootId;
return mirrorRootPath;
diff --git a/services/surfaceflinger/FrontEnd/LayerLifecycleManager.cpp b/services/surfaceflinger/FrontEnd/LayerLifecycleManager.cpp
index 1712137..a826ec1 100644
--- a/services/surfaceflinger/FrontEnd/LayerLifecycleManager.cpp
+++ b/services/surfaceflinger/FrontEnd/LayerLifecycleManager.cpp
@@ -45,11 +45,11 @@
for (auto& newLayer : newLayers) {
RequestedLayerState& layer = *newLayer.get();
auto [it, inserted] = mIdToLayer.try_emplace(layer.id, References{.owner = layer});
- if (!inserted) {
- LOG_ALWAYS_FATAL("Duplicate layer id found. New layer: %s Existing layer: %s",
- layer.getDebugString().c_str(),
- it->second.owner.getDebugString().c_str());
- }
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(!inserted,
+ "Duplicate layer id found. New layer: %s Existing layer: "
+ "%s",
+ layer.getDebugString().c_str(),
+ it->second.owner.getDebugString().c_str());
mAddedLayers.push_back(newLayer.get());
mChangedLayers.push_back(newLayer.get());
layer.parentId = linkLayer(layer.parentId, layer.id);
@@ -85,14 +85,15 @@
}
}
-void LayerLifecycleManager::onHandlesDestroyed(const std::vector<uint32_t>& destroyedHandles,
- bool ignoreUnknownHandles) {
+void LayerLifecycleManager::onHandlesDestroyed(
+ const std::vector<std::pair<uint32_t, std::string /* debugName */>>& destroyedHandles,
+ bool ignoreUnknownHandles) {
std::vector<uint32_t> layersToBeDestroyed;
- for (const auto& layerId : destroyedHandles) {
+ for (const auto& [layerId, name] : destroyedHandles) {
auto it = mIdToLayer.find(layerId);
if (it == mIdToLayer.end()) {
- LOG_ALWAYS_FATAL_IF(!ignoreUnknownHandles, "%s Layerid not found %d", __func__,
- layerId);
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(!ignoreUnknownHandles, "%s Layerid not found %s[%d]",
+ __func__, name.c_str(), layerId);
continue;
}
RequestedLayerState& layer = it->second.owner;
@@ -113,10 +114,8 @@
for (size_t i = 0; i < layersToBeDestroyed.size(); i++) {
uint32_t layerId = layersToBeDestroyed[i];
auto it = mIdToLayer.find(layerId);
- if (it == mIdToLayer.end()) {
- LOG_ALWAYS_FATAL("%s Layer with id %d not found", __func__, layerId);
- continue;
- }
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(it == mIdToLayer.end(), "%s Layer with id %d not found",
+ __func__, layerId);
RequestedLayerState& layer = it->second.owner;
@@ -135,11 +134,9 @@
auto& references = it->second.references;
for (uint32_t linkedLayerId : references) {
RequestedLayerState* linkedLayer = getLayerFromId(linkedLayerId);
- if (!linkedLayer) {
- LOG_ALWAYS_FATAL("%s Layerid reference %d not found for %d", __func__,
- linkedLayerId, layer.id);
- continue;
- };
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(!linkedLayer,
+ "%s Layerid reference %d not found for %d", __func__,
+ linkedLayerId, layer.id);
if (linkedLayer->parentId == layer.id) {
linkedLayer->parentId = UNASSIGNED_LAYER_ID;
if (linkedLayer->canBeDestroyed()) {
@@ -191,17 +188,17 @@
RequestedLayerState* layer = getLayerFromId(layerId);
if (layer == nullptr) {
- LOG_ALWAYS_FATAL_IF(!ignoreUnknownLayers, "%s Layer with layerid=%d not found",
- __func__, layerId);
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(!ignoreUnknownLayers,
+ "%s Layer with layerid=%d not found", __func__,
+ layerId);
continue;
}
- if (!layer->handleAlive) {
- LOG_ALWAYS_FATAL("%s Layer's with layerid=%d) is not alive. Possible out of "
- "order LayerLifecycleManager updates",
- __func__, layerId);
- continue;
- }
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(!layer->handleAlive,
+ "%s Layer's with layerid=%d) is not alive. Possible "
+ "out of "
+ "order LayerLifecycleManager updates",
+ __func__, layerId);
if (layer->changes.get() == 0) {
mChangedLayers.push_back(layer);
@@ -241,7 +238,7 @@
RequestedLayerState* bgColorLayer = getLayerFromId(layer->bgColorLayerId);
layer->bgColorLayerId = UNASSIGNED_LAYER_ID;
bgColorLayer->parentId = unlinkLayer(bgColorLayer->parentId, bgColorLayer->id);
- onHandlesDestroyed({bgColorLayer->id});
+ onHandlesDestroyed({{bgColorLayer->id, bgColorLayer->debugName}});
} else if (layer->bgColorLayerId != UNASSIGNED_LAYER_ID) {
RequestedLayerState* bgColorLayer = getLayerFromId(layer->bgColorLayerId);
bgColorLayer->color = layer->bgColor;
diff --git a/services/surfaceflinger/FrontEnd/LayerLifecycleManager.h b/services/surfaceflinger/FrontEnd/LayerLifecycleManager.h
index 48571bf..9aff78e 100644
--- a/services/surfaceflinger/FrontEnd/LayerLifecycleManager.h
+++ b/services/surfaceflinger/FrontEnd/LayerLifecycleManager.h
@@ -47,7 +47,8 @@
// Ignore unknown handles when iteroping with legacy front end. In the old world, we
// would create child layers which are not necessary with the new front end. This means
// we will get notified for handle changes that don't exist in the new front end.
- void onHandlesDestroyed(const std::vector<uint32_t>&, bool ignoreUnknownHandles = false);
+ void onHandlesDestroyed(const std::vector<std::pair<uint32_t, std::string /* debugName */>>&,
+ bool ignoreUnknownHandles = false);
// Detaches the layer from its relative parent to prevent a loop in the
// layer hierarchy. This overrides the RequestedLayerState and leaves
diff --git a/services/surfaceflinger/FrontEnd/LayerLog.h b/services/surfaceflinger/FrontEnd/LayerLog.h
index 4943483..3845dfe 100644
--- a/services/surfaceflinger/FrontEnd/LayerLog.h
+++ b/services/surfaceflinger/FrontEnd/LayerLog.h
@@ -16,6 +16,8 @@
#pragma once
+#include "Tracing/TransactionTracing.h"
+
// Uncomment to trace layer updates for a single layer
// #define LOG_LAYER 1
@@ -27,3 +29,17 @@
#endif
#define LLOGD(LAYER_ID, x, ...) ALOGD("[%d] %s " x, (LAYER_ID), __func__, ##__VA_ARGS__);
+
+#define LLOG_ALWAYS_FATAL_WITH_TRACE(...) \
+ do { \
+ TransactionTraceWriter::getInstance().invoke(__func__, /* overwrite= */ false); \
+ LOG_ALWAYS_FATAL(##__VA_ARGS__); \
+ } while (false)
+
+#define LLOG_ALWAYS_FATAL_WITH_TRACE_IF(cond, ...) \
+ do { \
+ if (__predict_false(cond)) { \
+ TransactionTraceWriter::getInstance().invoke(__func__, /* overwrite= */ false); \
+ } \
+ LOG_ALWAYS_FATAL_IF(cond, ##__VA_ARGS__); \
+ } while (false)
\ No newline at end of file
diff --git a/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp b/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp
index 159d0f0..21f1a4a 100644
--- a/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp
+++ b/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp
@@ -523,12 +523,9 @@
const Args& args, const LayerHierarchy& hierarchy,
LayerHierarchy::TraversalPath& traversalPath, const LayerSnapshot& parentSnapshot,
int depth) {
- if (depth > 50) {
- TransactionTraceWriter::getInstance().invoke("layer_builder_stack_overflow_",
- /*overwrite=*/false);
- LOG_ALWAYS_FATAL("Cycle detected in LayerSnapshotBuilder. See "
- "builder_stack_overflow_transactions.winscope");
- }
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(depth > 50,
+ "Cycle detected in LayerSnapshotBuilder. See "
+ "builder_stack_overflow_transactions.winscope");
const RequestedLayerState* layer = hierarchy.getLayer();
LayerSnapshot* snapshot = getSnapshot(traversalPath);
diff --git a/services/surfaceflinger/FrontEnd/TransactionHandler.cpp b/services/surfaceflinger/FrontEnd/TransactionHandler.cpp
index ca7c3c2..d3d9509 100644
--- a/services/surfaceflinger/FrontEnd/TransactionHandler.cpp
+++ b/services/surfaceflinger/FrontEnd/TransactionHandler.cpp
@@ -22,6 +22,7 @@
#include <cutils/trace.h>
#include <utils/Log.h>
#include <utils/Trace.h>
+#include "FrontEnd/LayerLog.h"
#include "TransactionHandler.h"
@@ -87,8 +88,8 @@
}
auto it = mPendingTransactionQueues.find(flushState.queueWithUnsignaledBuffer);
- LOG_ALWAYS_FATAL_IF(it == mPendingTransactionQueues.end(),
- "Could not find queue with unsignaled buffer!");
+ LLOG_ALWAYS_FATAL_WITH_TRACE_IF(it == mPendingTransactionQueues.end(),
+ "Could not find queue with unsignaled buffer!");
auto& queue = it->second;
popTransactionFromPending(transactions, flushState, queue);
diff --git a/services/surfaceflinger/FrontEnd/Update.h b/services/surfaceflinger/FrontEnd/Update.h
index e1449b6..e5cca8f 100644
--- a/services/surfaceflinger/FrontEnd/Update.h
+++ b/services/surfaceflinger/FrontEnd/Update.h
@@ -46,7 +46,7 @@
std::vector<LayerCreatedState> layerCreatedStates;
std::vector<std::unique_ptr<frontend::RequestedLayerState>> newLayers;
std::vector<LayerCreationArgs> layerCreationArgs;
- std::vector<uint32_t> destroyedHandles;
+ std::vector<std::pair<uint32_t, std::string /* debugName */>> destroyedHandles;
};
} // namespace android::surfaceflinger::frontend
diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index d8b920e..fa07001 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -5527,7 +5527,7 @@
void SurfaceFlinger::onHandleDestroyed(BBinder* handle, sp<Layer>& layer, uint32_t layerId) {
{
std::scoped_lock<std::mutex> lock(mCreatedLayersLock);
- mDestroyedHandles.emplace_back(layerId);
+ mDestroyedHandles.emplace_back(layerId, layer->getDebugName());
}
mTransactionHandler.onLayerDestroyed(layerId);
diff --git a/services/surfaceflinger/SurfaceFlinger.h b/services/surfaceflinger/SurfaceFlinger.h
index 175209f..7b64489 100644
--- a/services/surfaceflinger/SurfaceFlinger.h
+++ b/services/surfaceflinger/SurfaceFlinger.h
@@ -1425,7 +1425,7 @@
frontend::LayerHierarchyBuilder mLayerHierarchyBuilder{{}};
frontend::LayerSnapshotBuilder mLayerSnapshotBuilder;
- std::vector<uint32_t> mDestroyedHandles;
+ std::vector<std::pair<uint32_t, std::string>> mDestroyedHandles;
std::vector<std::unique_ptr<frontend::RequestedLayerState>> mNewLayers;
std::vector<LayerCreationArgs> mNewLayerArgs;
// These classes do not store any client state but help with managing transaction callbacks
diff --git a/services/surfaceflinger/Tracing/TransactionTracing.cpp b/services/surfaceflinger/Tracing/TransactionTracing.cpp
index 7e330b9..bc69191 100644
--- a/services/surfaceflinger/Tracing/TransactionTracing.cpp
+++ b/services/surfaceflinger/Tracing/TransactionTracing.cpp
@@ -111,7 +111,7 @@
update.createdLayers = std::move(newUpdate.layerCreationArgs);
newUpdate.layerCreationArgs.clear();
update.destroyedLayerHandles.reserve(newUpdate.destroyedHandles.size());
- for (uint32_t handle : newUpdate.destroyedHandles) {
+ for (auto& [handle, _] : newUpdate.destroyedHandles) {
update.destroyedLayerHandles.push_back(handle);
}
mPendingUpdates.emplace_back(update);
diff --git a/services/surfaceflinger/Tracing/tools/LayerTraceGenerator.cpp b/services/surfaceflinger/Tracing/tools/LayerTraceGenerator.cpp
index 519ef44..321b8ba 100644
--- a/services/surfaceflinger/Tracing/tools/LayerTraceGenerator.cpp
+++ b/services/surfaceflinger/Tracing/tools/LayerTraceGenerator.cpp
@@ -109,11 +109,11 @@
ALOGV(" destroyedHandles=%d", entry.destroyed_layers(j));
}
- std::vector<uint32_t> destroyedHandles;
+ std::vector<std::pair<uint32_t, std::string>> destroyedHandles;
destroyedHandles.reserve((size_t)entry.destroyed_layer_handles_size());
for (int j = 0; j < entry.destroyed_layer_handles_size(); j++) {
ALOGV(" destroyedHandles=%d", entry.destroyed_layer_handles(j));
- destroyedHandles.push_back(entry.destroyed_layer_handles(j));
+ destroyedHandles.push_back({entry.destroyed_layer_handles(j), ""});
}
bool displayChanged = entry.displays_changed();
diff --git a/services/surfaceflinger/tests/unittests/LayerHierarchyTest.h b/services/surfaceflinger/tests/unittests/LayerHierarchyTest.h
index f64ba2a..902f2b9 100644
--- a/services/surfaceflinger/tests/unittests/LayerHierarchyTest.h
+++ b/services/surfaceflinger/tests/unittests/LayerHierarchyTest.h
@@ -170,7 +170,7 @@
mLifecycleManager.applyTransactions(transactions);
}
- void destroyLayerHandle(uint32_t id) { mLifecycleManager.onHandlesDestroyed({id}); }
+ void destroyLayerHandle(uint32_t id) { mLifecycleManager.onHandlesDestroyed({{id, "test"}}); }
void updateAndVerify(LayerHierarchyBuilder& hierarchyBuilder) {
if (mLifecycleManager.getGlobalChanges().test(RequestedLayerState::Changes::Hierarchy)) {
diff --git a/services/surfaceflinger/tests/unittests/LayerLifecycleManagerTest.cpp b/services/surfaceflinger/tests/unittests/LayerLifecycleManagerTest.cpp
index 97ef5a2..e3c7837 100644
--- a/services/surfaceflinger/tests/unittests/LayerLifecycleManagerTest.cpp
+++ b/services/surfaceflinger/tests/unittests/LayerLifecycleManagerTest.cpp
@@ -84,7 +84,7 @@
layers.emplace_back(rootLayer(2));
layers.emplace_back(rootLayer(3));
lifecycleManager.addLayers(std::move(layers));
- lifecycleManager.onHandlesDestroyed({1, 2, 3});
+ lifecycleManager.onHandlesDestroyed({{1, "1"}, {2, "2"}, {3, "3"}});
EXPECT_TRUE(lifecycleManager.getGlobalChanges().test(RequestedLayerState::Changes::Hierarchy));
lifecycleManager.commitChanges();
EXPECT_FALSE(lifecycleManager.getGlobalChanges().test(RequestedLayerState::Changes::Hierarchy));
@@ -133,7 +133,7 @@
layers.emplace_back(rootLayer(1));
layers.emplace_back(rootLayer(2));
lifecycleManager.addLayers(std::move(layers));
- lifecycleManager.onHandlesDestroyed({1});
+ lifecycleManager.onHandlesDestroyed({{1, "1"}});
lifecycleManager.commitChanges();
SCOPED_TRACE("layerWithoutHandleIsDestroyed");
@@ -149,7 +149,7 @@
layers.emplace_back(rootLayer(1));
layers.emplace_back(rootLayer(2));
lifecycleManager.addLayers(std::move(layers));
- lifecycleManager.onHandlesDestroyed({1});
+ lifecycleManager.onHandlesDestroyed({{1, "1"}});
lifecycleManager.commitChanges();
listener->expectLayersAdded({1, 2});
listener->expectLayersDestroyed({1});
@@ -173,7 +173,7 @@
listener->expectLayersAdded({});
listener->expectLayersDestroyed({});
- lifecycleManager.onHandlesDestroyed({3});
+ lifecycleManager.onHandlesDestroyed({{3, "3"}});
lifecycleManager.commitChanges();
listener->expectLayersAdded({});
listener->expectLayersDestroyed({3});
@@ -194,7 +194,7 @@
listener->expectLayersDestroyed({});
lifecycleManager.applyTransactions(reparentLayerTransaction(3, UNASSIGNED_LAYER_ID));
- lifecycleManager.onHandlesDestroyed({3});
+ lifecycleManager.onHandlesDestroyed({{3, "3"}});
lifecycleManager.commitChanges();
listener->expectLayersAdded({});
listener->expectLayersDestroyed({3});
@@ -215,7 +215,7 @@
listener->expectLayersDestroyed({});
lifecycleManager.applyTransactions(reparentLayerTransaction(3, UNASSIGNED_LAYER_ID));
- lifecycleManager.onHandlesDestroyed({3, 4});
+ lifecycleManager.onHandlesDestroyed({{3, "3"}, {4, "4"}});
lifecycleManager.commitChanges();
listener->expectLayersAdded({});
listener->expectLayersDestroyed({3, 4});
@@ -376,7 +376,7 @@
transactions.back().states.front().layerId = 1;
transactions.emplace_back();
lifecycleManager.applyTransactions(transactions);
- lifecycleManager.onHandlesDestroyed({1});
+ lifecycleManager.onHandlesDestroyed({{1, "1"}});
ASSERT_EQ(lifecycleManager.getLayers().size(), 0u);
ASSERT_EQ(lifecycleManager.getDestroyedLayers().size(), 2u);