diff options
| author | 2023-08-19 14:20:18 -0700 | |
|---|---|---|
| committer | 2023-08-21 07:33:19 -0700 | |
| commit | 606d9d074646c04bd966ccd752ade0b796748216 (patch) | |
| tree | 213f6930e17df2a19c52adbad7a0ac45d8104f4e | |
| parent | 8c5b700a85f70b69e844545d23193a0eac622732 (diff) | |
[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
13 files changed, 72 insertions, 66 deletions
diff --git a/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp b/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp index ab4c15d670..962dc09680 100644 --- a/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp +++ b/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp @@ -60,9 +60,9 @@ void LayerHierarchy::traverse(const Visitor& visitor, 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 @@ void LayerHierarchy::removeChild(LayerHierarchy* child) { [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 @@ void LayerHierarchy::updateChild(LayerHierarchy* hierarchy, LayerHierarchy::Vari [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::getPartialHierarchy(uint32_t layerId, 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 @@ std::string LayerHierarchy::TraversalPath::toString() const { } 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 1712137a7e..a826ec18a1 100644 --- a/services/surfaceflinger/FrontEnd/LayerLifecycleManager.cpp +++ b/services/surfaceflinger/FrontEnd/LayerLifecycleManager.cpp @@ -45,11 +45,11 @@ void LayerLifecycleManager::addLayers(std::vector<std::unique_ptr<RequestedLayer 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::addLayers(std::vector<std::unique_ptr<RequestedLayer } } -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 @@ void LayerLifecycleManager::onHandlesDestroyed(const std::vector<uint32_t>& dest 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 @@ void LayerLifecycleManager::onHandlesDestroyed(const std::vector<uint32_t>& dest 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 @@ void LayerLifecycleManager::applyTransactions(const std::vector<TransactionState 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 @@ void LayerLifecycleManager::applyTransactions(const std::vector<TransactionState 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 48571bf923..9aff78e463 100644 --- a/services/surfaceflinger/FrontEnd/LayerLifecycleManager.h +++ b/services/surfaceflinger/FrontEnd/LayerLifecycleManager.h @@ -47,7 +47,8 @@ public: // 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 4943483e62..3845dfeb26 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 159d0f028d..21f1a4a53f 100644 --- a/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp +++ b/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp @@ -523,12 +523,9 @@ const LayerSnapshot& LayerSnapshotBuilder::updateSnapshotsInHierarchy( 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 ca7c3c25f7..d3d950974f 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 @@ void TransactionHandler::applyUnsignaledBufferTransaction( } 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 e1449b6e1b..e5cca8fa95 100644 --- a/services/surfaceflinger/FrontEnd/Update.h +++ b/services/surfaceflinger/FrontEnd/Update.h @@ -46,7 +46,7 @@ struct Update { 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 d8b920e750..fa070018a4 100644 --- a/services/surfaceflinger/SurfaceFlinger.cpp +++ b/services/surfaceflinger/SurfaceFlinger.cpp @@ -5527,7 +5527,7 @@ void SurfaceFlinger::markLayerPendingRemovalLocked(const sp<Layer>& layer) { 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 175209fad4..7b64489028 100644 --- a/services/surfaceflinger/SurfaceFlinger.h +++ b/services/surfaceflinger/SurfaceFlinger.h @@ -1425,7 +1425,7 @@ private: 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 7e330b97dd..bc69191cc1 100644 --- a/services/surfaceflinger/Tracing/TransactionTracing.cpp +++ b/services/surfaceflinger/Tracing/TransactionTracing.cpp @@ -111,7 +111,7 @@ void TransactionTracing::addCommittedTransactions(int64_t vsyncId, nsecs_t commi 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 519ef44552..321b8baccc 100644 --- a/services/surfaceflinger/Tracing/tools/LayerTraceGenerator.cpp +++ b/services/surfaceflinger/Tracing/tools/LayerTraceGenerator.cpp @@ -109,11 +109,11 @@ bool LayerTraceGenerator::generate(const proto::TransactionTraceFile& traceFile, 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 f64ba2a439..902f2b9405 100644 --- a/services/surfaceflinger/tests/unittests/LayerHierarchyTest.h +++ b/services/surfaceflinger/tests/unittests/LayerHierarchyTest.h @@ -170,7 +170,7 @@ protected: 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 97ef5a268d..e3c7837e70 100644 --- a/services/surfaceflinger/tests/unittests/LayerLifecycleManagerTest.cpp +++ b/services/surfaceflinger/tests/unittests/LayerLifecycleManagerTest.cpp @@ -84,7 +84,7 @@ TEST_F(LayerLifecycleManagerTest, addLayers) { 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 @@ TEST_F(LayerLifecycleManagerTest, layerWithoutHandleIsDestroyed) { 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 @@ TEST_F(LayerLifecycleManagerTest, rootLayerWithoutHandleIsDestroyed) { 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 @@ TEST_F(LayerLifecycleManagerTest, offscreenLayerIsDestroyed) { listener->expectLayersAdded({}); listener->expectLayersDestroyed({}); - lifecycleManager.onHandlesDestroyed({3}); + lifecycleManager.onHandlesDestroyed({{3, "3"}}); lifecycleManager.commitChanges(); listener->expectLayersAdded({}); listener->expectLayersDestroyed({3}); @@ -194,7 +194,7 @@ TEST_F(LayerLifecycleManagerTest, offscreenChildLayerWithHandleIsNotDestroyed) { 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 @@ TEST_F(LayerLifecycleManagerTest, offscreenChildLayerWithoutHandleIsDestroyed) { 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 @@ TEST_F(LayerLifecycleManagerTest, onParentDestroyDestroysBackgroundLayer) { 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); |