diff options
author | 2024-06-27 23:38:43 +0000 | |
---|---|---|
committer | 2024-06-28 19:20:08 +0000 | |
commit | be0ad90f195063f8a846b15cb435d71544e5db1f (patch) | |
tree | 31427d8262ad439780e1e9ca18d9c4c1a7c919e7 | |
parent | 20f86107d6bab7cc810700550b779bf5734b332f (diff) |
Create a wrapper for atrace macros
Create a SF specific macro to call into atrace. This will make the
switch to perfetto for capturing atrace tags easier.
Flag: EXEMPT refactor
Bug: 349905670
Test: perfetto
Change-Id: I4d046d837f52ef78b08e3c97556f2eddb06232dd
46 files changed, 606 insertions, 514 deletions
diff --git a/services/surfaceflinger/ClientCache.cpp b/services/surfaceflinger/ClientCache.cpp index 09e41ffede..40ea8d387a 100644 --- a/services/surfaceflinger/ClientCache.cpp +++ b/services/surfaceflinger/ClientCache.cpp @@ -22,7 +22,7 @@ #include <cinttypes> #include <android-base/stringprintf.h> -#include <gui/TraceUtils.h> +#include <common/trace.h> #include <renderengine/impl/ExternalTexture.h> #include "ClientCache.h" diff --git a/services/surfaceflinger/CompositionEngine/src/CompositionEngine.cpp b/services/surfaceflinger/CompositionEngine/src/CompositionEngine.cpp index 4c776879f0..5c5d0cd74d 100644 --- a/services/surfaceflinger/CompositionEngine/src/CompositionEngine.cpp +++ b/services/surfaceflinger/CompositionEngine/src/CompositionEngine.cpp @@ -14,6 +14,7 @@ * limitations under the License. */ +#include <common/trace.h> #include <compositionengine/CompositionRefreshArgs.h> #include <compositionengine/LayerFE.h> #include <compositionengine/LayerFECompositionState.h> @@ -23,7 +24,6 @@ #include <ui/DisplayMap.h> #include <renderengine/RenderEngine.h> -#include <utils/Trace.h> // TODO(b/129481165): remove the #pragma below and fix conversion issues #pragma clang diagnostic push @@ -128,7 +128,7 @@ void offloadOutputs(Outputs& outputs) { } // namespace void CompositionEngine::present(CompositionRefreshArgs& args) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); preComposition(args); @@ -155,7 +155,7 @@ void CompositionEngine::present(CompositionRefreshArgs& args) { } { - ATRACE_NAME("Waiting on HWC"); + SFTRACE_NAME("Waiting on HWC"); for (auto& future : presentFutures) { // TODO(b/185536303): Call ftl::Future::wait() once it exists, since // we do not need the return value of get(). @@ -177,7 +177,7 @@ void CompositionEngine::updateCursorAsync(CompositionRefreshArgs& args) { } void CompositionEngine::preComposition(CompositionRefreshArgs& args) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); bool needsAnotherUpdate = false; @@ -199,7 +199,7 @@ void CompositionEngine::preComposition(CompositionRefreshArgs& args) { // promises for buffer releases are fulfilled at the end of composition. void CompositionEngine::postComposition(CompositionRefreshArgs& args) { if (FlagManager::getInstance().ce_fence_promise()) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); for (auto& layerFE : args.layers) { diff --git a/services/surfaceflinger/CompositionEngine/src/Display.cpp b/services/surfaceflinger/CompositionEngine/src/Display.cpp index c1617d787b..77b1940e23 100644 --- a/services/surfaceflinger/CompositionEngine/src/Display.cpp +++ b/services/surfaceflinger/CompositionEngine/src/Display.cpp @@ -15,6 +15,7 @@ */ #include <android-base/stringprintf.h> +#include <common/trace.h> #include <compositionengine/CompositionEngine.h> #include <compositionengine/CompositionRefreshArgs.h> #include <compositionengine/DisplayCreationArgs.h> @@ -25,9 +26,6 @@ #include <compositionengine/impl/DumpHelpers.h> #include <compositionengine/impl/OutputLayer.h> #include <compositionengine/impl/RenderSurface.h> -#include <gui/TraceUtils.h> - -#include <utils/Trace.h> // TODO(b/129481165): remove the #pragma below and fix conversion issues #pragma clang diagnostic push @@ -235,7 +233,7 @@ void Display::beginFrame() { bool Display::chooseCompositionStrategy( std::optional<android::HWComposer::DeviceRequestedChanges>* outChanges) { - ATRACE_FORMAT("%s for %s", __func__, getNamePlusId().c_str()); + SFTRACE_FORMAT("%s for %s", __func__, getNamePlusId().c_str()); ALOGV(__FUNCTION__); if (mIsDisconnected) { diff --git a/services/surfaceflinger/CompositionEngine/src/Output.cpp b/services/surfaceflinger/CompositionEngine/src/Output.cpp index b40aea4210..64cded8691 100644 --- a/services/surfaceflinger/CompositionEngine/src/Output.cpp +++ b/services/surfaceflinger/CompositionEngine/src/Output.cpp @@ -17,6 +17,7 @@ #include <SurfaceFlingerProperties.sysprop.h> #include <android-base/stringprintf.h> #include <common/FlagManager.h> +#include <common/trace.h> #include <compositionengine/CompositionEngine.h> #include <compositionengine/CompositionRefreshArgs.h> #include <compositionengine/DisplayColorProfile.h> @@ -31,7 +32,6 @@ #include <compositionengine/impl/planner/Planner.h> #include <ftl/algorithm.h> #include <ftl/future.h> -#include <gui/TraceUtils.h> #include <scheduler/FrameTargeter.h> #include <scheduler/Time.h> @@ -53,7 +53,6 @@ #include <android-base/properties.h> #include <ui/DebugUtils.h> #include <ui/HdrCapabilities.h> -#include <utils/Trace.h> #include "TracedOrdinal.h" @@ -424,7 +423,7 @@ void Output::setReleasedLayers(Output::ReleasedLayers&& layers) { void Output::prepare(const compositionengine::CompositionRefreshArgs& refreshArgs, LayerFESet& geomSnapshots) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); rebuildLayerStacks(refreshArgs, geomSnapshots); @@ -453,8 +452,8 @@ ftl::Future<std::monostate> Output::present( }) .value(); }; - ATRACE_FORMAT("%s for %s%s", __func__, mNamePlusId.c_str(), - stringifyExpectedPresentTime().c_str()); + SFTRACE_FORMAT("%s for %s%s", __func__, mNamePlusId.c_str(), + stringifyExpectedPresentTime().c_str()); ALOGV(__FUNCTION__); updateColorProfile(refreshArgs); @@ -518,7 +517,7 @@ void Output::rebuildLayerStacks(const compositionengine::CompositionRefreshArgs& if (!outputState.isEnabled || CC_LIKELY(!refreshArgs.updatingOutputGeometryThisFrame)) { return; } - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); // Process the layers to determine visibility and coverage @@ -804,7 +803,7 @@ void Output::setReleasedLayers(const compositionengine::CompositionRefreshArgs&) } void Output::updateCompositionState(const compositionengine::CompositionRefreshArgs& refreshArgs) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); if (!getState().isEnabled) { @@ -831,14 +830,14 @@ void Output::planComposition() { return; } - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); mPlanner->plan(getOutputLayersOrderedByZ()); } void Output::writeCompositionState(const compositionengine::CompositionRefreshArgs& refreshArgs) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); if (!getState().isEnabled) { @@ -1081,7 +1080,7 @@ void Output::beginFrame() { } void Output::prepareFrame() { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); auto& outputState = editState(); @@ -1116,7 +1115,7 @@ std::future<bool> Output::chooseCompositionStrategyAsync( } GpuCompositionResult Output::prepareFrameAsync() { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); auto& state = editState(); const auto& previousChanges = state.previousDeviceRequestedChanges; @@ -1146,7 +1145,7 @@ GpuCompositionResult Output::prepareFrameAsync() { state.strategyPrediction = predictionSucceeded ? CompositionStrategyPredictionState::SUCCESS : CompositionStrategyPredictionState::FAIL; if (!predictionSucceeded) { - ATRACE_NAME("CompositionStrategyPredictionMiss"); + SFTRACE_NAME("CompositionStrategyPredictionMiss"); resetCompositionStrategy(); if (chooseCompositionSuccess) { applyCompositionStrategy(changes); @@ -1155,7 +1154,7 @@ GpuCompositionResult Output::prepareFrameAsync() { // Track the dequeued buffer to reuse so we don't need to dequeue another one. compositionResult.buffer = buffer; } else { - ATRACE_NAME("CompositionStrategyPredictionHit"); + SFTRACE_NAME("CompositionStrategyPredictionHit"); } state.previousDeviceRequestedChanges = std::move(changes); state.previousDeviceRequestedSuccess = chooseCompositionSuccess; @@ -1187,7 +1186,7 @@ void Output::devOptRepaintFlash(const compositionengine::CompositionRefreshArgs& } void Output::finishFrame(GpuCompositionResult&& result) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); const auto& outputState = getState(); if (!outputState.isEnabled) { @@ -1276,7 +1275,7 @@ bool Output::dequeueRenderBuffer(base::unique_fd* bufferFence, std::optional<base::unique_fd> Output::composeSurfaces( const Region& debugRegion, std::shared_ptr<renderengine::ExternalTexture> tex, base::unique_fd& fd) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV(__FUNCTION__); const auto& outputState = getState(); @@ -1317,13 +1316,13 @@ std::optional<base::unique_fd> Output::composeSurfaces( if (mClientCompositionRequestCache->exists(tex->getBuffer()->getId(), clientCompositionDisplay, clientCompositionLayers)) { - ATRACE_NAME("ClientCompositionCacheHit"); + SFTRACE_NAME("ClientCompositionCacheHit"); outputCompositionState.reusedClientComposition = true; setExpensiveRenderingExpected(false); // b/239944175 pass the fence associated with the buffer. return base::unique_fd(std::move(fd)); } - ATRACE_NAME("ClientCompositionCacheMiss"); + SFTRACE_NAME("ClientCompositionCacheMiss"); mClientCompositionRequestCache->add(tex->getBuffer()->getId(), clientCompositionDisplay, clientCompositionLayers); } @@ -1570,7 +1569,7 @@ bool Output::isPowerHintSessionGpuReportingEnabled() { } void Output::presentFrameAndReleaseLayers(bool flushEvenWhenDisabled) { - ATRACE_FORMAT("%s for %s", __func__, mNamePlusId.c_str()); + SFTRACE_FORMAT("%s for %s", __func__, mNamePlusId.c_str()); ALOGV(__FUNCTION__); if (!getState().isEnabled) { diff --git a/services/surfaceflinger/CompositionEngine/src/RenderSurface.cpp b/services/surfaceflinger/CompositionEngine/src/RenderSurface.cpp index c0b23d97d4..d6028bf4cf 100644 --- a/services/surfaceflinger/CompositionEngine/src/RenderSurface.cpp +++ b/services/surfaceflinger/CompositionEngine/src/RenderSurface.cpp @@ -18,6 +18,7 @@ #include <android-base/stringprintf.h> #include <android/native_window.h> +#include <common/trace.h> #include <compositionengine/CompositionEngine.h> #include <compositionengine/Display.h> #include <compositionengine/DisplaySurface.h> @@ -32,7 +33,6 @@ #include <system/window.h> #include <ui/GraphicBuffer.h> #include <ui/Rect.h> -#include <utils/Trace.h> // TODO(b/129481165): remove the #pragma below and fix conversion issues #pragma clang diagnostic push @@ -149,7 +149,7 @@ void RenderSurface::prepareFrame(bool usesClientComposition, bool usesDeviceComp std::shared_ptr<renderengine::ExternalTexture> RenderSurface::dequeueBuffer( base::unique_fd* bufferFence) { - ATRACE_CALL(); + SFTRACE_CALL(); int fd = -1; ANativeWindowBuffer* buffer = nullptr; diff --git a/services/surfaceflinger/CompositionEngine/src/planner/CachedSet.cpp b/services/surfaceflinger/CompositionEngine/src/planner/CachedSet.cpp index ea9442da06..409a206ace 100644 --- a/services/surfaceflinger/CompositionEngine/src/planner/CachedSet.cpp +++ b/services/surfaceflinger/CompositionEngine/src/planner/CachedSet.cpp @@ -21,6 +21,7 @@ #include <android-base/properties.h> #include <android-base/stringprintf.h> +#include <common/trace.h> #include <compositionengine/impl/OutputCompositionState.h> #include <compositionengine/impl/planner/CachedSet.h> #include <math/HashCombine.h> @@ -28,7 +29,6 @@ #include <renderengine/RenderEngine.h> #include <ui/DebugUtils.h> #include <ui/HdrRenderTypeUtils.h> -#include <utils/Trace.h> namespace android::compositionengine::impl::planner { @@ -160,7 +160,7 @@ void CachedSet::updateAge(std::chrono::steady_clock::time_point now) { void CachedSet::render(renderengine::RenderEngine& renderEngine, TexturePool& texturePool, const OutputCompositionState& outputState, bool deviceHandlesColorTransform) { - ATRACE_CALL(); + SFTRACE_CALL(); if (outputState.powerCallback) { outputState.powerCallback->notifyCpuLoadUp(); } diff --git a/services/surfaceflinger/CompositionEngine/src/planner/Flattener.cpp b/services/surfaceflinger/CompositionEngine/src/planner/Flattener.cpp index 4bafed2c8e..783209c26a 100644 --- a/services/surfaceflinger/CompositionEngine/src/planner/Flattener.cpp +++ b/services/surfaceflinger/CompositionEngine/src/planner/Flattener.cpp @@ -21,11 +21,10 @@ #include <android-base/properties.h> #include <common/FlagManager.h> +#include <common/trace.h> #include <compositionengine/impl/planner/Flattener.h> #include <compositionengine/impl/planner/LayerState.h> -#include <gui/TraceUtils.h> - using time_point = std::chrono::steady_clock::time_point; using namespace std::chrono_literals; @@ -77,7 +76,7 @@ Flattener::Flattener(renderengine::RenderEngine& renderEngine, const Tunables& t NonBufferHash Flattener::flattenLayers(const std::vector<const LayerState*>& layers, NonBufferHash hash, time_point now) { - ATRACE_CALL(); + SFTRACE_CALL(); const size_t unflattenedDisplayCost = calculateDisplayCost(layers); mUnflattenedDisplayCost += unflattenedDisplayCost; @@ -113,7 +112,7 @@ void Flattener::renderCachedSets( const OutputCompositionState& outputState, std::optional<std::chrono::steady_clock::time_point> renderDeadline, bool deviceHandlesColorTransform) { - ATRACE_CALL(); + SFTRACE_CALL(); if (!mNewCachedSet) { return; @@ -121,7 +120,7 @@ void Flattener::renderCachedSets( // Ensure that a cached set has a valid buffer first if (mNewCachedSet->hasRenderedBuffer()) { - ATRACE_NAME("mNewCachedSet->hasRenderedBuffer()"); + SFTRACE_NAME("mNewCachedSet->hasRenderedBuffer()"); return; } @@ -138,13 +137,13 @@ void Flattener::renderCachedSets( if (mNewCachedSet->getSkipCount() <= mTunables.mRenderScheduling->maxDeferRenderAttempts) { - ATRACE_FORMAT("DeadlinePassed: exceeded deadline by: %d us", - std::chrono::duration_cast<std::chrono::microseconds>( - estimatedRenderFinish - *renderDeadline) - .count()); + SFTRACE_FORMAT("DeadlinePassed: exceeded deadline by: %d us", + std::chrono::duration_cast<std::chrono::microseconds>( + estimatedRenderFinish - *renderDeadline) + .count()); return; } else { - ATRACE_NAME("DeadlinePassed: exceeded max skips"); + SFTRACE_NAME("DeadlinePassed: exceeded max skips"); } } } @@ -271,7 +270,7 @@ NonBufferHash Flattener::computeLayersHash() const{ // was already populated with these layers, i.e. on the second and following // calls with the same geometry. bool Flattener::mergeWithCachedSets(const std::vector<const LayerState*>& layers, time_point now) { - ATRACE_CALL(); + SFTRACE_CALL(); std::vector<CachedSet> merged; if (mLayers.empty()) { @@ -415,7 +414,7 @@ bool Flattener::mergeWithCachedSets(const std::vector<const LayerState*>& layers } std::vector<Flattener::Run> Flattener::findCandidateRuns(time_point now) const { - ATRACE_CALL(); + SFTRACE_CALL(); std::vector<Run> runs; bool isPartOfRun = false; Run::Builder builder; @@ -431,8 +430,8 @@ std::vector<Flattener::Run> Flattener::findCandidateRuns(time_point now) const { if (!layerIsInactive && currentSet->getLayerCount() == kNumLayersFpsConsideration) { auto layerFps = currentSet->getFirstLayer().getState()->getFps(); if (layerFps > 0 && layerFps <= kFpsActiveThreshold) { - ATRACE_FORMAT("layer is considered inactive due to low FPS [%s] %f", - currentSet->getFirstLayer().getName().c_str(), layerFps); + SFTRACE_FORMAT("layer is considered inactive due to low FPS [%s] %f", + currentSet->getFirstLayer().getName().c_str(), layerFps); layerIsInactive = true; } } @@ -494,7 +493,7 @@ std::optional<Flattener::Run> Flattener::findBestRun(std::vector<Flattener::Run> } void Flattener::buildCachedSets(time_point now) { - ATRACE_CALL(); + SFTRACE_CALL(); if (mLayers.empty()) { ALOGV("[%s] No layers found, returning", __func__); return; @@ -508,7 +507,7 @@ void Flattener::buildCachedSets(time_point now) { for (const CachedSet& layer : mLayers) { // TODO (b/191997217): make it less aggressive, and sync with findCandidateRuns if (layer.hasProtectedLayers()) { - ATRACE_NAME("layer->hasProtectedLayers()"); + SFTRACE_NAME("layer->hasProtectedLayers()"); return; } } diff --git a/services/surfaceflinger/CompositionEngine/src/planner/Planner.cpp b/services/surfaceflinger/CompositionEngine/src/planner/Planner.cpp index 5e6cade56f..d114ff79a1 100644 --- a/services/surfaceflinger/CompositionEngine/src/planner/Planner.cpp +++ b/services/surfaceflinger/CompositionEngine/src/planner/Planner.cpp @@ -21,11 +21,11 @@ #define ATRACE_TAG ATRACE_TAG_GRAPHICS #include <android-base/properties.h> +#include <common/trace.h> #include <compositionengine/LayerFECompositionState.h> #include <compositionengine/impl/OutputLayerCompositionState.h> #include <compositionengine/impl/planner/Planner.h> -#include <utils/Trace.h> #include <chrono> namespace android::compositionengine::impl::planner { @@ -83,7 +83,7 @@ void Planner::setDisplaySize(ui::Size size) { void Planner::plan( compositionengine::Output::OutputLayersEnumerator<compositionengine::Output>&& layers) { - ATRACE_CALL(); + SFTRACE_CALL(); std::unordered_set<LayerId> removedLayers; removedLayers.reserve(mPreviousLayers.size()); @@ -165,7 +165,7 @@ void Planner::plan( void Planner::reportFinalPlan( compositionengine::Output::OutputLayersEnumerator<compositionengine::Output>&& layers) { - ATRACE_CALL(); + SFTRACE_CALL(); if (!mPredictorEnabled) { return; } @@ -204,7 +204,7 @@ void Planner::reportFinalPlan( void Planner::renderCachedSets(const OutputCompositionState& outputState, std::optional<std::chrono::steady_clock::time_point> renderDeadline, bool deviceHandlesColorTransform) { - ATRACE_CALL(); + SFTRACE_CALL(); mFlattener.renderCachedSets(outputState, renderDeadline, deviceHandlesColorTransform); } diff --git a/services/surfaceflinger/Display/DisplayModeController.cpp b/services/surfaceflinger/Display/DisplayModeController.cpp index a6a9bec3c3..c43d585270 100644 --- a/services/surfaceflinger/Display/DisplayModeController.cpp +++ b/services/surfaceflinger/Display/DisplayModeController.cpp @@ -83,7 +83,7 @@ auto DisplayModeController::setDesiredMode(PhysicalDisplayId displayId, FTL_EXPECT(mDisplays.get(displayId).ok_or(DesiredModeAction::None)).get(); { - ATRACE_NAME(displayPtr->concatId(__func__).c_str()); + SFTRACE_NAME(displayPtr->concatId(__func__).c_str()); ALOGD("%s %s", displayPtr->concatId(__func__).c_str(), to_string(desiredMode).c_str()); std::scoped_lock lock(displayPtr->desiredModeLock); @@ -204,7 +204,7 @@ bool DisplayModeController::initiateModeChange(PhysicalDisplayId displayId, return false; } - ATRACE_INT(displayPtr->pendingModeFpsTrace.c_str(), mode.getVsyncRate().getIntValue()); + SFTRACE_INT(displayPtr->pendingModeFpsTrace.c_str(), mode.getVsyncRate().getIntValue()); return true; } @@ -227,8 +227,8 @@ void DisplayModeController::setActiveModeLocked(PhysicalDisplayId displayId, Dis Fps vsyncRate, Fps renderFps) { const auto& displayPtr = FTL_TRY(mDisplays.get(displayId).ok_or(ftl::Unit())).get(); - ATRACE_INT(displayPtr->activeModeFpsTrace.c_str(), vsyncRate.getIntValue()); - ATRACE_INT(displayPtr->renderRateFpsTrace.c_str(), renderFps.getIntValue()); + SFTRACE_INT(displayPtr->activeModeFpsTrace.c_str(), vsyncRate.getIntValue()); + SFTRACE_INT(displayPtr->renderRateFpsTrace.c_str(), renderFps.getIntValue()); displayPtr->selectorPtr->setActiveMode(modeId, renderFps); diff --git a/services/surfaceflinger/DisplayDevice.cpp b/services/surfaceflinger/DisplayDevice.cpp index 27ea4a9865..8288b99864 100644 --- a/services/surfaceflinger/DisplayDevice.cpp +++ b/services/surfaceflinger/DisplayDevice.cpp @@ -24,6 +24,7 @@ #define ATRACE_TAG ATRACE_TAG_GRAPHICS +#include <common/trace.h> #include <compositionengine/CompositionEngine.h> #include <compositionengine/Display.h> #include <compositionengine/DisplayColorProfile.h> @@ -398,7 +399,7 @@ void DisplayDevice::enableHdrSdrRatioOverlay(bool enable) { } void DisplayDevice::updateHdrSdrRatioOverlayRatio(float currentHdrSdrRatio) { - ATRACE_CALL(); + SFTRACE_CALL(); mHdrSdrRatio = currentHdrSdrRatio; if (mHdrSdrRatioOverlay) { mHdrSdrRatioOverlay->changeHdrSdrRatio(currentHdrSdrRatio); @@ -440,7 +441,7 @@ void DisplayDevice::enableRefreshRateOverlay(bool enable, bool setByHwc, Fps ref } void DisplayDevice::updateRefreshRateOverlayRate(Fps refreshRate, Fps renderFps, bool setByHwc) { - ATRACE_CALL(); + SFTRACE_CALL(); if (mRefreshRateOverlay) { if (!mRefreshRateOverlay->isSetByHwc() || setByHwc) { if (mRefreshRateSelector->isVrrDevice() && !mRefreshRateOverlay->isSetByHwc()) { diff --git a/services/surfaceflinger/DisplayHardware/AidlComposerHal.cpp b/services/surfaceflinger/DisplayHardware/AidlComposerHal.cpp index 362ab9c39e..d50a0bcec1 100644 --- a/services/surfaceflinger/DisplayHardware/AidlComposerHal.cpp +++ b/services/surfaceflinger/DisplayHardware/AidlComposerHal.cpp @@ -25,9 +25,8 @@ #include <android/binder_ibinder_platform.h> #include <android/binder_manager.h> #include <common/FlagManager.h> -#include <gui/TraceUtils.h> +#include <common/trace.h> #include <log/log.h> -#include <utils/Trace.h> #include <aidl/android/hardware/graphics/composer3/BnComposerCallback.h> @@ -677,7 +676,7 @@ Error AidlComposer::getReleaseFences(Display display, std::vector<Layer>* outLay Error AidlComposer::presentDisplay(Display display, int* outPresentFence) { const auto displayId = translate<int64_t>(display); - ATRACE_FORMAT("HwcPresentDisplay %" PRId64, displayId); + SFTRACE_FORMAT("HwcPresentDisplay %" PRId64, displayId); Error error = Error::NONE; mMutex.lock_shared(); @@ -810,7 +809,7 @@ Error AidlComposer::validateDisplay(Display display, nsecs_t expectedPresentTime int32_t frameIntervalNs, uint32_t* outNumTypes, uint32_t* outNumRequests) { const auto displayId = translate<int64_t>(display); - ATRACE_FORMAT("HwcValidateDisplay %" PRId64, displayId); + SFTRACE_FORMAT("HwcValidateDisplay %" PRId64, displayId); Error error = Error::NONE; mMutex.lock_shared(); @@ -840,7 +839,7 @@ Error AidlComposer::presentOrValidateDisplay(Display display, nsecs_t expectedPr uint32_t* outNumRequests, int* outPresentFence, uint32_t* state) { const auto displayId = translate<int64_t>(display); - ATRACE_FORMAT("HwcPresentOrValidateDisplay %" PRId64, displayId); + SFTRACE_FORMAT("HwcPresentOrValidateDisplay %" PRId64, displayId); Error error = Error::NONE; mMutex.lock_shared(); diff --git a/services/surfaceflinger/DisplayHardware/HWComposer.cpp b/services/surfaceflinger/DisplayHardware/HWComposer.cpp index 3d285a84ef..73fa855c3c 100644 --- a/services/surfaceflinger/DisplayHardware/HWComposer.cpp +++ b/services/surfaceflinger/DisplayHardware/HWComposer.cpp @@ -28,16 +28,15 @@ #include "HWComposer.h" #include <android-base/properties.h> +#include <common/trace.h> #include <compositionengine/Output.h> #include <compositionengine/OutputLayer.h> #include <compositionengine/impl/OutputLayerCompositionState.h> #include <ftl/concat.h> -#include <gui/TraceUtils.h> #include <log/log.h> #include <ui/DebugUtils.h> #include <ui/GraphicBuffer.h> #include <utils/Errors.h> -#include <utils/Trace.h> #include "../Layer.h" // needed only for debugging #include "../SurfaceFlingerProperties.h" @@ -178,8 +177,8 @@ std::optional<PhysicalDisplayId> HWComposer::onVsync(hal::HWDisplayId hwcDisplay displayData.lastPresentTimestamp = timestamp; } - ATRACE_INT(ftl::Concat("HW_VSYNC_", displayIdOpt->value).c_str(), - displayData.vsyncTraceToggle); + SFTRACE_INT(ftl::Concat("HW_VSYNC_", displayIdOpt->value).c_str(), + displayData.vsyncTraceToggle); displayData.vsyncTraceToggle = !displayData.vsyncTraceToggle; return displayIdOpt; @@ -428,14 +427,14 @@ void HWComposer::setVsyncEnabled(PhysicalDisplayId displayId, hal::Vsync enabled return; } - ATRACE_CALL(); + SFTRACE_CALL(); auto error = displayData.hwcDisplay->setVsyncEnabled(enabled); RETURN_IF_HWC_ERROR(error, displayId); displayData.vsyncEnabled = enabled; - ATRACE_INT(ftl::Concat("HW_VSYNC_ON_", displayId.value).c_str(), - enabled == hal::Vsync::ENABLE ? 1 : 0); + SFTRACE_INT(ftl::Concat("HW_VSYNC_ON_", displayId.value).c_str(), + enabled == hal::Vsync::ENABLE ? 1 : 0); } status_t HWComposer::setClientTarget(HalDisplayId displayId, uint32_t slot, @@ -455,7 +454,7 @@ status_t HWComposer::getDeviceCompositionChanges( std::optional<std::chrono::steady_clock::time_point> earliestPresentTime, nsecs_t expectedPresentTime, Fps frameInterval, std::optional<android::HWComposer::DeviceRequestedChanges>* outChanges) { - ATRACE_CALL(); + SFTRACE_CALL(); RETURN_IF_INVALID_DISPLAY(displayId, BAD_INDEX); @@ -493,7 +492,7 @@ status_t HWComposer::getDeviceCompositionChanges( }(); displayData.validateWasSkipped = false; - ATRACE_FORMAT("NextFrameInterval %d_Hz", frameInterval.getIntValue()); + SFTRACE_FORMAT("NextFrameInterval %d_Hz", frameInterval.getIntValue()); if (canSkipValidate) { sp<Fence> outPresentFence = Fence::NO_FENCE; uint32_t state = UINT32_MAX; @@ -568,7 +567,7 @@ sp<Fence> HWComposer::getLayerReleaseFence(HalDisplayId displayId, HWC2::Layer* status_t HWComposer::presentAndGetReleaseFences( HalDisplayId displayId, std::optional<std::chrono::steady_clock::time_point> earliestPresentTime) { - ATRACE_CALL(); + SFTRACE_CALL(); RETURN_IF_INVALID_DISPLAY(displayId, BAD_INDEX); @@ -584,7 +583,7 @@ status_t HWComposer::presentAndGetReleaseFences( } if (earliestPresentTime) { - ATRACE_NAME("wait for earliest present time"); + SFTRACE_NAME("wait for earliest present time"); std::this_thread::sleep_until(*earliestPresentTime); } @@ -897,9 +896,9 @@ status_t HWComposer::setRefreshRateChangedCallbackDebugEnabled(PhysicalDisplayId status_t HWComposer::notifyExpectedPresent(PhysicalDisplayId displayId, TimePoint expectedPresentTime, Fps frameInterval) { RETURN_IF_INVALID_DISPLAY(displayId, BAD_INDEX); - ATRACE_FORMAT("%s ExpectedPresentTime in %.2fms frameInterval %.2fms", __func__, - ticks<std::milli, float>(expectedPresentTime - TimePoint::now()), - ticks<std::milli, float>(Duration::fromNs(frameInterval.getPeriodNsecs()))); + SFTRACE_FORMAT("%s ExpectedPresentTime in %.2fms frameInterval %.2fms", __func__, + ticks<std::milli, float>(expectedPresentTime - TimePoint::now()), + ticks<std::milli, float>(Duration::fromNs(frameInterval.getPeriodNsecs()))); const auto error = mComposer->notifyExpectedPresent(mDisplayData[displayId].hwcDisplay->getId(), expectedPresentTime.ns(), frameInterval.getPeriodNsecs()); @@ -1149,7 +1148,7 @@ void HWComposer::loadHdrConversionCapabilities() { status_t HWComposer::setIdleTimerEnabled(PhysicalDisplayId displayId, std::chrono::milliseconds timeout) { - ATRACE_CALL(); + SFTRACE_CALL(); RETURN_IF_INVALID_DISPLAY(displayId, BAD_INDEX); const auto error = mDisplayData[displayId].hwcDisplay->setIdleTimerEnabled(timeout); if (error == hal::Error::UNSUPPORTED) { @@ -1168,7 +1167,7 @@ bool HWComposer::hasDisplayIdleTimerCapability(PhysicalDisplayId displayId) cons } Hwc2::AidlTransform HWComposer::getPhysicalDisplayOrientation(PhysicalDisplayId displayId) const { - ATRACE_CALL(); + SFTRACE_CALL(); RETURN_IF_INVALID_DISPLAY(displayId, Hwc2::AidlTransform::NONE); Hwc2::AidlTransform outTransform; const auto& hwcDisplay = mDisplayData.at(displayId).hwcDisplay; diff --git a/services/surfaceflinger/DisplayHardware/HidlComposerHal.cpp b/services/surfaceflinger/DisplayHardware/HidlComposerHal.cpp index 12ab2c284a..c5008d8dd5 100644 --- a/services/surfaceflinger/DisplayHardware/HidlComposerHal.cpp +++ b/services/surfaceflinger/DisplayHardware/HidlComposerHal.cpp @@ -27,11 +27,11 @@ #include <SurfaceFlingerProperties.h> #include <aidl/android/hardware/graphics/common/DisplayHotplugEvent.h> #include <android/binder_manager.h> +#include <common/trace.h> #include <composer-command-buffer/2.2/ComposerCommandBuffer.h> #include <hidl/HidlTransportSupport.h> #include <hidl/HidlTransportUtils.h> #include <log/log.h> -#include <utils/Trace.h> #include "HWC2.h" #include "Hal.h" @@ -588,7 +588,7 @@ Error HidlComposer::getReleaseFences(Display display, std::vector<Layer>* outLay } Error HidlComposer::presentDisplay(Display display, int* outPresentFence) { - ATRACE_NAME("HwcPresentDisplay"); + SFTRACE_NAME("HwcPresentDisplay"); mWriter.selectDisplay(display); mWriter.presentDisplay(); @@ -676,7 +676,7 @@ Error HidlComposer::setClientTargetSlotCount(Display display) { Error HidlComposer::validateDisplay(Display display, nsecs_t /*expectedPresentTime*/, int32_t /*frameIntervalNs*/, uint32_t* outNumTypes, uint32_t* outNumRequests) { - ATRACE_NAME("HwcValidateDisplay"); + SFTRACE_NAME("HwcValidateDisplay"); mWriter.selectDisplay(display); mWriter.validateDisplay(); @@ -694,7 +694,7 @@ Error HidlComposer::presentOrValidateDisplay(Display display, nsecs_t /*expected int32_t /*frameIntervalNs*/, uint32_t* outNumTypes, uint32_t* outNumRequests, int* outPresentFence, uint32_t* state) { - ATRACE_NAME("HwcPresentOrValidateDisplay"); + SFTRACE_NAME("HwcPresentOrValidateDisplay"); mWriter.selectDisplay(display); mWriter.presentOrvalidateDisplay(); diff --git a/services/surfaceflinger/DisplayHardware/PowerAdvisor.cpp b/services/surfaceflinger/DisplayHardware/PowerAdvisor.cpp index 6c1a81314d..da56014530 100644 --- a/services/surfaceflinger/DisplayHardware/PowerAdvisor.cpp +++ b/services/surfaceflinger/DisplayHardware/PowerAdvisor.cpp @@ -27,9 +27,9 @@ #include <optional> #include <android-base/properties.h> +#include <common/trace.h> #include <utils/Log.h> #include <utils/Mutex.h> -#include <utils/Trace.h> #include <binder/IServiceManager.h> @@ -74,9 +74,9 @@ std::chrono::milliseconds getUpdateTimeout() { void traceExpensiveRendering(bool enabled) { if (enabled) { - ATRACE_ASYNC_BEGIN("ExpensiveRendering", 0); + SFTRACE_ASYNC_BEGIN("ExpensiveRendering", 0); } else { - ATRACE_ASYNC_END("ExpensiveRendering", 0); + SFTRACE_ASYNC_END("ExpensiveRendering", 0); } } @@ -210,7 +210,7 @@ void PowerAdvisor::sendHintSessionHint(SessionHint hint) { ALOGV("Power hint session is not enabled, skip sending session hint"); return; } - ATRACE_CALL(); + SFTRACE_CALL(); if (sTraceHintSessionData) ATRACE_INT("Session hint", static_cast<int>(hint)); { std::scoped_lock lock(mHintSessionMutex); @@ -295,7 +295,7 @@ void PowerAdvisor::updateTargetWorkDuration(Duration targetDuration) { ALOGV("Power hint session is not enabled, skipping target update"); return; } - ATRACE_CALL(); + SFTRACE_CALL(); { mTargetDuration = targetDuration; if (sTraceHintSessionData) ATRACE_INT64("Time target", targetDuration.ns()); @@ -324,7 +324,7 @@ void PowerAdvisor::reportActualWorkDuration() { ALOGV("Actual work duration power hint cannot be sent, skipping"); return; } - ATRACE_CALL(); + SFTRACE_CALL(); std::optional<WorkDuration> actualDuration = estimateWorkDuration(); if (!actualDuration.has_value() || actualDuration->durationNanos < 0) { ALOGV("Failed to send actual work duration, skipping"); @@ -332,16 +332,16 @@ void PowerAdvisor::reportActualWorkDuration() { } actualDuration->durationNanos += sTargetSafetyMargin.ns(); if (sTraceHintSessionData) { - ATRACE_INT64("Measured duration", actualDuration->durationNanos); - ATRACE_INT64("Target error term", actualDuration->durationNanos - mTargetDuration.ns()); - ATRACE_INT64("Reported duration", actualDuration->durationNanos); + SFTRACE_INT64("Measured duration", actualDuration->durationNanos); + SFTRACE_INT64("Target error term", actualDuration->durationNanos - mTargetDuration.ns()); + SFTRACE_INT64("Reported duration", actualDuration->durationNanos); if (supportsGpuReporting()) { - ATRACE_INT64("Reported cpu duration", actualDuration->cpuDurationNanos); - ATRACE_INT64("Reported gpu duration", actualDuration->gpuDurationNanos); + SFTRACE_INT64("Reported cpu duration", actualDuration->cpuDurationNanos); + SFTRACE_INT64("Reported gpu duration", actualDuration->gpuDurationNanos); } - ATRACE_INT64("Reported target", mLastTargetDurationSent.ns()); - ATRACE_INT64("Reported target error term", - actualDuration->durationNanos - mLastTargetDurationSent.ns()); + SFTRACE_INT64("Reported target", mLastTargetDurationSent.ns()); + SFTRACE_INT64("Reported target error term", + actualDuration->durationNanos - mLastTargetDurationSent.ns()); } ALOGV("Sending actual work duration of: %" PRId64 " with cpu: %" PRId64 " and gpu: %" PRId64 @@ -664,9 +664,9 @@ std::optional<WorkDuration> PowerAdvisor::estimateWorkDuration() { .gpuDurationNanos = supportsGpuReporting() ? estimatedGpuDuration.ns() : 0, }; if (sTraceHintSessionData) { - ATRACE_INT64("Idle duration", idleDuration.ns()); - ATRACE_INT64("Total duration", totalDuration.ns()); - ATRACE_INT64("Flinger duration", flingerDuration.ns()); + SFTRACE_INT64("Idle duration", idleDuration.ns()); + SFTRACE_INT64("Total duration", totalDuration.ns()); + SFTRACE_INT64("Flinger duration", flingerDuration.ns()); } return std::make_optional(duration); } diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp index f671006149..55505650e3 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp @@ -22,8 +22,8 @@ #include <android-base/stringprintf.h> #include <common/FlagManager.h> +#include <common/trace.h> #include <utils/Log.h> -#include <utils/Trace.h> #include <chrono> #include <cinttypes> @@ -829,7 +829,7 @@ void SurfaceFrame::trace(int64_t displayFrameToken, nsecs_t monoBootOffset) cons namespace impl { int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) { - ATRACE_CALL(); + SFTRACE_CALL(); std::scoped_lock lock(mMutex); while (mPredictions.size() >= kMaxTokens) { mPredictions.erase(mPredictions.begin()); @@ -875,7 +875,7 @@ void FrameTimeline::registerDataSource() { std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken( const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid, uid_t ownerUid, int32_t layerId, std::string layerName, std::string debugName, bool isBuffer, GameMode gameMode) { - ATRACE_CALL(); + SFTRACE_CALL(); if (frameTimelineInfo.vsyncId == FrameTimelineInfo::INVALID_VSYNC_ID) { return std::make_shared<SurfaceFrame>(frameTimelineInfo, ownerPid, ownerUid, layerId, std::move(layerName), std::move(debugName), @@ -911,14 +911,14 @@ FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats, } void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) { - ATRACE_CALL(); + SFTRACE_CALL(); std::scoped_lock lock(mMutex); mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame); } void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, Fps refreshRate, Fps renderRate) { - ATRACE_CALL(); + SFTRACE_CALL(); std::scoped_lock lock(mMutex); mCurrentDisplayFrame->onSfWakeUp(token, refreshRate, renderRate, mTokenManager.getPredictionsForToken(token), wakeUpTime); @@ -927,7 +927,7 @@ void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, Fps refreshRa void FrameTimeline::setSfPresent(nsecs_t sfPresentTime, const std::shared_ptr<FenceTime>& presentFence, const std::shared_ptr<FenceTime>& gpuFence) { - ATRACE_CALL(); + SFTRACE_CALL(); std::scoped_lock lock(mMutex); mCurrentDisplayFrame->setActualEndTime(sfPresentTime); mCurrentDisplayFrame->setGpuFence(gpuFence); @@ -937,7 +937,7 @@ void FrameTimeline::setSfPresent(nsecs_t sfPresentTime, } void FrameTimeline::onCommitNotComposited() { - ATRACE_CALL(); + SFTRACE_CALL(); std::scoped_lock lock(mMutex); mCurrentDisplayFrame->onCommitNotComposited(); mCurrentDisplayFrame.reset(); @@ -1516,7 +1516,7 @@ void FrameTimeline::dumpJank(std::string& result) { } void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) { - ATRACE_CALL(); + SFTRACE_CALL(); std::unordered_map<std::string, bool> argsMap; for (size_t i = 0; i < args.size(); i++) { argsMap[std::string(String8(args[i]).c_str())] = true; diff --git a/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp b/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp index 39a6b777bb..f4335f36bc 100644 --- a/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp +++ b/services/surfaceflinger/FrontEnd/LayerHierarchy.cpp @@ -413,11 +413,11 @@ void LayerHierarchyBuilder::doUpdate( void LayerHierarchyBuilder::update(LayerLifecycleManager& layerLifecycleManager) { if (!mInitialized) { - ATRACE_NAME("LayerHierarchyBuilder:init"); + SFTRACE_NAME("LayerHierarchyBuilder:init"); init(layerLifecycleManager.getLayers()); } else if (layerLifecycleManager.getGlobalChanges().test( RequestedLayerState::Changes::Hierarchy)) { - ATRACE_NAME("LayerHierarchyBuilder:update"); + SFTRACE_NAME("LayerHierarchyBuilder:update"); doUpdate(layerLifecycleManager.getLayers(), layerLifecycleManager.getDestroyedLayers()); } else { return; // nothing to do @@ -426,7 +426,7 @@ void LayerHierarchyBuilder::update(LayerLifecycleManager& layerLifecycleManager) uint32_t invalidRelativeRoot; bool hasRelZLoop = mRoot.hasRelZLoop(invalidRelativeRoot); while (hasRelZLoop) { - ATRACE_NAME("FixRelZLoop"); + SFTRACE_NAME("FixRelZLoop"); TransactionTraceWriter::getInstance().invoke("relz_loop_detected", /*overwrite=*/false); layerLifecycleManager.fixRelativeZLoop(invalidRelativeRoot); diff --git a/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp b/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp index a4ffd51d43..2b1b2c85b3 100644 --- a/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp +++ b/services/surfaceflinger/FrontEnd/LayerSnapshotBuilder.cpp @@ -23,8 +23,8 @@ #include <optional> #include <common/FlagManager.h> +#include <common/trace.h> #include <ftl/small_map.h> -#include <gui/TraceUtils.h> #include <ui/DisplayMap.h> #include <ui/FloatRect.h> @@ -402,7 +402,7 @@ bool LayerSnapshotBuilder::tryFastUpdate(const Args& args) { // There are only content changes which do not require any child layer snapshots to be updated. ALOGV("%s", __func__); - ATRACE_NAME("FastPath"); + SFTRACE_NAME("FastPath"); uint32_t primaryDisplayRotationFlags = getPrimaryDisplayRotationFlags(args.displays); if (forceUpdate || args.displayChanges) { @@ -436,7 +436,7 @@ bool LayerSnapshotBuilder::tryFastUpdate(const Args& args) { } void LayerSnapshotBuilder::updateSnapshots(const Args& args) { - ATRACE_NAME("UpdateSnapshots"); + SFTRACE_NAME("UpdateSnapshots"); LayerSnapshot rootSnapshot = args.rootSnapshot; if (args.parentCrop) { rootSnapshot.geomLayerBounds = *args.parentCrop; diff --git a/services/surfaceflinger/FrontEnd/RequestedLayerState.cpp b/services/surfaceflinger/FrontEnd/RequestedLayerState.cpp index c3c299964a..17d3f4bf38 100644 --- a/services/surfaceflinger/FrontEnd/RequestedLayerState.cpp +++ b/services/surfaceflinger/FrontEnd/RequestedLayerState.cpp @@ -19,7 +19,7 @@ #undef LOG_TAG #define LOG_TAG "SurfaceFlinger" -#include <gui/TraceUtils.h> +#include <common/trace.h> #include <log/log.h> #include <private/android_filesystem_config.h> #include <sys/types.h> @@ -581,8 +581,8 @@ bool RequestedLayerState::backpressureEnabled() const { bool RequestedLayerState::isSimpleBufferUpdate(const layer_state_t& s) const { static constexpr uint64_t requiredFlags = layer_state_t::eBufferChanged; if ((s.what & requiredFlags) != requiredFlags) { - ATRACE_FORMAT_INSTANT("%s: false [missing required flags 0x%" PRIx64 "]", __func__, - (s.what | requiredFlags) & ~s.what); + SFTRACE_FORMAT_INSTANT("%s: false [missing required flags 0x%" PRIx64 "]", __func__, + (s.what | requiredFlags) & ~s.what); return false; } @@ -594,8 +594,8 @@ bool RequestedLayerState::isSimpleBufferUpdate(const layer_state_t& s) const { ? 0 : (layer_state_t::eAutoRefreshChanged | layer_state_t::eFlagsChanged)); if (s.what & deniedFlags) { - ATRACE_FORMAT_INSTANT("%s: false [has denied flags 0x%" PRIx64 "]", __func__, - s.what & deniedFlags); + SFTRACE_FORMAT_INSTANT("%s: false [has denied flags 0x%" PRIx64 "]", __func__, + s.what & deniedFlags); return false; } @@ -616,8 +616,8 @@ bool RequestedLayerState::isSimpleBufferUpdate(const layer_state_t& s) const { ? layer_state_t::eFlagsChanged : 0); if (changedFlags & deniedChanges) { - ATRACE_FORMAT_INSTANT("%s: false [has denied changes flags 0x%" PRIx64 "]", __func__, - changedFlags & deniedChanges); + SFTRACE_FORMAT_INSTANT("%s: false [has denied changes flags 0x%" PRIx64 "]", __func__, + changedFlags & deniedChanges); return false; } diff --git a/services/surfaceflinger/FrontEnd/TransactionHandler.cpp b/services/surfaceflinger/FrontEnd/TransactionHandler.cpp index d3d950974f..a1e8213132 100644 --- a/services/surfaceflinger/FrontEnd/TransactionHandler.cpp +++ b/services/surfaceflinger/FrontEnd/TransactionHandler.cpp @@ -19,9 +19,9 @@ #define LOG_TAG "SurfaceFlinger" #define ATRACE_TAG ATRACE_TAG_GRAPHICS +#include <common/trace.h> #include <cutils/trace.h> #include <utils/Log.h> -#include <utils/Trace.h> #include "FrontEnd/LayerLog.h" #include "TransactionHandler.h" @@ -31,7 +31,7 @@ namespace android::surfaceflinger::frontend { void TransactionHandler::queueTransaction(TransactionState&& state) { mLocklessTransactionQueue.push(std::move(state)); mPendingTransactionCount.fetch_add(1); - ATRACE_INT("TransactionQueue", static_cast<int>(mPendingTransactionCount.load())); + SFTRACE_INT("TransactionQueue", static_cast<int>(mPendingTransactionCount.load())); } void TransactionHandler::collectTransactions() { @@ -71,7 +71,7 @@ std::vector<TransactionState> TransactionHandler::flushTransactions() { applyUnsignaledBufferTransaction(transactions, flushState); mPendingTransactionCount.fetch_sub(transactions.size()); - ATRACE_INT("TransactionQueue", static_cast<int>(mPendingTransactionCount.load())); + SFTRACE_INT("TransactionQueue", static_cast<int>(mPendingTransactionCount.load())); return transactions; } @@ -83,7 +83,7 @@ void TransactionHandler::applyUnsignaledBufferTransaction( // only apply an unsignaled buffer transaction if it's the first one if (!transactions.empty()) { - ATRACE_NAME("fence unsignaled"); + SFTRACE_NAME("fence unsignaled"); return; } diff --git a/services/surfaceflinger/HdrLayerInfoReporter.cpp b/services/surfaceflinger/HdrLayerInfoReporter.cpp index 278833244c..85921bb72d 100644 --- a/services/surfaceflinger/HdrLayerInfoReporter.cpp +++ b/services/surfaceflinger/HdrLayerInfoReporter.cpp @@ -19,8 +19,8 @@ #define ATRACE_TAG ATRACE_TAG_GRAPHICS #include <android-base/stringprintf.h> +#include <common/trace.h> #include <inttypes.h> -#include <utils/Trace.h> #include "HdrLayerInfoReporter.h" @@ -29,7 +29,7 @@ namespace android { using base::StringAppendF; void HdrLayerInfoReporter::dispatchHdrLayerInfo(const HdrLayerInfo& info) { - ATRACE_CALL(); + SFTRACE_CALL(); if (mHdrInfoHistory.size() == 0 || mHdrInfoHistory.back().info != info) { mHdrInfoHistory.next() = EventHistoryEntry{info}; } @@ -47,7 +47,7 @@ void HdrLayerInfoReporter::dispatchHdrLayerInfo(const HdrLayerInfo& info) { } for (const auto& listener : toInvoke) { - ATRACE_NAME("invoking onHdrLayerInfoChanged"); + SFTRACE_NAME("invoking onHdrLayerInfoChanged"); listener->onHdrLayerInfoChanged(info.numberOfHdrLayers, info.maxW, info.maxH, info.flags, info.maxDesiredHdrSdrRatio); } diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp index e758741afb..86c7d165e8 100644 --- a/services/surfaceflinger/Layer.cpp +++ b/services/surfaceflinger/Layer.cpp @@ -27,6 +27,7 @@ #include <android-base/properties.h> #include <android-base/stringprintf.h> #include <binder/IPCThreadState.h> +#include <common/trace.h> #include <compositionengine/CompositionEngine.h> #include <compositionengine/Display.h> #include <compositionengine/LayerFECompositionState.h> @@ -39,7 +40,6 @@ #include <ftl/fake_guard.h> #include <gui/BufferItem.h> #include <gui/Surface.h> -#include <gui/TraceUtils.h> #include <math.h> #include <private/android_filesystem_config.h> #include <renderengine/RenderEngine.h> @@ -58,7 +58,6 @@ #include <utils/Log.h> #include <utils/NativeHandle.h> #include <utils/StopWatch.h> -#include <utils/Trace.h> #include <algorithm> #include <mutex> @@ -772,7 +771,7 @@ bool Layer::isSecure() const { // ---------------------------------------------------------------------------- uint32_t Layer::doTransaction(uint32_t flags) { - ATRACE_CALL(); + SFTRACE_CALL(); // TODO: This is unfortunate. mDrawingStateModified = mDrawingState.modified; @@ -2783,7 +2782,7 @@ void Layer::callReleaseBufferCallback(const sp<ITransactionCompletedListener>& l if (!listener) { return; } - ATRACE_FORMAT_INSTANT("callReleaseBufferCallback %s - %" PRIu64, getDebugName(), framenumber); + SFTRACE_FORMAT_INSTANT("callReleaseBufferCallback %s - %" PRIu64, getDebugName(), framenumber); uint32_t currentMaxAcquiredBufferCount = mFlinger->getMaxAcquiredBufferCountForCurrentRefreshRate(mOwnerUid); listener->onReleaseBuffer({buffer->getId(), framenumber}, @@ -2910,8 +2909,8 @@ void Layer::releasePendingBuffer(nsecs_t dequeueReadyTime) { handle->dequeueReadyTime = dequeueReadyTime; handle->currentMaxAcquiredBufferCount = mFlinger->getMaxAcquiredBufferCountForCurrentRefreshRate(mOwnerUid); - ATRACE_FORMAT_INSTANT("releasePendingBuffer %s - %" PRIu64, getDebugName(), - handle->previousReleaseCallbackId.framenumber); + SFTRACE_FORMAT_INSTANT("releasePendingBuffer %s - %" PRIu64, getDebugName(), + handle->previousReleaseCallbackId.framenumber); } for (auto& handle : mDrawingState.callbackHandles) { @@ -3090,13 +3089,13 @@ void Layer::resetDrawingStateBufferInfo() { bool Layer::setBuffer(std::shared_ptr<renderengine::ExternalTexture>& buffer, const BufferData& bufferData, nsecs_t postTime, nsecs_t desiredPresentTime, bool isAutoTimestamp, const FrameTimelineInfo& info) { - ATRACE_FORMAT("setBuffer %s - hasBuffer=%s", getDebugName(), (buffer ? "true" : "false")); + SFTRACE_FORMAT("setBuffer %s - hasBuffer=%s", getDebugName(), (buffer ? "true" : "false")); const bool frameNumberChanged = bufferData.flags.test(BufferData::BufferDataChange::frameNumberChanged); const uint64_t frameNumber = frameNumberChanged ? bufferData.frameNumber : mDrawingState.frameNumber + 1; - ATRACE_FORMAT_INSTANT("setBuffer %s - %" PRIu64, getDebugName(), frameNumber); + SFTRACE_FORMAT_INSTANT("setBuffer %s - %" PRIu64, getDebugName(), frameNumber); if (mDrawingState.buffer) { releasePreviousBuffer(); @@ -3191,10 +3190,10 @@ void Layer::setDesiredPresentTime(nsecs_t desiredPresentTime, bool isAutoTimesta } void Layer::recordLayerHistoryBufferUpdate(const scheduler::LayerProps& layerProps, nsecs_t now) { - ATRACE_CALL(); + SFTRACE_CALL(); const nsecs_t presentTime = [&] { if (!mDrawingState.isAutoTimestamp) { - ATRACE_FORMAT_INSTANT("desiredPresentTime"); + SFTRACE_FORMAT_INSTANT("desiredPresentTime"); return mDrawingState.desiredPresentTime; } @@ -3203,7 +3202,7 @@ void Layer::recordLayerHistoryBufferUpdate(const scheduler::LayerProps& layerPro mFlinger->mFrameTimeline->getTokenManager()->getPredictionsForToken( mDrawingState.latchedVsyncId); if (prediction.has_value()) { - ATRACE_FORMAT_INSTANT("predictedPresentTime"); + SFTRACE_FORMAT_INSTANT("predictedPresentTime"); mMaxTimeForUseVsyncId = prediction->presentTime + scheduler::LayerHistory::kMaxPeriodForHistory.count(); return prediction->presentTime; @@ -3241,7 +3240,7 @@ void Layer::recordLayerHistoryBufferUpdate(const scheduler::LayerProps& layerPro if (ATRACE_ENABLED() && presentTime > 0) { const auto presentIn = TimePoint::fromNs(presentTime) - TimePoint::now(); - ATRACE_FORMAT_INSTANT("presentIn %s", to_string(presentIn).c_str()); + SFTRACE_FORMAT_INSTANT("presentIn %s", to_string(presentIn).c_str()); } mFlinger->mScheduler->recordLayerHistory(sequence, layerProps, presentTime, now, @@ -3565,12 +3564,12 @@ void Layer::gatherBufferInfo() { ui::Dataspace dataspace = ui::Dataspace::UNKNOWN; status_t err = OK; { - ATRACE_NAME("getDataspace"); + SFTRACE_NAME("getDataspace"); err = mapper.getDataspace(mBufferInfo.mBuffer->getBuffer()->handle, &dataspace); } if (err != OK || dataspace != mBufferInfo.mDataspace) { { - ATRACE_NAME("setDataspace"); + SFTRACE_NAME("setDataspace"); err = mapper.setDataspace(mBufferInfo.mBuffer->getBuffer()->handle, static_cast<ui::Dataspace>(mBufferInfo.mDataspace)); } @@ -3634,7 +3633,7 @@ void Layer::decrementPendingBufferCount() { } void Layer::tracePendingBufferCount(int32_t pendingBuffers) { - ATRACE_INT(mBlastTransactionName.c_str(), pendingBuffers); + SFTRACE_INT(mBlastTransactionName.c_str(), pendingBuffers); } /* @@ -3712,41 +3711,41 @@ bool Layer::isSimpleBufferUpdate(const layer_state_t& s) const { : layer_state_t::eAutoRefreshChanged); if ((s.what & requiredFlags) != requiredFlags) { - ATRACE_FORMAT_INSTANT("%s: false [missing required flags 0x%" PRIx64 "]", __func__, - (s.what | requiredFlags) & ~s.what); + SFTRACE_FORMAT_INSTANT("%s: false [missing required flags 0x%" PRIx64 "]", __func__, + (s.what | requiredFlags) & ~s.what); return false; } if (s.what & deniedFlags) { - ATRACE_FORMAT_INSTANT("%s: false [has denied flags 0x%" PRIx64 "]", __func__, - s.what & deniedFlags); + SFTRACE_FORMAT_INSTANT("%s: false [has denied flags 0x%" PRIx64 "]", __func__, + s.what & deniedFlags); return false; } if (s.what & layer_state_t::ePositionChanged) { if (mRequestedTransform.tx() != s.x || mRequestedTransform.ty() != s.y) { - ATRACE_FORMAT_INSTANT("%s: false [ePositionChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [ePositionChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eAlphaChanged) { if (mDrawingState.color.a != s.color.a) { - ATRACE_FORMAT_INSTANT("%s: false [eAlphaChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eAlphaChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eColorTransformChanged) { if (mDrawingState.colorTransform != s.colorTransform) { - ATRACE_FORMAT_INSTANT("%s: false [eColorTransformChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eColorTransformChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eBackgroundColorChanged) { if (mDrawingState.bgColorLayer || s.bgColor.a != 0) { - ATRACE_FORMAT_INSTANT("%s: false [eBackgroundColorChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eBackgroundColorChanged changed]", __func__); return false; } } @@ -3756,92 +3755,92 @@ bool Layer::isSimpleBufferUpdate(const layer_state_t& s) const { mRequestedTransform.dtdy() != s.matrix.dtdy || mRequestedTransform.dtdx() != s.matrix.dtdx || mRequestedTransform.dsdy() != s.matrix.dsdy) { - ATRACE_FORMAT_INSTANT("%s: false [eMatrixChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eMatrixChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eCornerRadiusChanged) { if (mDrawingState.cornerRadius != s.cornerRadius) { - ATRACE_FORMAT_INSTANT("%s: false [eCornerRadiusChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eCornerRadiusChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eBackgroundBlurRadiusChanged) { if (mDrawingState.backgroundBlurRadius != static_cast<int>(s.backgroundBlurRadius)) { - ATRACE_FORMAT_INSTANT("%s: false [eBackgroundBlurRadiusChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eBackgroundBlurRadiusChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eBufferTransformChanged) { if (mDrawingState.bufferTransform != s.bufferTransform) { - ATRACE_FORMAT_INSTANT("%s: false [eBufferTransformChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eBufferTransformChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eTransformToDisplayInverseChanged) { if (mDrawingState.transformToDisplayInverse != s.transformToDisplayInverse) { - ATRACE_FORMAT_INSTANT("%s: false [eTransformToDisplayInverseChanged changed]", - __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eTransformToDisplayInverseChanged changed]", + __func__); return false; } } if (s.what & layer_state_t::eCropChanged) { if (mDrawingState.crop != s.crop) { - ATRACE_FORMAT_INSTANT("%s: false [eCropChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eCropChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eDataspaceChanged) { if (mDrawingState.dataspace != s.dataspace) { - ATRACE_FORMAT_INSTANT("%s: false [eDataspaceChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eDataspaceChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eHdrMetadataChanged) { if (mDrawingState.hdrMetadata != s.hdrMetadata) { - ATRACE_FORMAT_INSTANT("%s: false [eHdrMetadataChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eHdrMetadataChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eSidebandStreamChanged) { if (mDrawingState.sidebandStream != s.sidebandStream) { - ATRACE_FORMAT_INSTANT("%s: false [eSidebandStreamChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eSidebandStreamChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eColorSpaceAgnosticChanged) { if (mDrawingState.colorSpaceAgnostic != s.colorSpaceAgnostic) { - ATRACE_FORMAT_INSTANT("%s: false [eColorSpaceAgnosticChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eColorSpaceAgnosticChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eShadowRadiusChanged) { if (mDrawingState.shadowRadius != s.shadowRadius) { - ATRACE_FORMAT_INSTANT("%s: false [eShadowRadiusChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eShadowRadiusChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eFixedTransformHintChanged) { if (mDrawingState.fixedTransformHint != s.fixedTransformHint) { - ATRACE_FORMAT_INSTANT("%s: false [eFixedTransformHintChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eFixedTransformHintChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eTrustedOverlayChanged) { if (mDrawingState.isTrustedOverlay != (s.trustedOverlay == gui::TrustedOverlay::ENABLED)) { - ATRACE_FORMAT_INSTANT("%s: false [eTrustedOverlayChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eTrustedOverlayChanged changed]", __func__); return false; } } @@ -3850,28 +3849,28 @@ bool Layer::isSimpleBufferUpdate(const layer_state_t& s) const { StretchEffect temp = s.stretchEffect; temp.sanitize(); if (mDrawingState.stretchEffect != temp) { - ATRACE_FORMAT_INSTANT("%s: false [eStretchChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eStretchChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eBufferCropChanged) { if (mDrawingState.bufferCrop != s.bufferCrop) { - ATRACE_FORMAT_INSTANT("%s: false [eBufferCropChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eBufferCropChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eDestinationFrameChanged) { if (mDrawingState.destinationFrame != s.destinationFrame) { - ATRACE_FORMAT_INSTANT("%s: false [eDestinationFrameChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eDestinationFrameChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eDimmingEnabledChanged) { if (mDrawingState.dimmingEnabled != s.dimmingEnabled) { - ATRACE_FORMAT_INSTANT("%s: false [eDimmingEnabledChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eDimmingEnabledChanged changed]", __func__); return false; } } @@ -3879,14 +3878,14 @@ bool Layer::isSimpleBufferUpdate(const layer_state_t& s) const { if (s.what & layer_state_t::eExtendedRangeBrightnessChanged) { if (mDrawingState.currentHdrSdrRatio != s.currentHdrSdrRatio || mDrawingState.desiredHdrSdrRatio != s.desiredHdrSdrRatio) { - ATRACE_FORMAT_INSTANT("%s: false [eExtendedRangeBrightnessChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eExtendedRangeBrightnessChanged changed]", __func__); return false; } } if (s.what & layer_state_t::eDesiredHdrHeadroomChanged) { if (mDrawingState.desiredHdrSdrRatio != s.desiredHdrSdrRatio) { - ATRACE_FORMAT_INSTANT("%s: false [eDesiredHdrHeadroomChanged changed]", __func__); + SFTRACE_FORMAT_INSTANT("%s: false [eDesiredHdrHeadroomChanged changed]", __func__); return false; } } @@ -4078,8 +4077,8 @@ bool Layer::latchBuffer(bool& recomputeVisibleRegions, nsecs_t latchTime) { } bool Layer::latchBufferImpl(bool& recomputeVisibleRegions, nsecs_t latchTime, bool bgColorOnly) { - ATRACE_FORMAT_INSTANT("latchBuffer %s - %" PRIu64, getDebugName(), - getDrawingState().frameNumber); + SFTRACE_FORMAT_INSTANT("latchBuffer %s - %" PRIu64, getDebugName(), + getDrawingState().frameNumber); bool refreshRequired = latchSidebandStream(recomputeVisibleRegions); @@ -4090,7 +4089,7 @@ bool Layer::latchBufferImpl(bool& recomputeVisibleRegions, nsecs_t latchTime, bo // If the head buffer's acquire fence hasn't signaled yet, return and // try again later if (!fenceHasSignaled()) { - ATRACE_NAME("!fenceHasSignaled()"); + SFTRACE_NAME("!fenceHasSignaled()"); mFlinger->onLayerUpdate(); return false; } diff --git a/services/surfaceflinger/LayerFE.cpp b/services/surfaceflinger/LayerFE.cpp index c2251a858b..8f819b25e0 100644 --- a/services/surfaceflinger/LayerFE.cpp +++ b/services/surfaceflinger/LayerFE.cpp @@ -19,11 +19,10 @@ #define LOG_TAG "SurfaceFlinger" #define ATRACE_TAG ATRACE_TAG_GRAPHICS +#include <common/trace.h> #include <gui/GLConsumer.h> -#include <gui/TraceUtils.h> #include <math/vec3.h> #include <system/window.h> -#include <utils/Log.h> #include "LayerFE.h" #include "SurfaceFlinger.h" @@ -122,7 +121,7 @@ std::optional<compositionengine::LayerFE::LayerSettings> LayerFE::prepareClientC std::optional<compositionengine::LayerFE::LayerSettings> LayerFE::prepareClientCompositionInternal( compositionengine::LayerFE::ClientCompositionTargetSettings& targetSettings) const { - ATRACE_CALL(); + SFTRACE_CALL(); compositionengine::LayerFE::LayerSettings layerSettings; layerSettings.geometry.boundaries = reduce(mSnapshot->geomLayerBounds, mSnapshot->transparentRegionHint); @@ -214,7 +213,7 @@ void LayerFE::prepareEffectsClientComposition( void LayerFE::prepareBufferStateClientComposition( compositionengine::LayerFE::LayerSettings& layerSettings, compositionengine::LayerFE::ClientCompositionTargetSettings& targetSettings) const { - ATRACE_CALL(); + SFTRACE_CALL(); if (CC_UNLIKELY(!mSnapshot->externalTexture)) { // If there is no buffer for the layer or we have sidebandstream where there is no // activeBuffer, then we need to return LayerSettings. diff --git a/services/surfaceflinger/RegionSamplingThread.cpp b/services/surfaceflinger/RegionSamplingThread.cpp index 1eb865d600..06a4d00e48 100644 --- a/services/surfaceflinger/RegionSamplingThread.cpp +++ b/services/surfaceflinger/RegionSamplingThread.cpp @@ -26,6 +26,7 @@ #include "RegionSamplingThread.h" +#include <common/trace.h> #include <compositionengine/Display.h> #include <compositionengine/impl/OutputCompositionState.h> #include <cutils/properties.h> @@ -34,7 +35,6 @@ #include <gui/SyncScreenCaptureListener.h> #include <renderengine/impl/ExternalTexture.h> #include <ui/DisplayStatInfo.h> -#include <utils/Trace.h> #include <string> @@ -148,7 +148,7 @@ void RegionSamplingThread::checkForStaleLuma() { std::lock_guard lock(mThreadControlMutex); if (mSampleRequestTime.has_value()) { - ATRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::waitForSamplePhase)); + SFTRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::waitForSamplePhase)); mSampleRequestTime.reset(); mFlinger.scheduleSample(); } @@ -166,7 +166,7 @@ void RegionSamplingThread::doSample( if (mLastSampleTime + mTunables.mSamplingPeriod > now) { // content changed, but we sampled not too long ago, so we need to sample some time in the // future. - ATRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::idleTimerWaiting)); + SFTRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::idleTimerWaiting)); mSampleRequestTime = now; return; } @@ -175,13 +175,13 @@ void RegionSamplingThread::doSample( // until the next vsync deadline, defer this sampling work // to a later frame, when hopefully there will be more time. if (samplingDeadline.has_value() && now + mTunables.mSamplingDuration > *samplingDeadline) { - ATRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::waitForQuietFrame)); + SFTRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::waitForQuietFrame)); mSampleRequestTime = mSampleRequestTime.value_or(now); return; } } - ATRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::sample)); + SFTRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::sample)); mSampleRequestTime.reset(); mLastSampleTime = now; @@ -247,7 +247,7 @@ std::vector<float> RegionSamplingThread::sampleBuffer( } void RegionSamplingThread::captureSample() { - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard lock(mSamplingMutex); if (mDescriptors.empty()) { @@ -393,7 +393,7 @@ void RegionSamplingThread::captureSample() { } mCachedBuffer = buffer; - ATRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::noWorkNeeded)); + SFTRACE_INT(lumaSamplingStepTag, static_cast<int>(samplingStep::noWorkNeeded)); } // NO_THREAD_SAFETY_ANALYSIS is because std::unique_lock presently lacks thread safety annotations. diff --git a/services/surfaceflinger/Scheduler/EventThread.cpp b/services/surfaceflinger/Scheduler/EventThread.cpp index 6b654499a2..d31fceab7e 100644 --- a/services/surfaceflinger/Scheduler/EventThread.cpp +++ b/services/surfaceflinger/Scheduler/EventThread.cpp @@ -33,7 +33,7 @@ #include <android-base/stringprintf.h> #include <binder/IPCThreadState.h> - +#include <common/trace.h> #include <cutils/compiler.h> #include <cutils/sched_policy.h> @@ -41,7 +41,6 @@ #include <gui/SchedulingPolicy.h> #include <utils/Errors.h> -#include <utils/Trace.h> #include <common/FlagManager.h> #include <scheduler/VsyncConfig.h> @@ -226,14 +225,14 @@ binder::Status EventThreadConnection::setVsyncRate(int rate) { } binder::Status EventThreadConnection::requestNextVsync() { - ATRACE_CALL(); + SFTRACE_CALL(); mEventThread->requestNextVsync(sp<EventThreadConnection>::fromExisting(this)); return binder::Status::ok(); } binder::Status EventThreadConnection::getLatestVsyncEventData( ParcelableVsyncEventData* outVsyncEventData) { - ATRACE_CALL(); + SFTRACE_CALL(); outVsyncEventData->vsync = mEventThread->getLatestVsyncEventData(sp<EventThreadConnection>::fromExisting(this), systemTime()); diff --git a/services/surfaceflinger/Scheduler/LayerHistory.cpp b/services/surfaceflinger/Scheduler/LayerHistory.cpp index a819b7979f..4fd4c0ecc3 100644 --- a/services/surfaceflinger/Scheduler/LayerHistory.cpp +++ b/services/surfaceflinger/Scheduler/LayerHistory.cpp @@ -21,8 +21,8 @@ #include "LayerHistory.h" #include <android-base/stringprintf.h> +#include <common/trace.h> #include <cutils/properties.h> -#include <gui/TraceUtils.h> #include <utils/Log.h> #include <utils/Timers.h> @@ -72,7 +72,7 @@ bool useFrameRatePriority() { void trace(const LayerInfo& info, LayerHistory::LayerVoteType type, int fps) { const auto traceType = [&](LayerHistory::LayerVoteType checkedType, int value) { - ATRACE_INT(info.getTraceTag(checkedType), type == checkedType ? value : 0); + SFTRACE_INT(info.getTraceTag(checkedType), type == checkedType ? value : 0); }; traceType(LayerHistory::LayerVoteType::NoVote, 1); @@ -190,7 +190,7 @@ void LayerHistory::setLayerProperties(int32_t id, const LayerProps& properties) } auto LayerHistory::summarize(const RefreshRateSelector& selector, nsecs_t now) -> Summary { - ATRACE_CALL(); + SFTRACE_CALL(); Summary summary; std::lock_guard lock(mLock); @@ -204,7 +204,7 @@ auto LayerHistory::summarize(const RefreshRateSelector& selector, nsecs_t now) - ALOGV("%s has priority: %d %s focused", info->getName().c_str(), frameRateSelectionPriority, layerFocused ? "" : "not"); - ATRACE_FORMAT("%s", info->getName().c_str()); + SFTRACE_FORMAT("%s", info->getName().c_str()); const auto votes = info->getRefreshRateVote(selector, now); for (LayerInfo::LayerVote vote : votes) { if (vote.isNoVote()) { @@ -222,8 +222,8 @@ auto LayerHistory::summarize(const RefreshRateSelector& selector, nsecs_t now) - const std::string categoryString = vote.category == FrameRateCategory::Default ? "" : base::StringPrintf("category=%s", ftl::enum_string(vote.category).c_str()); - ATRACE_FORMAT_INSTANT("%s %s %s (%.2f)", ftl::enum_string(vote.type).c_str(), - to_string(vote.fps).c_str(), categoryString.c_str(), weight); + SFTRACE_FORMAT_INSTANT("%s %s %s (%.2f)", ftl::enum_string(vote.type).c_str(), + to_string(vote.fps).c_str(), categoryString.c_str(), weight); summary.push_back({info->getName(), info->getOwnerUid(), vote.type, vote.fps, vote.seamlessness, vote.category, vote.categorySmoothSwitchOnly, weight, layerFocused}); @@ -238,7 +238,7 @@ auto LayerHistory::summarize(const RefreshRateSelector& selector, nsecs_t now) - } void LayerHistory::partitionLayers(nsecs_t now, bool isVrrDevice) { - ATRACE_CALL(); + SFTRACE_CALL(); const nsecs_t threshold = getActiveLayerThreshold(now); // iterate over inactive map @@ -310,7 +310,7 @@ void LayerHistory::partitionLayers(nsecs_t now, bool isVrrDevice) { if (gameModeFrameRateOverride.isValid()) { info->setLayerVote({gameFrameRateOverrideVoteType, gameModeFrameRateOverride}); - ATRACE_FORMAT_INSTANT("GameModeFrameRateOverride"); + SFTRACE_FORMAT_INSTANT("GameModeFrameRateOverride"); if (CC_UNLIKELY(mTraceEnabled)) { trace(*info, gameFrameRateOverrideVoteType, gameModeFrameRateOverride.getIntValue()); @@ -326,19 +326,19 @@ void LayerHistory::partitionLayers(nsecs_t now, bool isVrrDevice) { } else if (gameDefaultFrameRateOverride.isValid()) { info->setLayerVote( {gameFrameRateOverrideVoteType, gameDefaultFrameRateOverride}); - ATRACE_FORMAT_INSTANT("GameDefaultFrameRateOverride"); + SFTRACE_FORMAT_INSTANT("GameDefaultFrameRateOverride"); if (CC_UNLIKELY(mTraceEnabled)) { trace(*info, gameFrameRateOverrideVoteType, gameDefaultFrameRateOverride.getIntValue()); } } else { if (frameRate.isValid() && !frameRate.isVoteValidForMrr(isVrrDevice)) { - ATRACE_FORMAT_INSTANT("Reset layer to ignore explicit vote on MRR %s: %s " - "%s %s", - info->getName().c_str(), - ftl::enum_string(frameRate.vote.type).c_str(), - to_string(frameRate.vote.rate).c_str(), - ftl::enum_string(frameRate.category).c_str()); + SFTRACE_FORMAT_INSTANT("Reset layer to ignore explicit vote on MRR %s: %s " + "%s %s", + info->getName().c_str(), + ftl::enum_string(frameRate.vote.type).c_str(), + to_string(frameRate.vote.rate).c_str(), + ftl::enum_string(frameRate.category).c_str()); } info->resetLayerVote(); } @@ -349,12 +349,12 @@ void LayerHistory::partitionLayers(nsecs_t now, bool isVrrDevice) { frameRate.vote.seamlessness, frameRate.category}); } else { if (!frameRate.isVoteValidForMrr(isVrrDevice)) { - ATRACE_FORMAT_INSTANT("Reset layer to ignore explicit vote on MRR %s: %s " - "%s %s", - info->getName().c_str(), - ftl::enum_string(frameRate.vote.type).c_str(), - to_string(frameRate.vote.rate).c_str(), - ftl::enum_string(frameRate.category).c_str()); + SFTRACE_FORMAT_INSTANT("Reset layer to ignore explicit vote on MRR %s: %s " + "%s %s", + info->getName().c_str(), + ftl::enum_string(frameRate.vote.type).c_str(), + to_string(frameRate.vote.rate).c_str(), + ftl::enum_string(frameRate.category).c_str()); } info->resetLayerVote(); } @@ -421,7 +421,7 @@ auto LayerHistory::findLayer(int32_t id) -> std::pair<LayerStatus, LayerPair*> { bool LayerHistory::isSmallDirtyArea(uint32_t dirtyArea, float threshold) const { const float ratio = (float)dirtyArea / mDisplayArea; const bool isSmallDirty = ratio <= threshold; - ATRACE_FORMAT_INSTANT("small dirty=%s, ratio=%.3f", isSmallDirty ? "true" : "false", ratio); + SFTRACE_FORMAT_INSTANT("small dirty=%s, ratio=%.3f", isSmallDirty ? "true" : "false", ratio); return isSmallDirty; } diff --git a/services/surfaceflinger/Scheduler/LayerInfo.cpp b/services/surfaceflinger/Scheduler/LayerInfo.cpp index 632f42ab36..a1a60e3e30 100644 --- a/services/surfaceflinger/Scheduler/LayerInfo.cpp +++ b/services/surfaceflinger/Scheduler/LayerInfo.cpp @@ -27,10 +27,10 @@ #include <utility> #include <android/native_window.h> +#include <common/trace.h> #include <cutils/compiler.h> #include <cutils/trace.h> #include <ftl/enum.h> -#include <gui/TraceUtils.h> #include <system/window.h> #undef LOG_TAG @@ -259,7 +259,7 @@ std::optional<nsecs_t> LayerInfo::calculateAverageFrameTime() const { } if (smallDirtyCount > 0) { - ATRACE_FORMAT_INSTANT("small dirty = %" PRIu32, smallDirtyCount); + SFTRACE_FORMAT_INSTANT("small dirty = %" PRIu32, smallDirtyCount); } if (numDeltas == 0) { @@ -272,7 +272,7 @@ std::optional<nsecs_t> LayerInfo::calculateAverageFrameTime() const { std::optional<Fps> LayerInfo::calculateRefreshRateIfPossible(const RefreshRateSelector& selector, nsecs_t now) { - ATRACE_CALL(); + SFTRACE_CALL(); static constexpr float MARGIN = 1.0f; // 1Hz if (!hasEnoughDataForHeuristic()) { ALOGV("Not enough data"); @@ -307,7 +307,7 @@ std::optional<Fps> LayerInfo::calculateRefreshRateIfPossible(const RefreshRateSe LayerInfo::RefreshRateVotes LayerInfo::getRefreshRateVote(const RefreshRateSelector& selector, nsecs_t now) { - ATRACE_CALL(); + SFTRACE_CALL(); LayerInfo::RefreshRateVotes votes; if (mLayerVote.type != LayerHistory::LayerVoteType::Heuristic) { @@ -315,8 +315,8 @@ LayerInfo::RefreshRateVotes LayerInfo::getRefreshRateVote(const RefreshRateSelec const auto voteType = mLayerVote.type == LayerHistory::LayerVoteType::NoVote ? LayerHistory::LayerVoteType::NoVote : LayerHistory::LayerVoteType::ExplicitCategory; - ATRACE_FORMAT_INSTANT("Vote %s (category=%s)", ftl::enum_string(voteType).c_str(), - ftl::enum_string(mLayerVote.category).c_str()); + SFTRACE_FORMAT_INSTANT("Vote %s (category=%s)", ftl::enum_string(voteType).c_str(), + ftl::enum_string(mLayerVote.category).c_str()); ALOGV("%s voted %s with category: %s", mName.c_str(), ftl::enum_string(voteType).c_str(), ftl::enum_string(mLayerVote.category).c_str()); @@ -326,7 +326,7 @@ LayerInfo::RefreshRateVotes LayerInfo::getRefreshRateVote(const RefreshRateSelec if (mLayerVote.fps.isValid() || mLayerVote.type != LayerHistory::LayerVoteType::ExplicitDefault) { - ATRACE_FORMAT_INSTANT("Vote %s", ftl::enum_string(mLayerVote.type).c_str()); + SFTRACE_FORMAT_INSTANT("Vote %s", ftl::enum_string(mLayerVote.type).c_str()); ALOGV("%s voted %d", mName.c_str(), static_cast<int>(mLayerVote.type)); votes.push_back({mLayerVote.type, mLayerVote.fps, mLayerVote.seamlessness, FrameRateCategory::Default, mLayerVote.categorySmoothSwitchOnly}); @@ -336,7 +336,7 @@ LayerInfo::RefreshRateVotes LayerInfo::getRefreshRateVote(const RefreshRateSelec } if (isAnimating(now)) { - ATRACE_FORMAT_INSTANT("animating"); + SFTRACE_FORMAT_INSTANT("animating"); ALOGV("%s is animating", mName.c_str()); mLastRefreshRate.animating = true; votes.push_back({LayerHistory::LayerVoteType::Max, Fps()}); @@ -345,7 +345,7 @@ LayerInfo::RefreshRateVotes LayerInfo::getRefreshRateVote(const RefreshRateSelec // Vote for max refresh rate whenever we're front-buffered. if (FlagManager::getInstance().vrr_config() && isFrontBuffered()) { - ATRACE_FORMAT_INSTANT("front buffered"); + SFTRACE_FORMAT_INSTANT("front buffered"); ALOGV("%s is front-buffered", mName.c_str()); votes.push_back({LayerHistory::LayerVoteType::Max, Fps()}); return votes; @@ -354,7 +354,7 @@ LayerInfo::RefreshRateVotes LayerInfo::getRefreshRateVote(const RefreshRateSelec const LayerInfo::Frequent frequent = isFrequent(now); mIsFrequencyConclusive = frequent.isConclusive; if (!frequent.isFrequent) { - ATRACE_FORMAT_INSTANT("infrequent"); + SFTRACE_FORMAT_INSTANT("infrequent"); ALOGV("%s is infrequent", mName.c_str()); mLastRefreshRate.infrequent = true; mLastSmallDirtyCount = 0; @@ -365,14 +365,14 @@ LayerInfo::RefreshRateVotes LayerInfo::getRefreshRateVote(const RefreshRateSelec } if (frequent.clearHistory) { - ATRACE_FORMAT_INSTANT("frequent.clearHistory"); + SFTRACE_FORMAT_INSTANT("frequent.clearHistory"); ALOGV("%s frequent.clearHistory", mName.c_str()); clearHistory(now); } // Return no vote if the recent frames are small dirty. if (frequent.isSmallDirty && !mLastRefreshRate.reported.isValid()) { - ATRACE_FORMAT_INSTANT("NoVote (small dirty)"); + SFTRACE_FORMAT_INSTANT("NoVote (small dirty)"); ALOGV("%s is small dirty", mName.c_str()); votes.push_back({LayerHistory::LayerVoteType::NoVote, Fps()}); return votes; @@ -380,13 +380,13 @@ LayerInfo::RefreshRateVotes LayerInfo::getRefreshRateVote(const RefreshRateSelec auto refreshRate = calculateRefreshRateIfPossible(selector, now); if (refreshRate.has_value()) { - ATRACE_FORMAT_INSTANT("calculated (%s)", to_string(*refreshRate).c_str()); + SFTRACE_FORMAT_INSTANT("calculated (%s)", to_string(*refreshRate).c_str()); ALOGV("%s calculated refresh rate: %s", mName.c_str(), to_string(*refreshRate).c_str()); votes.push_back({LayerHistory::LayerVoteType::Heuristic, refreshRate.value()}); return votes; } - ATRACE_FORMAT_INSTANT("Max (can't resolve refresh rate)"); + SFTRACE_FORMAT_INSTANT("Max (can't resolve refresh rate)"); ALOGV("%s Max (can't resolve refresh rate)", mName.c_str()); votes.push_back({LayerHistory::LayerVoteType::Max, Fps()}); return votes; @@ -452,7 +452,7 @@ Fps LayerInfo::RefreshRateHistory::add(Fps refreshRate, nsecs_t now, mHeuristicTraceTagData = makeHeuristicTraceTagData(); } - ATRACE_INT(mHeuristicTraceTagData->average.c_str(), refreshRate.getIntValue()); + SFTRACE_INT(mHeuristicTraceTagData->average.c_str(), refreshRate.getIntValue()); } return selectRefreshRate(selector); @@ -486,9 +486,9 @@ Fps LayerInfo::RefreshRateHistory::selectRefreshRate(const RefreshRateSelector& mHeuristicTraceTagData = makeHeuristicTraceTagData(); } - ATRACE_INT(mHeuristicTraceTagData->max.c_str(), max->refreshRate.getIntValue()); - ATRACE_INT(mHeuristicTraceTagData->min.c_str(), min->refreshRate.getIntValue()); - ATRACE_INT(mHeuristicTraceTagData->consistent.c_str(), consistent); + SFTRACE_INT(mHeuristicTraceTagData->max.c_str(), max->refreshRate.getIntValue()); + SFTRACE_INT(mHeuristicTraceTagData->min.c_str(), min->refreshRate.getIntValue()); + SFTRACE_INT(mHeuristicTraceTagData->consistent.c_str(), consistent); } return consistent ? maxClosestRate : Fps(); diff --git a/services/surfaceflinger/Scheduler/MessageQueue.cpp b/services/surfaceflinger/Scheduler/MessageQueue.cpp index ff88d71259..6a67ac5d42 100644 --- a/services/surfaceflinger/Scheduler/MessageQueue.cpp +++ b/services/surfaceflinger/Scheduler/MessageQueue.cpp @@ -57,7 +57,7 @@ MessageQueue::MessageQueue(ICompositor& compositor, sp<Handler> handler) mHandler(std::move(handler)) {} void MessageQueue::vsyncCallback(nsecs_t vsyncTime, nsecs_t targetWakeupTime, nsecs_t readyTime) { - ATRACE_CALL(); + SFTRACE_CALL(); // Trace VSYNC-sf mVsync.value = (mVsync.value + 1) % 2; @@ -136,7 +136,7 @@ void MessageQueue::destroyVsync() { } void MessageQueue::setDuration(std::chrono::nanoseconds workDuration) { - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard lock(mVsync.mutex); mVsync.workDuration = workDuration; mVsync.scheduledFrameTimeOpt = @@ -189,7 +189,7 @@ void MessageQueue::scheduleConfigure() { } void MessageQueue::scheduleFrame() { - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard lock(mVsync.mutex); mVsync.scheduledFrameTimeOpt = diff --git a/services/surfaceflinger/Scheduler/RefreshRateSelector.cpp b/services/surfaceflinger/Scheduler/RefreshRateSelector.cpp index be5ffbcb71..0b17c8495c 100644 --- a/services/surfaceflinger/Scheduler/RefreshRateSelector.cpp +++ b/services/surfaceflinger/Scheduler/RefreshRateSelector.cpp @@ -28,13 +28,12 @@ #include <android-base/properties.h> #include <android-base/stringprintf.h> +#include <common/trace.h> #include <ftl/enum.h> #include <ftl/fake_guard.h> #include <ftl/match.h> #include <ftl/unit.h> -#include <gui/TraceUtils.h> #include <scheduler/FrameRateMode.h> -#include <utils/Trace.h> #include "RefreshRateSelector.h" @@ -494,7 +493,7 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi GlobalSignals signals, Fps pacesetterFps) const -> RankedFrameRates { using namespace fps_approx_ops; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("%s: %zu layers", __func__, layers.size()); const auto& activeMode = *getActiveModeLocked().modePtr; @@ -508,8 +507,8 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi }); if (!ranking.empty()) { - ATRACE_FORMAT_INSTANT("%s (Follower display)", - to_string(ranking.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (Follower display)", + to_string(ranking.front().frameRateMode.fps).c_str()); return {ranking, kNoSignals, pacesetterFps}; } @@ -521,8 +520,8 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi if (signals.powerOnImminent) { ALOGV("Power On Imminent"); const auto ranking = rankFrameRates(activeMode.getGroup(), RefreshRateOrder::Descending); - ATRACE_FORMAT_INSTANT("%s (Power On Imminent)", - to_string(ranking.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (Power On Imminent)", + to_string(ranking.front().frameRateMode.fps).c_str()); return {ranking, GlobalSignals{.powerOnImminent = true}}; } @@ -608,8 +607,8 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi if (signals.touch && !hasExplicitVoteLayers) { ALOGV("Touch Boost"); const auto ranking = rankFrameRates(anchorGroup, RefreshRateOrder::Descending); - ATRACE_FORMAT_INSTANT("%s (Touch Boost)", - to_string(ranking.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (Touch Boost)", + to_string(ranking.front().frameRateMode.fps).c_str()); return {ranking, GlobalSignals{.touch = true}}; } @@ -620,15 +619,15 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi !(policy->primaryRangeIsSingleRate() && hasExplicitVoteLayers)) { ALOGV("Idle"); const auto ranking = rankFrameRates(activeMode.getGroup(), RefreshRateOrder::Ascending); - ATRACE_FORMAT_INSTANT("%s (Idle)", to_string(ranking.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (Idle)", to_string(ranking.front().frameRateMode.fps).c_str()); return {ranking, GlobalSignals{.idle = true}}; } if (layers.empty() || noVoteLayers == layers.size()) { ALOGV("No layers with votes"); const auto ranking = rankFrameRates(anchorGroup, RefreshRateOrder::Descending); - ATRACE_FORMAT_INSTANT("%s (No layers with votes)", - to_string(ranking.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (No layers with votes)", + to_string(ranking.front().frameRateMode.fps).c_str()); return {ranking, kNoSignals}; } @@ -637,8 +636,8 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi ALOGV("All layers NoPreference"); const auto ascendingWithPreferred = rankFrameRates(anchorGroup, RefreshRateOrder::Ascending, activeMode.getId()); - ATRACE_FORMAT_INSTANT("%s (All layers NoPreference)", - to_string(ascendingWithPreferred.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (All layers NoPreference)", + to_string(ascendingWithPreferred.front().frameRateMode.fps).c_str()); return {ascendingWithPreferred, kNoSignals}; } @@ -653,8 +652,8 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi return !smoothSwitchOnly || mode.modePtr->getId() == activeModeId; }); - ATRACE_FORMAT_INSTANT("%s (All layers Min)", - to_string(ranking.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (All layers Min)", + to_string(ranking.front().frameRateMode.fps).c_str()); return {ranking, kNoSignals}; } @@ -847,13 +846,13 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi if (noLayerScore) { ALOGV("Layers not scored"); const auto descending = rankFrameRates(anchorGroup, RefreshRateOrder::Descending); - ATRACE_FORMAT_INSTANT("%s (Layers not scored)", - to_string(descending.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (Layers not scored)", + to_string(descending.front().frameRateMode.fps).c_str()); return {descending, kNoSignals}; } else { ALOGV("primaryRangeIsSingleRate"); - ATRACE_FORMAT_INSTANT("%s (primaryRangeIsSingleRate)", - to_string(ranking.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (primaryRangeIsSingleRate)", + to_string(ranking.front().frameRateMode.fps).c_str()); return {ranking, kNoSignals}; } } @@ -889,8 +888,8 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi if (scores.front().frameRateMode.fps < touchRefreshRates.front().frameRateMode.fps) { ALOGV("Touch Boost"); - ATRACE_FORMAT_INSTANT("%s (Touch Boost [late])", - to_string(touchRefreshRates.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (Touch Boost [late])", + to_string(touchRefreshRates.front().frameRateMode.fps).c_str()); return {touchRefreshRates, GlobalSignals{.touch = true}}; } } @@ -901,13 +900,13 @@ auto RefreshRateSelector::getRankedFrameRatesLocked(const std::vector<LayerRequi ALOGV("preferredDisplayMode"); const auto ascendingWithPreferred = rankFrameRates(anchorGroup, RefreshRateOrder::Ascending, activeMode.getId()); - ATRACE_FORMAT_INSTANT("%s (preferredDisplayMode)", - to_string(ascendingWithPreferred.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (preferredDisplayMode)", + to_string(ascendingWithPreferred.front().frameRateMode.fps).c_str()); return {ascendingWithPreferred, kNoSignals}; } ALOGV("%s (scored)", to_string(ranking.front().frameRateMode.fps).c_str()); - ATRACE_FORMAT_INSTANT("%s (scored)", to_string(ranking.front().frameRateMode.fps).c_str()); + SFTRACE_FORMAT_INSTANT("%s (scored)", to_string(ranking.front().frameRateMode.fps).c_str()); return {ranking, kNoSignals}; } @@ -949,7 +948,7 @@ auto RefreshRateSelector::getFrameRateOverrides(const std::vector<LayerRequireme Fps displayRefreshRate, GlobalSignals globalSignals) const -> UidToFrameRateOverride { - ATRACE_CALL(); + SFTRACE_CALL(); if (mConfig.enableFrameRateOverride == Config::FrameRateOverride::Disabled) { return {}; } @@ -1064,12 +1063,12 @@ auto RefreshRateSelector::getFrameRateOverrides(const std::vector<LayerRequireme return lhs < rhs && !ScoredFrameRate::scoresEqual(lhs, rhs); }); ALOGV("%s: overriding to %s for uid=%d", __func__, to_string(overrideFps).c_str(), uid); - ATRACE_FORMAT_INSTANT("%s: overriding to %s for uid=%d", __func__, - to_string(overrideFps).c_str(), uid); + SFTRACE_FORMAT_INSTANT("%s: overriding to %s for uid=%d", __func__, + to_string(overrideFps).c_str(), uid); if (ATRACE_ENABLED() && FlagManager::getInstance().trace_frame_rate_override()) { std::stringstream ss; ss << "FrameRateOverride " << uid; - ATRACE_INT(ss.str().c_str(), overrideFps.getIntValue()); + SFTRACE_INT(ss.str().c_str(), overrideFps.getIntValue()); } frameRateOverrides.emplace(uid, overrideFps); } diff --git a/services/surfaceflinger/Scheduler/Scheduler.cpp b/services/surfaceflinger/Scheduler/Scheduler.cpp index e66926181a..c43e942723 100644 --- a/services/surfaceflinger/Scheduler/Scheduler.cpp +++ b/services/surfaceflinger/Scheduler/Scheduler.cpp @@ -24,12 +24,12 @@ #include <android-base/stringprintf.h> #include <android/hardware/configstore/1.0/ISurfaceFlingerConfigs.h> #include <android/hardware/configstore/1.1/ISurfaceFlingerConfigs.h> +#include <common/trace.h> #include <configstore/Utils.h> #include <ftl/concat.h> #include <ftl/enum.h> #include <ftl/fake_guard.h> #include <ftl/small_map.h> -#include <gui/TraceUtils.h> #include <gui/WindowInfo.h> #include <system/window.h> #include <ui/DisplayMap.h> @@ -250,8 +250,8 @@ void Scheduler::onFrameSignal(ICompositor& compositor, VsyncId vsyncId, const auto period = pacesetterPtr->targeterPtr->target().expectedFrameDuration(); const auto skipDuration = Duration::fromNs( static_cast<nsecs_t>(period.ns() * mPacesetterFrameDurationFractionToSkip)); - ATRACE_FORMAT("Injecting jank for %f%% of the frame (%" PRId64 " ns)", - mPacesetterFrameDurationFractionToSkip * 100, skipDuration.ns()); + SFTRACE_FORMAT("Injecting jank for %f%% of the frame (%" PRId64 " ns)", + mPacesetterFrameDurationFractionToSkip * 100, skipDuration.ns()); std::this_thread::sleep_for(skipDuration); mPacesetterFrameDurationFractionToSkip = 0.f; } @@ -282,7 +282,7 @@ bool Scheduler::isVsyncValid(TimePoint expectedVsyncTime, uid_t uid) const { return true; } - ATRACE_FORMAT("%s uid: %d frameRate: %s", __func__, uid, to_string(*frameRate).c_str()); + SFTRACE_FORMAT("%s uid: %d frameRate: %s", __func__, uid, to_string(*frameRate).c_str()); return getVsyncSchedule()->getTracker().isVSyncInPhase(expectedVsyncTime.ns(), *frameRate); } @@ -510,7 +510,7 @@ void Scheduler::disableHardwareVsync(PhysicalDisplayId id, bool disallow) { } void Scheduler::resyncAllToHardwareVsync(bool allowToEnable) { - ATRACE_CALL(); + SFTRACE_CALL(); std::scoped_lock lock(mDisplayLock); ftl::FakeGuard guard(kMainThreadContext); @@ -544,12 +544,12 @@ void Scheduler::resyncToHardwareVsyncLocked(PhysicalDisplayId id, bool allowToEn void Scheduler::onHardwareVsyncRequest(PhysicalDisplayId id, bool enabled) { static const auto& whence = __func__; - ATRACE_NAME(ftl::Concat(whence, ' ', id.value, ' ', enabled).c_str()); + SFTRACE_NAME(ftl::Concat(whence, ' ', id.value, ' ', enabled).c_str()); // On main thread to serialize reads/writes of pending hardware VSYNC state. static_cast<void>( schedule([=, this]() FTL_FAKE_GUARD(mDisplayLock) FTL_FAKE_GUARD(kMainThreadContext) { - ATRACE_NAME(ftl::Concat(whence, ' ', id.value, ' ', enabled).c_str()); + SFTRACE_NAME(ftl::Concat(whence, ' ', id.value, ' ', enabled).c_str()); if (const auto displayOpt = mDisplays.get(id)) { auto& display = displayOpt->get(); @@ -631,7 +631,7 @@ bool Scheduler::addResyncSample(PhysicalDisplayId id, nsecs_t timestamp, } void Scheduler::addPresentFence(PhysicalDisplayId id, std::shared_ptr<FenceTime> fence) { - ATRACE_NAME(ftl::Concat(__func__, ' ', id.value).c_str()); + SFTRACE_NAME(ftl::Concat(__func__, ' ', id.value).c_str()); const auto scheduleOpt = (ftl::FakeGuard(mDisplayLock), mDisplays.get(id)).and_then([](const Display& display) { return display.powerMode == hal::PowerMode::OFF @@ -694,7 +694,7 @@ void Scheduler::chooseRefreshRateForContent( const auto selectorPtr = pacesetterSelectorPtr(); if (!selectorPtr->canSwitch()) return; - ATRACE_CALL(); + SFTRACE_CALL(); LayerHistory::Summary summary = mLayerHistory.summarize(*selectorPtr, systemTime()); applyPolicy(&Policy::contentRequirements, std::move(summary)); @@ -779,7 +779,7 @@ auto Scheduler::getVsyncScheduleLocked(std::optional<PhysicalDisplayId> idOpt) c } void Scheduler::kernelIdleTimerCallback(TimerState state) { - ATRACE_INT("ExpiredKernelIdleTimer", static_cast<int>(state)); + SFTRACE_INT("ExpiredKernelIdleTimer", static_cast<int>(state)); // TODO(145561154): cleanup the kernel idle timer implementation and the refresh rate // magic number @@ -810,7 +810,7 @@ void Scheduler::kernelIdleTimerCallback(TimerState state) { void Scheduler::idleTimerCallback(TimerState state) { applyPolicy(&Policy::idleTimer, state); - ATRACE_INT("ExpiredIdleTimer", static_cast<int>(state)); + SFTRACE_INT("ExpiredIdleTimer", static_cast<int>(state)); } void Scheduler::touchTimerCallback(TimerState state) { @@ -822,12 +822,12 @@ void Scheduler::touchTimerCallback(TimerState state) { if (applyPolicy(&Policy::touch, touch).touch) { mLayerHistory.clear(); } - ATRACE_INT("TouchState", static_cast<int>(touch)); + SFTRACE_INT("TouchState", static_cast<int>(touch)); } void Scheduler::displayPowerTimerCallback(TimerState state) { applyPolicy(&Policy::displayPowerTimer, state); - ATRACE_INT("ExpiredDisplayPowerTimer", static_cast<int>(state)); + SFTRACE_INT("ExpiredDisplayPowerTimer", static_cast<int>(state)); } void Scheduler::dump(utils::Dumper& dumper) const { @@ -990,7 +990,7 @@ void Scheduler::updateAttachedChoreographersFrameRate( auto& layerChoreographers = choreographers->second; layerChoreographers.frameRate = fps; - ATRACE_FORMAT_INSTANT("%s: %s for %s", __func__, to_string(fps).c_str(), layer.name.c_str()); + SFTRACE_FORMAT_INSTANT("%s: %s for %s", __func__, to_string(fps).c_str(), layer.name.c_str()); ALOGV("%s: %s for %s", __func__, to_string(fps).c_str(), layer.name.c_str()); auto it = layerChoreographers.connections.begin(); @@ -1072,13 +1072,13 @@ int Scheduler::updateAttachedChoreographersInternal( void Scheduler::updateAttachedChoreographers( const surfaceflinger::frontend::LayerHierarchy& layerHierarchy, Fps displayRefreshRate) { - ATRACE_CALL(); + SFTRACE_CALL(); updateAttachedChoreographersInternal(layerHierarchy, displayRefreshRate, 0); } template <typename S, typename T> auto Scheduler::applyPolicy(S Policy::*statePtr, T&& newState) -> GlobalSignals { - ATRACE_CALL(); + SFTRACE_CALL(); std::vector<display::DisplayModeRequest> modeRequests; GlobalSignals consideredSignals; @@ -1149,7 +1149,7 @@ auto Scheduler::applyPolicy(S Policy::*statePtr, T&& newState) -> GlobalSignals } auto Scheduler::chooseDisplayModes() const -> DisplayModeChoiceMap { - ATRACE_CALL(); + SFTRACE_CALL(); DisplayModeChoiceMap modeChoices; const auto globalSignals = makeGlobalSignals(); diff --git a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp index 6d6b70d198..8dae3ca0a3 100644 --- a/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp +++ b/services/surfaceflinger/Scheduler/VSyncDispatchTimerQueue.cpp @@ -19,8 +19,8 @@ #include <vector> #include <android-base/stringprintf.h> +#include <common/trace.h> #include <ftl/concat.h> -#include <gui/TraceUtils.h> #include <log/log_main.h> #include <scheduler/TimeKeeper.h> @@ -52,7 +52,7 @@ void traceEntry(const VSyncDispatchTimerQueueEntry& entry, nsecs_t now) { ftl::Concat trace(ftl::truncated<5>(entry.name()), " alarm in ", ns2us(*entry.wakeupTime() - now), "us; VSYNC in ", ns2us(*entry.targetVsync() - now), "us"); - ATRACE_FORMAT_INSTANT(trace.c_str()); + SFTRACE_FORMAT_INSTANT(trace.c_str()); } } // namespace @@ -98,7 +98,7 @@ std::optional<nsecs_t> VSyncDispatchTimerQueueEntry::targetVsync() const { ScheduleResult VSyncDispatchTimerQueueEntry::schedule(VSyncDispatch::ScheduleTiming timing, VSyncTracker& tracker, nsecs_t now) { - ATRACE_NAME("VSyncDispatchTimerQueueEntry::schedule"); + SFTRACE_NAME("VSyncDispatchTimerQueueEntry::schedule"); auto nextVsyncTime = tracker.nextAnticipatedVSyncTimeFrom(std::max(timing.lastVsync, now + timing.workDuration + @@ -110,8 +110,8 @@ ScheduleResult VSyncDispatchTimerQueueEntry::schedule(VSyncDispatch::ScheduleTim mArmedInfo && (nextVsyncTime > (mArmedInfo->mActualVsyncTime + mMinVsyncDistance)); bool const wouldSkipAWakeup = mArmedInfo && ((nextWakeupTime > (mArmedInfo->mActualWakeupTime + mMinVsyncDistance))); - ATRACE_FORMAT_INSTANT("%s: wouldSkipAVsyncTarget=%d wouldSkipAWakeup=%d", mName.c_str(), - wouldSkipAVsyncTarget, wouldSkipAWakeup); + SFTRACE_FORMAT_INSTANT("%s: wouldSkipAVsyncTarget=%d wouldSkipAWakeup=%d", mName.c_str(), + wouldSkipAVsyncTarget, wouldSkipAWakeup); if (FlagManager::getInstance().dont_skip_on_early_ro()) { if (wouldSkipAVsyncTarget || wouldSkipAWakeup) { nextVsyncTime = mArmedInfo->mActualVsyncTime; @@ -154,13 +154,13 @@ nsecs_t VSyncDispatchTimerQueueEntry::adjustVsyncIfNeeded(VSyncTracker& tracker, bool const nextVsyncTooClose = mLastDispatchTime && (nextVsyncTime - *mLastDispatchTime + mMinVsyncDistance) <= currentPeriod; if (alreadyDispatchedForVsync) { - ATRACE_FORMAT_INSTANT("alreadyDispatchedForVsync"); + SFTRACE_FORMAT_INSTANT("alreadyDispatchedForVsync"); return tracker.nextAnticipatedVSyncTimeFrom(*mLastDispatchTime + mMinVsyncDistance, *mLastDispatchTime); } if (nextVsyncTooClose) { - ATRACE_FORMAT_INSTANT("nextVsyncTooClose"); + SFTRACE_FORMAT_INSTANT("nextVsyncTooClose"); return tracker.nextAnticipatedVSyncTimeFrom(*mLastDispatchTime + currentPeriod, *mLastDispatchTime + currentPeriod); } @@ -172,7 +172,7 @@ auto VSyncDispatchTimerQueueEntry::getArmedInfo(VSyncTracker& tracker, nsecs_t n VSyncDispatch::ScheduleTiming timing, std::optional<ArmingInfo> armedInfo) const -> ArmingInfo { - ATRACE_NAME("VSyncDispatchTimerQueueEntry::getArmedInfo"); + SFTRACE_NAME("VSyncDispatchTimerQueueEntry::getArmedInfo"); const auto earliestReadyBy = now + timing.workDuration + timing.readyDuration; const auto earliestVsync = std::max(earliestReadyBy, timing.lastVsync); @@ -188,8 +188,8 @@ auto VSyncDispatchTimerQueueEntry::getArmedInfo(VSyncTracker& tracker, nsecs_t n armedInfo && (nextVsyncTime > (armedInfo->mActualVsyncTime + mMinVsyncDistance)); bool const wouldSkipAWakeup = armedInfo && (nextWakeupTime > (armedInfo->mActualWakeupTime + mMinVsyncDistance)); - ATRACE_FORMAT_INSTANT("%s: wouldSkipAVsyncTarget=%d wouldSkipAWakeup=%d", mName.c_str(), - wouldSkipAVsyncTarget, wouldSkipAWakeup); + SFTRACE_FORMAT_INSTANT("%s: wouldSkipAVsyncTarget=%d wouldSkipAWakeup=%d", mName.c_str(), + wouldSkipAVsyncTarget, wouldSkipAWakeup); if (wouldSkipAVsyncTarget || wouldSkipAWakeup) { return *armedInfo; } @@ -199,7 +199,7 @@ auto VSyncDispatchTimerQueueEntry::getArmedInfo(VSyncTracker& tracker, nsecs_t n } void VSyncDispatchTimerQueueEntry::update(VSyncTracker& tracker, nsecs_t now) { - ATRACE_NAME("VSyncDispatchTimerQueueEntry::update"); + SFTRACE_NAME("VSyncDispatchTimerQueueEntry::update"); if (!mArmedInfo && !mWorkloadUpdateInfo) { return; } @@ -208,9 +208,9 @@ void VSyncDispatchTimerQueueEntry::update(VSyncTracker& tracker, nsecs_t now) { const auto workDelta = mWorkloadUpdateInfo->workDuration - mScheduleTiming.workDuration; const auto readyDelta = mWorkloadUpdateInfo->readyDuration - mScheduleTiming.readyDuration; const auto lastVsyncDelta = mWorkloadUpdateInfo->lastVsync - mScheduleTiming.lastVsync; - ATRACE_FORMAT_INSTANT("Workload updated workDelta=%" PRId64 " readyDelta=%" PRId64 - " lastVsyncDelta=%" PRId64, - workDelta, readyDelta, lastVsyncDelta); + SFTRACE_FORMAT_INSTANT("Workload updated workDelta=%" PRId64 " readyDelta=%" PRId64 + " lastVsyncDelta=%" PRId64, + workDelta, readyDelta, lastVsyncDelta); mScheduleTiming = *mWorkloadUpdateInfo; mWorkloadUpdateInfo.reset(); } @@ -310,7 +310,7 @@ void VSyncDispatchTimerQueue::rearmTimer(nsecs_t now) { void VSyncDispatchTimerQueue::rearmTimerSkippingUpdateFor( nsecs_t now, CallbackMap::const_iterator skipUpdateIt) { - ATRACE_CALL(); + SFTRACE_CALL(); std::optional<nsecs_t> min; std::optional<nsecs_t> targetVsync; std::optional<std::string_view> nextWakeupName; @@ -337,13 +337,13 @@ void VSyncDispatchTimerQueue::rearmTimerSkippingUpdateFor( if (min && min < mIntendedWakeupTime) { setTimer(*min, now); } else { - ATRACE_NAME("cancel timer"); + SFTRACE_NAME("cancel timer"); cancelTimer(); } } void VSyncDispatchTimerQueue::timerCallback() { - ATRACE_CALL(); + SFTRACE_CALL(); struct Invocation { std::shared_ptr<VSyncDispatchTimerQueueEntry> callback; nsecs_t vsyncTimestamp; @@ -383,7 +383,7 @@ void VSyncDispatchTimerQueue::timerCallback() { for (auto const& invocation : invocations) { ftl::Concat trace(ftl::truncated<5>(invocation.callback->name())); - ATRACE_FORMAT("%s: %s", __func__, trace.c_str()); + SFTRACE_FORMAT("%s: %s", __func__, trace.c_str()); invocation.callback->callback(invocation.vsyncTimestamp, invocation.wakeupTimestamp, invocation.deadlineTimestamp); } diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp index 0644acaee2..16799bd32d 100644 --- a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp +++ b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp @@ -30,10 +30,10 @@ #include <android-base/logging.h> #include <android-base/stringprintf.h> #include <common/FlagManager.h> +#include <common/trace.h> #include <cutils/compiler.h> #include <cutils/properties.h> #include <ftl/concat.h> -#include <gui/TraceUtils.h> #include <utils/Log.h> #include "RefreshRateSelector.h" @@ -77,7 +77,7 @@ inline void VSyncPredictor::traceInt64If(const char* name, int64_t value) const } inline void VSyncPredictor::traceInt64(const char* name, int64_t value) const { - ATRACE_INT64(ftl::Concat(ftl::truncated<14>(name), " ", mId.value).c_str(), value); + SFTRACE_INT64(ftl::Concat(ftl::truncated<14>(name), " ", mId.value).c_str(), value); } inline size_t VSyncPredictor::next(size_t i) const { @@ -98,7 +98,7 @@ bool VSyncPredictor::validate(nsecs_t timestamp) const { (timestamp - aValidTimestamp) % idealPeriod() * kMaxPercent / idealPeriod(); if (percent >= kOutlierTolerancePercent && percent <= (kMaxPercent - kOutlierTolerancePercent)) { - ATRACE_FORMAT_INSTANT("timestamp is not aligned with model"); + SFTRACE_FORMAT_INSTANT("timestamp is not aligned with model"); return false; } @@ -109,7 +109,7 @@ bool VSyncPredictor::validate(nsecs_t timestamp) const { const auto distancePercent = std::abs(*iter - timestamp) * kMaxPercent / idealPeriod(); if (distancePercent < kOutlierTolerancePercent) { // duplicate timestamp - ATRACE_FORMAT_INSTANT("duplicate timestamp"); + SFTRACE_FORMAT_INSTANT("duplicate timestamp"); return false; } return true; @@ -135,7 +135,7 @@ Period VSyncPredictor::minFramePeriodLocked() const { } bool VSyncPredictor::addVsyncTimestamp(nsecs_t timestamp) { - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard lock(mMutex); @@ -155,8 +155,8 @@ bool VSyncPredictor::addVsyncTimestamp(nsecs_t timestamp) { } else { mKnownTimestamp = timestamp; } - ATRACE_FORMAT_INSTANT("timestamp rejected. mKnownTimestamp was %.2fms ago", - (mClock->now() - *mKnownTimestamp) / 1e6f); + SFTRACE_FORMAT_INSTANT("timestamp rejected. mKnownTimestamp was %.2fms ago", + (mClock->now() - *mKnownTimestamp) / 1e6f); return false; } @@ -297,7 +297,7 @@ nsecs_t VSyncPredictor::snapToVsync(nsecs_t timePoint) const { nsecs_t VSyncPredictor::nextAnticipatedVSyncTimeFrom(nsecs_t timePoint, std::optional<nsecs_t> lastVsyncOpt) { - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard lock(mMutex); const auto now = TimePoint::fromNs(mClock->now()); @@ -330,8 +330,8 @@ nsecs_t VSyncPredictor::nextAnticipatedVSyncTimeFrom(nsecs_t timePoint, if (*vsyncOpt > mLastCommittedVsync) { mLastCommittedVsync = *vsyncOpt; - ATRACE_FORMAT_INSTANT("mLastCommittedVsync in %.2fms", - float(mLastCommittedVsync.ns() - mClock->now()) / 1e6f); + SFTRACE_FORMAT_INSTANT("mLastCommittedVsync in %.2fms", + float(mLastCommittedVsync.ns() - mClock->now()) / 1e6f); } return vsyncOpt->ns(); @@ -374,7 +374,7 @@ bool VSyncPredictor::isVSyncInPhase(nsecs_t timePoint, Fps frameRate) { } void VSyncPredictor::setRenderRate(Fps renderRate, bool applyImmediately) { - ATRACE_FORMAT("%s %s", __func__, to_string(renderRate).c_str()); + SFTRACE_FORMAT("%s %s", __func__, to_string(renderRate).c_str()); ALOGV("%s %s: RenderRate %s ", __func__, to_string(mId).c_str(), to_string(renderRate).c_str()); std::lock_guard lock(mMutex); const auto prevRenderRate = mRenderRateOpt; @@ -382,7 +382,7 @@ void VSyncPredictor::setRenderRate(Fps renderRate, bool applyImmediately) { const auto renderPeriodDelta = prevRenderRate ? prevRenderRate->getPeriodNsecs() - renderRate.getPeriodNsecs() : 0; if (applyImmediately) { - ATRACE_FORMAT_INSTANT("applyImmediately"); + SFTRACE_FORMAT_INSTANT("applyImmediately"); while (mTimelines.size() > 1) { mTimelines.pop_front(); } @@ -394,7 +394,7 @@ void VSyncPredictor::setRenderRate(Fps renderRate, bool applyImmediately) { const bool newRenderRateIsHigher = renderPeriodDelta > renderRate.getPeriodNsecs() && mLastCommittedVsync.ns() - mClock->now() > 2 * renderRate.getPeriodNsecs(); if (newRenderRateIsHigher) { - ATRACE_FORMAT_INSTANT("newRenderRateIsHigher"); + SFTRACE_FORMAT_INSTANT("newRenderRateIsHigher"); mTimelines.clear(); mLastCommittedVsync = TimePoint::fromNs(0); @@ -415,7 +415,7 @@ void VSyncPredictor::setRenderRate(Fps renderRate, bool applyImmediately) { void VSyncPredictor::setDisplayModePtr(ftl::NonNull<DisplayModePtr> modePtr) { LOG_ALWAYS_FATAL_IF(mId != modePtr->getPhysicalDisplayId(), "mode does not belong to the display"); - ATRACE_FORMAT("%s %s", __func__, to_string(*modePtr).c_str()); + SFTRACE_FORMAT("%s %s", __func__, to_string(*modePtr).c_str()); const auto timeout = modePtr->getVrrConfig() ? modePtr->getVrrConfig()->notifyExpectedPresentConfig : std::nullopt; @@ -443,7 +443,7 @@ void VSyncPredictor::setDisplayModePtr(ftl::NonNull<DisplayModePtr> modePtr) { Duration VSyncPredictor::ensureMinFrameDurationIsKept(TimePoint expectedPresentTime, TimePoint lastConfirmedPresentTime) { - ATRACE_CALL(); + SFTRACE_CALL(); if (mNumVsyncsForFrame <= 1) { return 0ns; @@ -456,14 +456,15 @@ Duration VSyncPredictor::ensureMinFrameDurationIsKept(TimePoint expectedPresentT auto prev = lastConfirmedPresentTime.ns(); for (auto& current : mPastExpectedPresentTimes) { if (CC_UNLIKELY(mTraceOn)) { - ATRACE_FORMAT_INSTANT("current %.2f past last signaled fence", - static_cast<float>(current.ns() - lastConfirmedPresentTime.ns()) / - 1e6f); + SFTRACE_FORMAT_INSTANT("current %.2f past last signaled fence", + static_cast<float>(current.ns() - + lastConfirmedPresentTime.ns()) / + 1e6f); } const auto minPeriodViolation = current.ns() - prev + threshold < minFramePeriod; if (minPeriodViolation) { - ATRACE_NAME("minPeriodViolation"); + SFTRACE_NAME("minPeriodViolation"); current = TimePoint::fromNs(prev + minFramePeriod); prev = current.ns(); } else { @@ -487,16 +488,16 @@ Duration VSyncPredictor::ensureMinFrameDurationIsKept(TimePoint expectedPresentT void VSyncPredictor::onFrameBegin(TimePoint expectedPresentTime, TimePoint lastConfirmedPresentTime) { - ATRACE_NAME("VSyncPredictor::onFrameBegin"); + SFTRACE_NAME("VSyncPredictor::onFrameBegin"); std::lock_guard lock(mMutex); if (!mDisplayModePtr->getVrrConfig()) return; if (CC_UNLIKELY(mTraceOn)) { - ATRACE_FORMAT_INSTANT("vsync is %.2f past last signaled fence", - static_cast<float>(expectedPresentTime.ns() - - lastConfirmedPresentTime.ns()) / - 1e6f); + SFTRACE_FORMAT_INSTANT("vsync is %.2f past last signaled fence", + static_cast<float>(expectedPresentTime.ns() - + lastConfirmedPresentTime.ns()) / + 1e6f); } const auto currentPeriod = mRateMap.find(idealPeriod())->second.slope; const auto threshold = currentPeriod / 2; @@ -507,9 +508,9 @@ void VSyncPredictor::onFrameBegin(TimePoint expectedPresentTime, const bool frontIsBeforeConfirmed = front < lastConfirmedPresentTime.ns() + threshold; if (frontIsBeforeConfirmed) { if (CC_UNLIKELY(mTraceOn)) { - ATRACE_FORMAT_INSTANT("Discarding old vsync - %.2f before last signaled fence", - static_cast<float>(lastConfirmedPresentTime.ns() - front) / - 1e6f); + SFTRACE_FORMAT_INSTANT("Discarding old vsync - %.2f before last signaled fence", + static_cast<float>(lastConfirmedPresentTime.ns() - front) / + 1e6f); } mPastExpectedPresentTimes.pop_front(); } else { @@ -524,7 +525,7 @@ void VSyncPredictor::onFrameBegin(TimePoint expectedPresentTime, } void VSyncPredictor::onFrameMissed(TimePoint expectedPresentTime) { - ATRACE_NAME("VSyncPredictor::onFrameMissed"); + SFTRACE_NAME("VSyncPredictor::onFrameMissed"); std::lock_guard lock(mMutex); if (!mDisplayModePtr->getVrrConfig()) return; @@ -550,7 +551,7 @@ VSyncPredictor::Model VSyncPredictor::getVSyncPredictionModelLocked() const { } void VSyncPredictor::clearTimestamps() { - ATRACE_CALL(); + SFTRACE_CALL(); if (!mTimestamps.empty()) { auto const maxRb = *std::max_element(mTimestamps.begin(), mTimestamps.end()); @@ -612,7 +613,7 @@ void VSyncPredictor::purgeTimelines(android::TimePoint now) { if (mRenderRateOpt && mLastCommittedVsync.ns() + mRenderRateOpt->getPeriodNsecs() * kEnoughFramesToBreakPhase < mClock->now()) { - ATRACE_FORMAT_INSTANT("kEnoughFramesToBreakPhase"); + SFTRACE_FORMAT_INSTANT("kEnoughFramesToBreakPhase"); mTimelines.clear(); mLastCommittedVsync = TimePoint::fromNs(0); mTimelines.emplace_back(mLastCommittedVsync, mIdealPeriod, mRenderRateOpt); @@ -648,16 +649,16 @@ VSyncPredictor::VsyncTimeline::VsyncTimeline(TimePoint knownVsync, Period idealP void VSyncPredictor::VsyncTimeline::freeze(TimePoint lastVsync) { LOG_ALWAYS_FATAL_IF(mValidUntil.has_value()); - ATRACE_FORMAT_INSTANT("renderRate %s valid for %.2f", - mRenderRateOpt ? to_string(*mRenderRateOpt).c_str() : "NA", - float(lastVsync.ns() - TimePoint::now().ns()) / 1e6f); + SFTRACE_FORMAT_INSTANT("renderRate %s valid for %.2f", + mRenderRateOpt ? to_string(*mRenderRateOpt).c_str() : "NA", + float(lastVsync.ns() - TimePoint::now().ns()) / 1e6f); mValidUntil = lastVsync; } std::optional<TimePoint> VSyncPredictor::VsyncTimeline::nextAnticipatedVSyncTimeFrom( Model model, std::optional<Period> minFramePeriodOpt, nsecs_t vsync, MissedVsync missedVsync, std::optional<nsecs_t> lastVsyncOpt) { - ATRACE_FORMAT("renderRate %s", mRenderRateOpt ? to_string(*mRenderRateOpt).c_str() : "NA"); + SFTRACE_FORMAT("renderRate %s", mRenderRateOpt ? to_string(*mRenderRateOpt).c_str() : "NA"); nsecs_t vsyncTime = snapToVsyncAlignedWithRenderRate(model, vsync); const auto threshold = model.slope / 2; @@ -671,7 +672,7 @@ std::optional<TimePoint> VSyncPredictor::VsyncTimeline::nextAnticipatedVSyncTime // on whether we skipped the frame (onFrameMissed) or not (onFrameBegin) we apply a // different fixup. There is no need to to shift the vsync timeline again. vsyncTime += missedVsync.fixup.ns(); - ATRACE_FORMAT_INSTANT("lastFrameMissed"); + SFTRACE_FORMAT_INSTANT("lastFrameMissed"); } else if (mightBackpressure && lastVsyncOpt) { if (!FlagManager::getInstance().vrr_bugfix_24q4()) { // lastVsyncOpt does not need to be corrected with the new rate, and @@ -682,27 +683,27 @@ std::optional<TimePoint> VSyncPredictor::VsyncTimeline::nextAnticipatedVSyncTime const auto vsyncDiff = vsyncTime - *lastVsyncOpt; if (vsyncDiff <= minFramePeriodOpt->ns() - threshold) { // avoid a duplicate vsync - ATRACE_FORMAT_INSTANT("skipping a vsync to avoid duplicate frame. next in %.2f " - "which " - "is %.2f " - "from " - "prev. " - "adjust by %.2f", - static_cast<float>(vsyncTime - TimePoint::now().ns()) / 1e6f, - static_cast<float>(vsyncDiff) / 1e6f, - static_cast<float>(mRenderRateOpt->getPeriodNsecs()) / 1e6f); + SFTRACE_FORMAT_INSTANT("skipping a vsync to avoid duplicate frame. next in %.2f " + "which " + "is %.2f " + "from " + "prev. " + "adjust by %.2f", + static_cast<float>(vsyncTime - TimePoint::now().ns()) / 1e6f, + static_cast<float>(vsyncDiff) / 1e6f, + static_cast<float>(mRenderRateOpt->getPeriodNsecs()) / 1e6f); vsyncTime += mRenderRateOpt->getPeriodNsecs(); } } } - ATRACE_FORMAT_INSTANT("vsync in %.2fms", float(vsyncTime - TimePoint::now().ns()) / 1e6f); + SFTRACE_FORMAT_INSTANT("vsync in %.2fms", float(vsyncTime - TimePoint::now().ns()) / 1e6f); const bool isVsyncInvalid = FlagManager::getInstance().vrr_bugfix_24q4() ? isWithin(TimePoint::fromNs(vsyncTime)) == VsyncOnTimeline::Outside : mValidUntil && vsyncTime > mValidUntil->ns(); if (isVsyncInvalid) { - ATRACE_FORMAT_INSTANT("no longer valid for vsync in %.2f", - static_cast<float>(vsyncTime - TimePoint::now().ns()) / 1e6f); + SFTRACE_FORMAT_INSTANT("no longer valid for vsync in %.2f", + static_cast<float>(vsyncTime - TimePoint::now().ns()) / 1e6f); return std::nullopt; } @@ -766,14 +767,14 @@ bool VSyncPredictor::VsyncTimeline::isVSyncInPhase(Model model, nsecs_t vsync, F return true; } const auto vsyncSequence = getVsyncSequenceLocked(model, vsync); - ATRACE_FORMAT_INSTANT("vsync in: %.2f sequence: %" PRId64 " divisor: %zu", - getVsyncIn(now, vsyncSequence.vsyncTime), vsyncSequence.seq, divisor); + SFTRACE_FORMAT_INSTANT("vsync in: %.2f sequence: %" PRId64 " divisor: %zu", + getVsyncIn(now, vsyncSequence.vsyncTime), vsyncSequence.seq, divisor); return vsyncSequence.seq % divisor == 0; } void VSyncPredictor::VsyncTimeline::shiftVsyncSequence(Duration phase) { if (mLastVsyncSequence) { - ATRACE_FORMAT_INSTANT("adjusting vsync by %.2f", static_cast<float>(phase.ns()) / 1e6f); + SFTRACE_FORMAT_INSTANT("adjusting vsync by %.2f", static_cast<float>(phase.ns()) / 1e6f); mLastVsyncSequence->vsyncTime += phase.ns(); } } diff --git a/services/surfaceflinger/Scheduler/VSyncReactor.cpp b/services/surfaceflinger/Scheduler/VSyncReactor.cpp index 8038364453..2455822c7d 100644 --- a/services/surfaceflinger/Scheduler/VSyncReactor.cpp +++ b/services/surfaceflinger/Scheduler/VSyncReactor.cpp @@ -20,11 +20,10 @@ //#define LOG_NDEBUG 0 #include <assert.h> +#include <common/trace.h> #include <cutils/properties.h> #include <ftl/concat.h> -#include <gui/TraceUtils.h> #include <log/log.h> -#include <utils/Trace.h> #include "../TracedOrdinal.h" #include "VSyncDispatch.h" @@ -53,7 +52,7 @@ VSyncReactor::VSyncReactor(PhysicalDisplayId id, std::unique_ptr<Clock> clock, VSyncReactor::~VSyncReactor() = default; bool VSyncReactor::addPresentFence(std::shared_ptr<FenceTime> fence) { - ATRACE_CALL(); + SFTRACE_CALL(); if (!fence) { return false; @@ -66,8 +65,8 @@ bool VSyncReactor::addPresentFence(std::shared_ptr<FenceTime> fence) { std::lock_guard lock(mMutex); if (mExternalIgnoreFences || mInternalIgnoreFences) { - ATRACE_FORMAT_INSTANT("mExternalIgnoreFences=%d mInternalIgnoreFences=%d", - mExternalIgnoreFences, mInternalIgnoreFences); + SFTRACE_FORMAT_INSTANT("mExternalIgnoreFences=%d mInternalIgnoreFences=%d", + mExternalIgnoreFences, mInternalIgnoreFences); return true; } @@ -121,7 +120,7 @@ void VSyncReactor::updateIgnorePresentFencesInternal() { } void VSyncReactor::startPeriodTransitionInternal(ftl::NonNull<DisplayModePtr> modePtr) { - ATRACE_FORMAT("%s %" PRIu64, __func__, mId.value); + SFTRACE_FORMAT("%s %" PRIu64, __func__, mId.value); mPeriodConfirmationInProgress = true; mModePtrTransitioningTo = modePtr.get(); mMoreSamplesNeeded = true; @@ -129,15 +128,15 @@ void VSyncReactor::startPeriodTransitionInternal(ftl::NonNull<DisplayModePtr> mo } void VSyncReactor::endPeriodTransition() { - ATRACE_FORMAT("%s %" PRIu64, __func__, mId.value); + SFTRACE_FORMAT("%s %" PRIu64, __func__, mId.value); mModePtrTransitioningTo.reset(); mPeriodConfirmationInProgress = false; mLastHwVsync.reset(); } void VSyncReactor::onDisplayModeChanged(ftl::NonNull<DisplayModePtr> modePtr, bool force) { - ATRACE_INT64(ftl::Concat("VSR-", __func__, " ", mId.value).c_str(), - modePtr->getVsyncRate().getPeriodNsecs()); + SFTRACE_INT64(ftl::Concat("VSR-", __func__, " ", mId.value).c_str(), + modePtr->getVsyncRate().getPeriodNsecs()); std::lock_guard lock(mMutex); mLastHwVsync.reset(); @@ -191,7 +190,7 @@ bool VSyncReactor::addHwVsyncTimestamp(nsecs_t timestamp, std::optional<nsecs_t> std::lock_guard lock(mMutex); if (periodConfirmed(timestamp, hwcVsyncPeriod)) { - ATRACE_FORMAT("VSR %" PRIu64 ": period confirmed", mId.value); + SFTRACE_FORMAT("VSR %" PRIu64 ": period confirmed", mId.value); if (mModePtrTransitioningTo) { mTracker.setDisplayModePtr(ftl::as_non_null(mModePtrTransitioningTo)); *periodFlushed = true; @@ -205,12 +204,12 @@ bool VSyncReactor::addHwVsyncTimestamp(nsecs_t timestamp, std::optional<nsecs_t> endPeriodTransition(); mMoreSamplesNeeded = mTracker.needsMoreSamples(); } else if (mPeriodConfirmationInProgress) { - ATRACE_FORMAT("VSR %" PRIu64 ": still confirming period", mId.value); + SFTRACE_FORMAT("VSR %" PRIu64 ": still confirming period", mId.value); mLastHwVsync = timestamp; mMoreSamplesNeeded = true; *periodFlushed = false; } else { - ATRACE_FORMAT("VSR %" PRIu64 ": adding sample", mId.value); + SFTRACE_FORMAT("VSR %" PRIu64 ": adding sample", mId.value); *periodFlushed = false; mTracker.addVsyncTimestamp(timestamp); mMoreSamplesNeeded = mTracker.needsMoreSamples(); diff --git a/services/surfaceflinger/Scheduler/VsyncModulator.cpp b/services/surfaceflinger/Scheduler/VsyncModulator.cpp index 586357f50a..fa377e9323 100644 --- a/services/surfaceflinger/Scheduler/VsyncModulator.cpp +++ b/services/surfaceflinger/Scheduler/VsyncModulator.cpp @@ -22,8 +22,8 @@ #include "VsyncModulator.h" #include <android-base/properties.h> +#include <common/trace.h> #include <log/log.h> -#include <utils/Trace.h> #include <chrono> #include <cinttypes> @@ -72,7 +72,7 @@ VsyncModulator::VsyncConfigOpt VsyncModulator::setTransactionSchedule(Transactio } if (mTraceDetailedInfo) { - ATRACE_INT("mEarlyWakeup", static_cast<int>(mEarlyWakeupRequests.size())); + SFTRACE_INT("mEarlyWakeup", static_cast<int>(mEarlyWakeupRequests.size())); } if (mEarlyWakeupRequests.empty() && schedule == Schedule::EarlyEnd) { @@ -172,9 +172,9 @@ VsyncConfig VsyncModulator::updateVsyncConfigLocked() { const bool isEarlyGpu = &offsets == &mVsyncConfigSet.earlyGpu; const bool isLate = &offsets == &mVsyncConfigSet.late; - ATRACE_INT("Vsync-EarlyOffsetsOn", isEarly); - ATRACE_INT("Vsync-EarlyGpuOffsetsOn", isEarlyGpu); - ATRACE_INT("Vsync-LateOffsetsOn", isLate); + SFTRACE_INT("Vsync-EarlyOffsetsOn", isEarly); + SFTRACE_INT("Vsync-EarlyGpuOffsetsOn", isEarlyGpu); + SFTRACE_INT("Vsync-LateOffsetsOn", isLate); } return offsets; diff --git a/services/surfaceflinger/Scheduler/VsyncSchedule.cpp b/services/surfaceflinger/Scheduler/VsyncSchedule.cpp index 2fa3318560..d3e312ae00 100644 --- a/services/surfaceflinger/Scheduler/VsyncSchedule.cpp +++ b/services/surfaceflinger/Scheduler/VsyncSchedule.cpp @@ -18,8 +18,8 @@ #include <common/FlagManager.h> +#include <common/trace.h> #include <ftl/fake_guard.h> -#include <gui/TraceUtils.h> #include <scheduler/Fps.h> #include <scheduler/Timer.h> @@ -182,7 +182,7 @@ void VsyncSchedule::enableHardwareVsync() { } void VsyncSchedule::enableHardwareVsyncLocked() { - ATRACE_CALL(); + SFTRACE_CALL(); if (mHwVsyncState == HwVsyncState::Disabled) { getTracker().resetModel(); mRequestHardwareVsync(mId, true); @@ -191,7 +191,7 @@ void VsyncSchedule::enableHardwareVsyncLocked() { } void VsyncSchedule::disableHardwareVsync(bool disallow) { - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mHwVsyncLock); switch (mHwVsyncState) { case HwVsyncState::Enabled: diff --git a/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp b/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp index badd21ef86..60694b96a4 100644 --- a/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp +++ b/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp @@ -14,9 +14,8 @@ * limitations under the License. */ -#include <gui/TraceUtils.h> - #include <common/FlagManager.h> +#include <common/trace.h> #include <scheduler/FrameTargeter.h> #include <scheduler/IVsyncSource.h> @@ -90,9 +89,9 @@ void FrameTargeter::beginFrame(const BeginFrameArgs& args, const IVsyncSource& v mEarliestPresentTime = computeEarliestPresentTime(minFramePeriod, args.hwcMinWorkDuration); } - ATRACE_FORMAT("%s %" PRId64 " vsyncIn %.2fms%s", __func__, ftl::to_underlying(args.vsyncId), - ticks<std::milli, float>(mExpectedPresentTime - TimePoint::now()), - mExpectedPresentTime == args.expectedVsyncTime ? "" : " (adjusted)"); + SFTRACE_FORMAT("%s %" PRId64 " vsyncIn %.2fms%s", __func__, ftl::to_underlying(args.vsyncId), + ticks<std::milli, float>(mExpectedPresentTime - TimePoint::now()), + mExpectedPresentTime == args.expectedVsyncTime ? "" : " (adjusted)"); const FenceTimePtr& pastPresentFence = presentFenceForPastVsync(minFramePeriod); @@ -165,7 +164,7 @@ void FrameTargeter::dump(utils::Dumper& dumper) const { } bool FrameTargeter::isFencePending(const FenceTimePtr& fence, int graceTimeMs) { - ATRACE_CALL(); + SFTRACE_CALL(); const status_t status = fence->wait(graceTimeMs); // This is the same as Fence::Status::Unsignaled, but it saves a call to getStatus, diff --git a/services/surfaceflinger/Scheduler/src/Timer.cpp b/services/surfaceflinger/Scheduler/src/Timer.cpp index eeb9c60d15..fba3d58db5 100644 --- a/services/surfaceflinger/Scheduler/src/Timer.cpp +++ b/services/surfaceflinger/Scheduler/src/Timer.cpp @@ -24,10 +24,10 @@ #include <sys/timerfd.h> #include <sys/unistd.h> +#include <common/trace.h> #include <ftl/concat.h> #include <ftl/enum.h> #include <log/log.h> -#include <utils/Trace.h> #include <scheduler/Timer.h> @@ -190,7 +190,7 @@ bool Timer::dispatch() { setDebugState(DebugState::Running); if (ATRACE_ENABLED()) { ftl::Concat trace("TimerIteration #", iteration++); - ATRACE_NAME(trace.c_str()); + SFTRACE_NAME(trace.c_str()); } if (nfds == -1) { diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp index a65ef4e623..b3c9b7fa34 100644 --- a/services/surfaceflinger/SurfaceFlinger.cpp +++ b/services/surfaceflinger/SurfaceFlinger.cpp @@ -42,6 +42,7 @@ #include <binder/PermissionCache.h> #include <com_android_graphics_surfaceflinger_flags.h> #include <common/FlagManager.h> +#include <common/trace.h> #include <compositionengine/CompositionEngine.h> #include <compositionengine/CompositionRefreshArgs.h> #include <compositionengine/Display.h> @@ -71,7 +72,6 @@ #include <gui/LayerState.h> #include <gui/Surface.h> #include <gui/SurfaceComposerClient.h> -#include <gui/TraceUtils.h> #include <hidl/ServiceManagement.h> #include <layerproto/LayerProtoParser.h> #include <linux/sched/types.h> @@ -434,7 +434,7 @@ SurfaceFlinger::SurfaceFlinger(Factory& factory, SkipInitializationTag) } SurfaceFlinger::SurfaceFlinger(Factory& factory) : SurfaceFlinger(factory, SkipInitialization) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGI("SurfaceFlinger is starting"); hasSyncFramework = running_without_sync_framework(true); @@ -861,7 +861,7 @@ renderengine::RenderEngine::BlurAlgorithm chooseBlurAlgorithm(bool supportsBlur) } void SurfaceFlinger::init() FTL_FAKE_GUARD(kMainThreadContext) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGI( "SurfaceFlinger's main thread ready to run. " "Initializing graphics H/W..."); addTransactionReadyFilters(); @@ -1313,7 +1313,7 @@ void SurfaceFlinger::setDesiredMode(display::DisplayModeRequest&& desiredMode) { const auto mode = desiredMode.mode; const auto displayId = mode.modePtr->getPhysicalDisplayId(); - ATRACE_NAME(ftl::Concat(__func__, ' ', displayId.value).c_str()); + SFTRACE_NAME(ftl::Concat(__func__, ' ', displayId.value).c_str()); const bool emitEvent = desiredMode.emitEvent; @@ -1366,7 +1366,7 @@ void SurfaceFlinger::setDesiredMode(display::DisplayModeRequest&& desiredMode) { status_t SurfaceFlinger::setActiveModeFromBackdoor(const sp<display::DisplayToken>& displayToken, DisplayModeId modeId, Fps minFps, Fps maxFps) { - ATRACE_CALL(); + SFTRACE_CALL(); if (!displayToken) { return BAD_VALUE; @@ -1416,7 +1416,7 @@ status_t SurfaceFlinger::setActiveModeFromBackdoor(const sp<display::DisplayToke } void SurfaceFlinger::finalizeDisplayModeChange(PhysicalDisplayId displayId) { - ATRACE_NAME(ftl::Concat(__func__, ' ', displayId.value).c_str()); + SFTRACE_NAME(ftl::Concat(__func__, ' ', displayId.value).c_str()); const auto pendingModeOpt = mDisplayModeController.getPendingMode(displayId); if (!pendingModeOpt) { @@ -1480,7 +1480,7 @@ void SurfaceFlinger::applyActiveMode(PhysicalDisplayId displayId) { } void SurfaceFlinger::initiateDisplayModeChanges() { - ATRACE_CALL(); + SFTRACE_CALL(); std::optional<PhysicalDisplayId> displayToUpdateImmediately; @@ -1559,7 +1559,7 @@ void SurfaceFlinger::initiateDisplayModeChanges() { void SurfaceFlinger::disableExpensiveRendering() { const char* const whence = __func__; auto future = mScheduler->schedule([=, this]() FTL_FAKE_GUARD(mStateLock) { - ATRACE_NAME(whence); + SFTRACE_NAME(whence); if (mPowerAdvisor->isUsingExpensiveRendering()) { for (const auto& [_, display] : mDisplays) { constexpr bool kDisable = false; @@ -2224,9 +2224,9 @@ void SurfaceFlinger::onComposerHalVsync(hal::HWDisplayId hwcDisplayId, int64_t t } } - ATRACE_NAME(vsyncPeriod - ? ftl::Concat(__func__, ' ', hwcDisplayId, ' ', *vsyncPeriod, "ns").c_str() - : ftl::Concat(__func__, ' ', hwcDisplayId).c_str()); + SFTRACE_NAME(vsyncPeriod + ? ftl::Concat(__func__, ' ', hwcDisplayId, ' ', *vsyncPeriod, "ns").c_str() + : ftl::Concat(__func__, ' ', hwcDisplayId).c_str()); Mutex::Autolock lock(mStateLock); if (const auto displayIdOpt = getHwComposer().onVsync(hwcDisplayId, timestamp)) { @@ -2284,12 +2284,12 @@ void SurfaceFlinger::onComposerHalRefresh(hal::HWDisplayId) { } void SurfaceFlinger::onComposerHalVsyncIdle(hal::HWDisplayId) { - ATRACE_CALL(); + SFTRACE_CALL(); mScheduler->forceNextResync(); } void SurfaceFlinger::onRefreshRateChangedDebug(const RefreshRateChangedDebugData& data) { - ATRACE_CALL(); + SFTRACE_CALL(); const char* const whence = __func__; static_cast<void>(mScheduler->schedule([=, this]() FTL_FAKE_GUARD(mStateLock) FTL_FAKE_GUARD( kMainThreadContext) { @@ -2298,7 +2298,7 @@ void SurfaceFlinger::onRefreshRateChangedDebug(const RefreshRateChangedDebugData const Fps refreshRate = Fps::fromPeriodNsecs( getHwComposer().getComposer()->isVrrSupported() ? data.refreshPeriodNanos : data.vsyncPeriodNanos); - ATRACE_FORMAT("%s refresh rate = %d", whence, refreshRate.getIntValue()); + SFTRACE_FORMAT("%s refresh rate = %d", whence, refreshRate.getIntValue()); const auto renderRate = mDisplayModeController.getActiveMode(*displayIdOpt).fps; constexpr bool kSetByHwc = true; @@ -2318,7 +2318,7 @@ void SurfaceFlinger::configure() { bool SurfaceFlinger::updateLayerSnapshotsLegacy(VsyncId vsyncId, nsecs_t frameTimeNs, bool flushTransactions, bool& outTransactionsAreEmpty) { - ATRACE_CALL(); + SFTRACE_CALL(); frontend::Update update; if (flushTransactions) { update = flushLifecycleUpdates(); @@ -2417,10 +2417,10 @@ void SurfaceFlinger::updateLayerHistory(nsecs_t now) { bool SurfaceFlinger::updateLayerSnapshots(VsyncId vsyncId, nsecs_t frameTimeNs, bool flushTransactions, bool& outTransactionsAreEmpty) { using Changes = frontend::RequestedLayerState::Changes; - ATRACE_CALL(); + SFTRACE_CALL(); frontend::Update update; if (flushTransactions) { - ATRACE_NAME("TransactionHandler:flushTransactions"); + SFTRACE_NAME("TransactionHandler:flushTransactions"); // Locking: // 1. to prevent onHandleDestroyed from being called while the state lock is held, // we must keep a copy of the transactions (specifically the composer @@ -2472,7 +2472,7 @@ bool SurfaceFlinger::updateLayerSnapshots(VsyncId vsyncId, nsecs_t frameTimeNs, mustComposite |= applyAndCommitDisplayTransactionStatesLocked(update.transactions); { - ATRACE_NAME("LayerSnapshotBuilder:update"); + SFTRACE_NAME("LayerSnapshotBuilder:update"); frontend::LayerSnapshotBuilder::Args args{.root = mLayerHierarchyBuilder.getHierarchy(), .layerLifecycleManager = mLayerLifecycleManager, @@ -2513,7 +2513,7 @@ bool SurfaceFlinger::updateLayerSnapshots(VsyncId vsyncId, nsecs_t frameTimeNs, } bool newDataLatched = false; - ATRACE_NAME("DisplayCallbackAndStatsUpdates"); + SFTRACE_NAME("DisplayCallbackAndStatsUpdates"); mustComposite |= applyTransactionsLocked(update.transactions, vsyncId); traverseLegacyLayers([&](Layer* layer) { layer->commitTransaction(); }); const nsecs_t latchTime = systemTime(); @@ -2579,7 +2579,7 @@ bool SurfaceFlinger::updateLayerSnapshots(VsyncId vsyncId, nsecs_t frameTimeNs, } { - ATRACE_NAME("LLM:commitChanges"); + SFTRACE_NAME("LLM:commitChanges"); mLayerLifecycleManager.commitChanges(); } @@ -2602,7 +2602,7 @@ bool SurfaceFlinger::commit(PhysicalDisplayId pacesetterId, const scheduler::FrameTarget& pacesetterFrameTarget = *frameTargets.get(pacesetterId)->get(); const VsyncId vsyncId = pacesetterFrameTarget.vsyncId(); - ATRACE_NAME(ftl::Concat(__func__, ' ', ftl::to_underlying(vsyncId)).c_str()); + SFTRACE_NAME(ftl::Concat(__func__, ' ', ftl::to_underlying(vsyncId)).c_str()); if (pacesetterFrameTarget.didMissFrame()) { mTimeStats->incrementMissedFrames(); @@ -2744,7 +2744,7 @@ CompositeResultsPerDisplay SurfaceFlinger::composite( frameTargeters.get(pacesetterId)->get()->target(); const VsyncId vsyncId = pacesetterTarget.vsyncId(); - ATRACE_NAME(ftl::Concat(__func__, ' ', ftl::to_underlying(vsyncId)).c_str()); + SFTRACE_NAME(ftl::Concat(__func__, ' ', ftl::to_underlying(vsyncId)).c_str()); compositionengine::CompositionRefreshArgs refreshArgs; refreshArgs.powerCallback = this; @@ -2908,7 +2908,7 @@ CompositeResultsPerDisplay SurfaceFlinger::composite( } } - ATRACE_NAME("postComposition"); + SFTRACE_NAME("postComposition"); mTimeStats->recordFrameDuration(pacesetterTarget.frameBeginTime().ns(), systemTime()); // Send a power hint after presentation is finished. @@ -3004,7 +3004,7 @@ CompositeResultsPerDisplay SurfaceFlinger::composite( } void SurfaceFlinger::updateLayerGeometry() { - ATRACE_CALL(); + SFTRACE_CALL(); if (mVisibleRegionsDirty) { computeLayerBounds(); @@ -3088,7 +3088,7 @@ ui::Rotation SurfaceFlinger::getPhysicalDisplayOrientation(DisplayId displayId, void SurfaceFlinger::onCompositionPresented(PhysicalDisplayId pacesetterId, const scheduler::FrameTargeters& frameTargeters, nsecs_t presentStartTime) { - ATRACE_CALL(); + SFTRACE_CALL(); ui::PhysicalDisplayMap<PhysicalDisplayId, std::shared_ptr<FenceTime>> presentFences; ui::PhysicalDisplayMap<PhysicalDisplayId, const sp<Fence>> gpuCompositionDoneFences; @@ -3333,7 +3333,7 @@ void SurfaceFlinger::onCompositionPresented(PhysicalDisplayId pacesetterId, // side-effect of getTotalSize(), so we check that again here if (ATRACE_ENABLED()) { // getTotalSize returns the total number of buffers that were allocated by SurfaceFlinger - ATRACE_INT64("Total Buffer Size", GraphicBufferAllocator::get().getTotalSize()); + SFTRACE_INT64("Total Buffer Size", GraphicBufferAllocator::get().getTotalSize()); } logFrameStats(presentTime); @@ -3370,7 +3370,7 @@ void SurfaceFlinger::computeLayerBounds() { } void SurfaceFlinger::commitTransactions() { - ATRACE_CALL(); + SFTRACE_CALL(); mDebugInTransaction = systemTime(); // Here we're guaranteed that some transaction flags are set @@ -3383,7 +3383,7 @@ void SurfaceFlinger::commitTransactions() { } void SurfaceFlinger::commitTransactionsLegacy() { - ATRACE_CALL(); + SFTRACE_CALL(); // Keep a copy of the drawing state (that is going to be overwritten // by commitTransactionsLocked) outside of mStateLock so that the side @@ -4131,7 +4131,7 @@ void SurfaceFlinger::updateInputFlinger(VsyncId vsyncId, TimePoint frameTime) { if (!mInputFlinger || (!mUpdateInputInfo && mInputWindowCommands.empty())) { return; } - ATRACE_CALL(); + SFTRACE_CALL(); std::vector<WindowInfo> windowInfos; std::vector<DisplayInfo> displayInfos; @@ -4161,7 +4161,7 @@ void SurfaceFlinger::updateInputFlinger(VsyncId vsyncId, TimePoint frameTime) { std::move(mInputWindowCommands), inputFlinger = mInputFlinger, this, visibleWindowsChanged, vsyncId, frameTime]() { - ATRACE_NAME("BackgroundExecutor::updateInputFlinger"); + SFTRACE_NAME("BackgroundExecutor::updateInputFlinger"); if (updateWindowInfo) { mWindowInfosListenerInvoker ->windowInfosChanged(gui::WindowInfosUpdate{std::move(windowInfos), @@ -4274,7 +4274,7 @@ void SurfaceFlinger::requestDisplayModes(std::vector<display::DisplayModeRequest return; } - ATRACE_CALL(); + SFTRACE_CALL(); // If this is called from the main thread mStateLock must be locked before // Currently the only way to call this function from the main thread is from @@ -4313,7 +4313,7 @@ void SurfaceFlinger::notifyCpuLoadUp() { } void SurfaceFlinger::onChoreographerAttached() { - ATRACE_CALL(); + SFTRACE_CALL(); if (mLayerLifecycleManagerEnabled) { mUpdateAttachedChoreographer = true; scheduleCommit(FrameHint::kNone); @@ -4541,7 +4541,7 @@ void SurfaceFlinger::initScheduler(const sp<const DisplayDevice>& display) { } void SurfaceFlinger::doCommitTransactions() { - ATRACE_CALL(); + SFTRACE_CALL(); if (!mLayersPendingRemoval.isEmpty()) { // Notify removed layers now that they can't be drawn from @@ -4622,7 +4622,7 @@ void SurfaceFlinger::invalidateLayerStack(const ui::LayerFilter& layerFilter, co } bool SurfaceFlinger::latchBuffers() { - ATRACE_CALL(); + SFTRACE_CALL(); const nsecs_t latchTime = systemTime(); @@ -4799,7 +4799,7 @@ uint32_t SurfaceFlinger::getTransactionFlags() const { uint32_t SurfaceFlinger::clearTransactionFlags(uint32_t mask) { uint32_t transactionFlags = mTransactionFlags.fetch_and(~mask); - ATRACE_INT("mTransactionFlags", transactionFlags); + SFTRACE_INT("mTransactionFlags", transactionFlags); return transactionFlags & mask; } @@ -4807,7 +4807,7 @@ void SurfaceFlinger::setTransactionFlags(uint32_t mask, TransactionSchedule sche const sp<IBinder>& applyToken, FrameHint frameHint) { mScheduler->modulateVsync({}, &VsyncModulator::setTransactionSchedule, schedule, applyToken); uint32_t transactionFlags = mTransactionFlags.fetch_or(mask); - ATRACE_INT("mTransactionFlags", transactionFlags); + SFTRACE_INT("mTransactionFlags", transactionFlags); if (const bool scheduled = transactionFlags & mask; !scheduled) { scheduleCommit(frameHint); @@ -4832,8 +4832,8 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyTimelin // for stability reasons. if (!transaction.isAutoTimestamp && desiredPresentTime >= expectedPresentTime && desiredPresentTime < expectedPresentTime + 1s) { - ATRACE_FORMAT("not current desiredPresentTime: %" PRId64 " expectedPresentTime: %" PRId64, - desiredPresentTime, expectedPresentTime); + SFTRACE_FORMAT("not current desiredPresentTime: %" PRId64 " expectedPresentTime: %" PRId64, + desiredPresentTime, expectedPresentTime); return TransactionReadiness::NotReady; } @@ -4845,16 +4845,16 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyTimelin // incorrectly as the frame rate of SF changed before it drained the older transactions. if (ftl::to_underlying(vsyncId) == FrameTimelineInfo::INVALID_VSYNC_ID && !mScheduler->isVsyncValid(expectedPresentTime, transaction.originUid)) { - ATRACE_FORMAT("!isVsyncValid expectedPresentTime: %" PRId64 " uid: %d", expectedPresentTime, - transaction.originUid); + SFTRACE_FORMAT("!isVsyncValid expectedPresentTime: %" PRId64 " uid: %d", + expectedPresentTime, transaction.originUid); return TransactionReadiness::NotReady; } // If the client didn't specify desiredPresentTime, use the vsyncId to determine the // expected present time of this transaction. if (transaction.isAutoTimestamp && frameIsEarly(expectedPresentTime, vsyncId)) { - ATRACE_FORMAT("frameIsEarly vsyncId: %" PRId64 " expectedPresentTime: %" PRId64, - transaction.frameTimelineInfo.vsyncId, expectedPresentTime); + SFTRACE_FORMAT("frameIsEarly vsyncId: %" PRId64 " expectedPresentTime: %" PRId64, + transaction.frameTimelineInfo.vsyncId, expectedPresentTime); return TransactionReadiness::NotReady; } @@ -4883,9 +4883,9 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC s.bufferData->acquireFence); // Delete the entire state at this point and not just release the buffer because // everything associated with the Layer in this Transaction is now out of date. - ATRACE_FORMAT("DeleteStaleBuffer %s barrierProducerId:%d > %d", - layer->getDebugName(), layer->getDrawingState().barrierProducerId, - s.bufferData->producerId); + SFTRACE_FORMAT("DeleteStaleBuffer %s barrierProducerId:%d > %d", + layer->getDebugName(), layer->getDrawingState().barrierProducerId, + s.bufferData->producerId); return TraverseBuffersReturnValues::DELETE_AND_CONTINUE_TRAVERSAL; } @@ -4895,10 +4895,10 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC ((flushState.bufferLayersReadyToPresent.get(s.surface.get()) >= s.bufferData->barrierFrameNumber)); if (!willApplyBarrierFrame) { - ATRACE_FORMAT("NotReadyBarrier %s barrierFrameNumber:%" PRId64 " > %" PRId64, - layer->getDebugName(), - layer->getDrawingState().barrierFrameNumber, - s.bufferData->barrierFrameNumber); + SFTRACE_FORMAT("NotReadyBarrier %s barrierFrameNumber:%" PRId64 " > %" PRId64, + layer->getDebugName(), + layer->getDrawingState().barrierFrameNumber, + s.bufferData->barrierFrameNumber); ready = TransactionReadiness::NotReadyBarrier; return TraverseBuffersReturnValues::STOP_TRAVERSAL; } @@ -4910,7 +4910,7 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC const bool hasPendingBuffer = flushState.bufferLayersReadyToPresent.contains(s.surface.get()); if (layer->backpressureEnabled() && hasPendingBuffer && transaction.isAutoTimestamp) { - ATRACE_FORMAT("hasPendingBuffer %s", layer->getDebugName()); + SFTRACE_FORMAT("hasPendingBuffer %s", layer->getDebugName()); ready = TransactionReadiness::NotReady; return TraverseBuffersReturnValues::STOP_TRAVERSAL; } @@ -4927,8 +4927,8 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC layer->isSimpleBufferUpdate(s); if (allowLatchUnsignaled) { - ATRACE_FORMAT("fence unsignaled try allowLatchUnsignaled %s", - layer->getDebugName()); + SFTRACE_FORMAT("fence unsignaled try allowLatchUnsignaled %s", + layer->getDebugName()); ready = TransactionReadiness::NotReadyUnsignaled; } else { ready = TransactionReadiness::NotReady; @@ -4947,7 +4947,7 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC .bufferId = s.bufferData->getId(), .frameNumber = s.bufferData->frameNumber}); } - ATRACE_FORMAT("fence unsignaled %s", layer->getDebugName()); + SFTRACE_FORMAT("fence unsignaled %s", layer->getDebugName()); return TraverseBuffersReturnValues::STOP_TRAVERSAL; } } @@ -4977,8 +4977,8 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC uint32_t currentMaxAcquiredBufferCount = getMaxAcquiredBufferCountForCurrentRefreshRate( layer->ownerUid.val()); - ATRACE_FORMAT_INSTANT("callReleaseBufferCallback %s - %" PRIu64, - layer->name.c_str(), s.bufferData->frameNumber); + SFTRACE_FORMAT_INSTANT("callReleaseBufferCallback %s - %" PRIu64, + layer->name.c_str(), s.bufferData->frameNumber); s.bufferData->releaseBufferListener ->onReleaseBuffer({resolvedState.externalTexture->getBuffer() ->getId(), @@ -4992,9 +4992,9 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC // Delete the entire state at this point and not just release the buffer // because everything associated with the Layer in this Transaction is now // out of date. - ATRACE_FORMAT("DeleteStaleBuffer %s barrierProducerId:%d > %d", - layer->name.c_str(), layer->barrierProducerId, - s.bufferData->producerId); + SFTRACE_FORMAT("DeleteStaleBuffer %s barrierProducerId:%d > %d", + layer->name.c_str(), layer->barrierProducerId, + s.bufferData->producerId); return TraverseBuffersReturnValues::DELETE_AND_CONTINUE_TRAVERSAL; } @@ -5004,10 +5004,10 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC ((flushState.bufferLayersReadyToPresent.get(s.surface.get()) >= s.bufferData->barrierFrameNumber)); if (!willApplyBarrierFrame) { - ATRACE_FORMAT("NotReadyBarrier %s barrierFrameNumber:%" PRId64 - " > %" PRId64, - layer->name.c_str(), layer->barrierFrameNumber, - s.bufferData->barrierFrameNumber); + SFTRACE_FORMAT("NotReadyBarrier %s barrierFrameNumber:%" PRId64 + " > %" PRId64, + layer->name.c_str(), layer->barrierFrameNumber, + s.bufferData->barrierFrameNumber); ready = TransactionReadiness::NotReadyBarrier; return TraverseBuffersReturnValues::STOP_TRAVERSAL; } @@ -5020,7 +5020,7 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC flushState.bufferLayersReadyToPresent.contains(s.surface.get()); if (layer->backpressureEnabled() && hasPendingBuffer && transaction.isAutoTimestamp) { - ATRACE_FORMAT("hasPendingBuffer %s", layer->name.c_str()); + SFTRACE_FORMAT("hasPendingBuffer %s", layer->name.c_str()); ready = TransactionReadiness::NotReady; return TraverseBuffersReturnValues::STOP_TRAVERSAL; } @@ -5037,8 +5037,8 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC flushState.firstTransaction) && layer->isSimpleBufferUpdate(s); if (allowLatchUnsignaled) { - ATRACE_FORMAT("fence unsignaled try allowLatchUnsignaled %s", - layer->name.c_str()); + SFTRACE_FORMAT("fence unsignaled try allowLatchUnsignaled %s", + layer->name.c_str()); ready = TransactionReadiness::NotReadyUnsignaled; } else { ready = TransactionReadiness::NotReady; @@ -5055,7 +5055,7 @@ TransactionHandler::TransactionReadiness SurfaceFlinger::transactionReadyBufferC .frameNumber = s.bufferData->frameNumber}); } - ATRACE_FORMAT("fence unsignaled %s", layer->name.c_str()); + SFTRACE_FORMAT("fence unsignaled %s", layer->name.c_str()); return TraverseBuffersReturnValues::STOP_TRAVERSAL; } } @@ -5136,22 +5136,22 @@ bool SurfaceFlinger::frameIsEarly(TimePoint expectedPresentTime, VsyncId vsyncId bool SurfaceFlinger::shouldLatchUnsignaled(const layer_state_t& state, size_t numStates, bool firstTransaction) const { if (enableLatchUnsignaledConfig == LatchUnsignaledConfig::Disabled) { - ATRACE_FORMAT_INSTANT("%s: false (LatchUnsignaledConfig::Disabled)", __func__); + SFTRACE_FORMAT_INSTANT("%s: false (LatchUnsignaledConfig::Disabled)", __func__); return false; } // We only want to latch unsignaled when a single layer is updated in this // transaction (i.e. not a blast sync transaction). if (numStates != 1) { - ATRACE_FORMAT_INSTANT("%s: false (numStates=%zu)", __func__, numStates); + SFTRACE_FORMAT_INSTANT("%s: false (numStates=%zu)", __func__, numStates); return false; } if (enableLatchUnsignaledConfig == LatchUnsignaledConfig::AutoSingleLayer) { if (!firstTransaction) { - ATRACE_FORMAT_INSTANT("%s: false (LatchUnsignaledConfig::AutoSingleLayer; not first " - "transaction)", - __func__); + SFTRACE_FORMAT_INSTANT("%s: false (LatchUnsignaledConfig::AutoSingleLayer; not first " + "transaction)", + __func__); return false; } @@ -5159,9 +5159,9 @@ bool SurfaceFlinger::shouldLatchUnsignaled(const layer_state_t& state, size_t nu // as it leads to jank due to RenderEngine waiting for unsignaled buffer // or window animations being slow. if (mScheduler->vsyncModulator().isVsyncConfigEarly()) { - ATRACE_FORMAT_INSTANT("%s: false (LatchUnsignaledConfig::AutoSingleLayer; " - "isVsyncConfigEarly)", - __func__); + SFTRACE_FORMAT_INSTANT("%s: false (LatchUnsignaledConfig::AutoSingleLayer; " + "isVsyncConfigEarly)", + __func__); return false; } } @@ -5176,7 +5176,7 @@ status_t SurfaceFlinger::setTransactionState( const std::vector<client_cache_t>& uncacheBuffers, bool hasListenerCallbacks, const std::vector<ListenerCallbacks>& listenerCallbacks, uint64_t transactionId, const std::vector<uint64_t>& mergedTransactionIds) { - ATRACE_CALL(); + SFTRACE_CALL(); IPCThreadState* ipc = IPCThreadState::self(); const int originPid = ipc->getCallingPid(); @@ -6459,7 +6459,7 @@ void SurfaceFlinger::logFrameStats(TimePoint now) { if (now - sTimestamp < 30min) return; sTimestamp = now; - ATRACE_CALL(); + SFTRACE_CALL(); mDrawingState.traverse([&](Layer* layer) { layer->logFrameStats(); }); } @@ -7764,7 +7764,7 @@ void SurfaceFlinger::toggleKernelIdleTimer() { switch (action) { case KernelIdleTimerAction::TurnOff: if (mKernelIdleTimerEnabled) { - ATRACE_INT("KernelIdleTimer", 0); + SFTRACE_INT("KernelIdleTimer", 0); std::chrono::milliseconds constexpr kTimerDisabledTimeout = 0ms; updateKernelIdleTimer(kTimerDisabledTimeout, kernelIdleTimerController.value(), display->getPhysicalId()); @@ -7773,7 +7773,7 @@ void SurfaceFlinger::toggleKernelIdleTimer() { break; case KernelIdleTimerAction::TurnOn: if (!mKernelIdleTimerEnabled) { - ATRACE_INT("KernelIdleTimer", 1); + SFTRACE_INT("KernelIdleTimer", 1); const std::chrono::milliseconds timeout = display->refreshRateSelector().getIdleTimerTimeout(); updateKernelIdleTimer(timeout, kernelIdleTimerController.value(), @@ -7902,7 +7902,7 @@ static void invokeScreenCaptureError(const status_t status, void SurfaceFlinger::captureDisplay(const DisplayCaptureArgs& args, const sp<IScreenCaptureListener>& captureListener) { - ATRACE_CALL(); + SFTRACE_CALL(); status_t validate = validateScreenshotPermissions(args); if (validate != OK) { @@ -8033,7 +8033,7 @@ ScreenCaptureResults SurfaceFlinger::captureLayersSync(const LayerCaptureArgs& a void SurfaceFlinger::captureLayers(const LayerCaptureArgs& args, const sp<IScreenCaptureListener>& captureListener) { - ATRACE_CALL(); + SFTRACE_CALL(); status_t validate = validateScreenshotPermissions(args); if (validate != OK) { @@ -8166,7 +8166,7 @@ std::optional<SurfaceFlinger::OutputCompositionState> SurfaceFlinger::getSnapsho std::vector<sp<LayerFE>>& layerFEs) { return mScheduler ->schedule([=, this, &renderAreaBuilder, &layerFEs]() REQUIRES(kMainThreadContext) { - ATRACE_NAME("getSnapshotsFromMainThread"); + SFTRACE_NAME("getSnapshotsFromMainThread"); auto layers = getLayerSnapshotsFn(); for (auto& [layer, layerFE] : layers) { attachReleaseFenceFutureToLayer(layer, layerFE.get(), ui::INVALID_LAYER_STACK); @@ -8182,7 +8182,7 @@ void SurfaceFlinger::captureScreenCommon(RenderAreaBuilderVariant renderAreaBuil ui::Size bufferSize, ui::PixelFormat reqPixelFormat, bool allowProtected, bool grayscale, const sp<IScreenCaptureListener>& captureListener) { - ATRACE_CALL(); + SFTRACE_CALL(); if (exceedsMaxRenderTargetSize(bufferSize.getWidth(), bufferSize.getHeight())) { ALOGE("Attempted to capture screen with size (%" PRId32 ", %" PRId32 @@ -8319,7 +8319,7 @@ ftl::SharedFuture<FenceResult> SurfaceFlinger::captureScreenshot( const std::shared_ptr<renderengine::ExternalTexture>& buffer, bool regionSampling, bool grayscale, bool isProtected, const sp<IScreenCaptureListener>& captureListener, std::optional<OutputCompositionState>& displayState, std::vector<sp<LayerFE>>& layerFEs) { - ATRACE_CALL(); + SFTRACE_CALL(); ScreenCaptureResults captureResults; std::unique_ptr<const RenderArea> renderArea = @@ -8359,7 +8359,7 @@ ftl::SharedFuture<FenceResult> SurfaceFlinger::captureScreenshotLegacy( RenderAreaBuilderVariant renderAreaBuilder, GetLayerSnapshotsFunction getLayerSnapshotsFn, const std::shared_ptr<renderengine::ExternalTexture>& buffer, bool regionSampling, bool grayscale, bool isProtected, const sp<IScreenCaptureListener>& captureListener) { - ATRACE_CALL(); + SFTRACE_CALL(); auto takeScreenshotFn = [=, this, renderAreaBuilder = std::move(renderAreaBuilder)]() REQUIRES( kMainThreadContext) mutable -> ftl::SharedFuture<FenceResult> { @@ -8423,7 +8423,7 @@ ftl::SharedFuture<FenceResult> SurfaceFlinger::renderScreenImpl( bool grayscale, bool isProtected, ScreenCaptureResults& captureResults, std::optional<OutputCompositionState>& displayState, std::vector<std::pair<Layer*, sp<LayerFE>>>& layers, std::vector<sp<LayerFE>>& layerFEs) { - ATRACE_CALL(); + SFTRACE_CALL(); for (auto& layerFE : layerFEs) { frontend::LayerSnapshot* snapshot = layerFE->mSnapshot.get(); @@ -8681,7 +8681,7 @@ status_t SurfaceFlinger::setDesiredDisplayModeSpecsInternal( const sp<DisplayDevice>& display, const scheduler::RefreshRateSelector::PolicyVariant& policy) { const auto displayId = display->getPhysicalId(); - ATRACE_NAME(ftl::Concat(__func__, ' ', displayId.value).c_str()); + SFTRACE_NAME(ftl::Concat(__func__, ' ', displayId.value).c_str()); Mutex::Autolock lock(mStateLock); @@ -8774,7 +8774,7 @@ gui::DisplayModeSpecs::RefreshRateRanges translate(const FpsRanges& ranges) { status_t SurfaceFlinger::setDesiredDisplayModeSpecs(const sp<IBinder>& displayToken, const gui::DisplayModeSpecs& specs) { - ATRACE_CALL(); + SFTRACE_CALL(); if (!displayToken) { return BAD_VALUE; @@ -8808,7 +8808,7 @@ status_t SurfaceFlinger::setDesiredDisplayModeSpecs(const sp<IBinder>& displayTo status_t SurfaceFlinger::getDesiredDisplayModeSpecs(const sp<IBinder>& displayToken, gui::DisplayModeSpecs* outSpecs) { - ATRACE_CALL(); + SFTRACE_CALL(); if (!displayToken || !outSpecs) { return BAD_VALUE; @@ -9100,7 +9100,7 @@ sp<DisplayDevice> SurfaceFlinger::getActivatableDisplay() const { void SurfaceFlinger::onActiveDisplayChangedLocked(const DisplayDevice* inactiveDisplayPtr, const DisplayDevice& activeDisplay) { - ATRACE_CALL(); + SFTRACE_CALL(); if (inactiveDisplayPtr) { inactiveDisplayPtr->getCompositionDisplay()->setLayerCachingTexturePoolEnabled(false); @@ -9534,7 +9534,7 @@ SurfaceFlinger::getLayerSnapshotsForScreenshots(uint32_t rootLayerId, uint32_t u frontend::Update SurfaceFlinger::flushLifecycleUpdates() { frontend::Update update; - ATRACE_NAME("TransactionHandler:flushTransactions"); + SFTRACE_NAME("TransactionHandler:flushTransactions"); // Locking: // 1. to prevent onHandleDestroyed from being called while the state lock is held, // we must keep a copy of the transactions (specifically the composer @@ -9580,7 +9580,7 @@ void SurfaceFlinger::doActiveLayersTracingIfNeeded(bool isCompositionComputed, perfetto::protos::LayersSnapshotProto SurfaceFlinger::takeLayersSnapshotProto( uint32_t traceFlags, TimePoint time, VsyncId vsyncId, bool visibleRegionDirty) { - ATRACE_CALL(); + SFTRACE_CALL(); perfetto::protos::LayersSnapshotProto snapshot; snapshot.set_elapsed_realtime_nanos(time.ns()); snapshot.set_vsync_id(ftl::to_underlying(vsyncId)); diff --git a/services/surfaceflinger/SurfaceFlinger.h b/services/surfaceflinger/SurfaceFlinger.h index 54717c0599..8242844b03 100644 --- a/services/surfaceflinger/SurfaceFlinger.h +++ b/services/surfaceflinger/SurfaceFlinger.h @@ -29,6 +29,7 @@ #include <android/gui/DisplayState.h> #include <android/gui/IJankListener.h> #include <android/gui/ISurfaceComposerClient.h> +#include <common/trace.h> #include <cutils/atomic.h> #include <cutils/compiler.h> #include <ftl/algorithm.h> @@ -53,7 +54,6 @@ #include <utils/KeyedVector.h> #include <utils/RefBase.h> #include <utils/SortedVector.h> -#include <utils/Trace.h> #include <utils/threads.h> #include <compositionengine/OutputColorSetting.h> @@ -450,7 +450,7 @@ private: if (it != mCounterByLayerHandle.end()) { auto [name, pendingBuffers] = it->second; int32_t count = ++(*pendingBuffers); - ATRACE_INT(name.c_str(), count); + SFTRACE_INT(name.c_str(), count); } else { ALOGW("Handle not found! %p", layerHandle); } diff --git a/services/surfaceflinger/TimeStats/Android.bp b/services/surfaceflinger/TimeStats/Android.bp index a631074f4d..ea86911bed 100644 --- a/services/surfaceflinger/TimeStats/Android.bp +++ b/services/surfaceflinger/TimeStats/Android.bp @@ -24,6 +24,7 @@ cc_defaults { static_libs: [ "libtimestats_proto", + "libsurfaceflinger_common", ], export_static_lib_headers: [ diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp index 368cb41779..c60ded6e56 100644 --- a/services/surfaceflinger/TimeStats/TimeStats.cpp +++ b/services/surfaceflinger/TimeStats/TimeStats.cpp @@ -19,11 +19,11 @@ #define ATRACE_TAG ATRACE_TAG_GRAPHICS #include <android-base/stringprintf.h> +#include <common/trace.h> #include <log/log.h> #include <timestatsatomsproto/TimeStatsAtomsProtoHeader.h> #include <utils/String8.h> #include <utils/Timers.h> -#include <utils/Trace.h> #include <algorithm> #include <chrono> @@ -271,7 +271,7 @@ bool TimeStats::onPullAtom(const int atomId, std::vector<uint8_t>* pulledData) { } void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::string& result) { - ATRACE_CALL(); + SFTRACE_CALL(); std::unordered_map<std::string, int32_t> argsMap; for (size_t index = 0; index < args.size(); ++index) { @@ -304,7 +304,7 @@ void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::strin } std::string TimeStats::miniDump() { - ATRACE_CALL(); + SFTRACE_CALL(); std::string result = "TimeStats miniDump:\n"; std::lock_guard<std::mutex> lock(mMutex); @@ -318,7 +318,7 @@ std::string TimeStats::miniDump() { void TimeStats::incrementTotalFrames() { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); mTimeStats.totalFramesLegacy++; @@ -327,7 +327,7 @@ void TimeStats::incrementTotalFrames() { void TimeStats::incrementMissedFrames() { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); mTimeStats.missedFramesLegacy++; @@ -338,7 +338,7 @@ void TimeStats::pushCompositionStrategyState(const TimeStats::ClientCompositionR return; } - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); if (record.changed) mTimeStats.compositionStrategyChangesLegacy++; @@ -351,7 +351,7 @@ void TimeStats::pushCompositionStrategyState(const TimeStats::ClientCompositionR void TimeStats::incrementRefreshRateSwitches() { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); mTimeStats.refreshRateSwitchesLegacy++; @@ -445,7 +445,7 @@ void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId, Fps displayR std::optional<Fps> renderRate, SetFrameRateVote frameRateVote, GameMode gameMode) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-flushAvailableRecordsToStatsLocked", layerId); LayerRecord& layerRecord = mTimeStatsTracker[layerId]; @@ -568,7 +568,7 @@ void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::st uid_t uid, nsecs_t postTime, GameMode gameMode) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-[%" PRIu64 "]-[%s]-PostTime[%" PRId64 "]", layerId, frameNumber, layerName.c_str(), postTime); @@ -612,7 +612,7 @@ void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::st void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerId, frameNumber, latchTime); std::lock_guard<std::mutex> lock(mMutex); @@ -630,7 +630,7 @@ void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latc void TimeStats::incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-LatchSkipped-Reason[%d]", layerId, static_cast<std::underlying_type<LatchSkipReason>::type>(reason)); @@ -648,7 +648,7 @@ void TimeStats::incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) { void TimeStats::incrementBadDesiredPresent(int32_t layerId) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-BadDesiredPresent", layerId); std::lock_guard<std::mutex> lock(mMutex); @@ -660,7 +660,7 @@ void TimeStats::incrementBadDesiredPresent(int32_t layerId) { void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerId, frameNumber, desiredTime); std::lock_guard<std::mutex> lock(mMutex); @@ -678,7 +678,7 @@ void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t de void TimeStats::setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerId, frameNumber, acquireTime); std::lock_guard<std::mutex> lock(mMutex); @@ -697,7 +697,7 @@ void TimeStats::setAcquireFence(int32_t layerId, uint64_t frameNumber, const std::shared_ptr<FenceTime>& acquireFence) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerId, frameNumber, acquireFence->getSignalTime()); @@ -718,7 +718,7 @@ void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t pr SetFrameRateVote frameRateVote, GameMode gameMode) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerId, frameNumber, presentTime); std::lock_guard<std::mutex> lock(mMutex); @@ -744,7 +744,7 @@ void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber, SetFrameRateVote frameRateVote, GameMode gameMode) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerId, frameNumber, presentFence->getSignalTime()); @@ -805,7 +805,7 @@ static void updateJankPayload(T& t, int32_t reasons) { void TimeStats::incrementJankyFrames(const JankyFramesInfo& info) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); // Only update layer stats if we're already tracking the layer in TimeStats. @@ -861,7 +861,7 @@ void TimeStats::incrementJankyFrames(const JankyFramesInfo& info) { } void TimeStats::onDestroy(int32_t layerId) { - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-onDestroy", layerId); std::lock_guard<std::mutex> lock(mMutex); mTimeStatsTracker.erase(layerId); @@ -870,7 +870,7 @@ void TimeStats::onDestroy(int32_t layerId) { void TimeStats::removeTimeRecord(int32_t layerId, uint64_t frameNumber) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); ALOGV("[%d]-[%" PRIu64 "]-removeTimeRecord", layerId, frameNumber); std::lock_guard<std::mutex> lock(mMutex); @@ -935,7 +935,7 @@ void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) { } void TimeStats::flushAvailableGlobalRecordsToStatsLocked() { - ATRACE_CALL(); + SFTRACE_CALL(); while (!mGlobalRecord.presentFences.empty()) { const nsecs_t curPresentTime = mGlobalRecord.presentFences.front()->getSignalTime(); @@ -992,7 +992,7 @@ void TimeStats::flushAvailableGlobalRecordsToStatsLocked() { void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); if (presentFence == nullptr || !presentFence->isValid()) { mGlobalRecord.prevPresentTime = 0; @@ -1022,7 +1022,7 @@ void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentF void TimeStats::enable() { if (mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); mEnabled.store(true); @@ -1034,7 +1034,7 @@ void TimeStats::enable() { void TimeStats::disable() { if (!mEnabled.load()) return; - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); flushPowerTimeLocked(); @@ -1051,7 +1051,7 @@ void TimeStats::clearAll() { } void TimeStats::clearGlobalLocked() { - ATRACE_CALL(); + SFTRACE_CALL(); mTimeStats.statsStartLegacy = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0); mTimeStats.statsEndLegacy = 0; @@ -1078,7 +1078,7 @@ void TimeStats::clearGlobalLocked() { } void TimeStats::clearLayersLocked() { - ATRACE_CALL(); + SFTRACE_CALL(); mTimeStatsTracker.clear(); @@ -1093,7 +1093,7 @@ bool TimeStats::isEnabled() { } void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::string& result) { - ATRACE_CALL(); + SFTRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); if (mTimeStats.statsStartLegacy == 0) { diff --git a/services/surfaceflinger/TracedOrdinal.h b/services/surfaceflinger/TracedOrdinal.h index 1adc3a531d..eba1ecf760 100644 --- a/services/surfaceflinger/TracedOrdinal.h +++ b/services/surfaceflinger/TracedOrdinal.h @@ -21,8 +21,8 @@ #include <functional> #include <string> +#include <common/trace.h> #include <cutils/compiler.h> -#include <utils/Trace.h> namespace android { @@ -88,13 +88,13 @@ private: } if (!signbit(mData)) { - ATRACE_INT64(mName.c_str(), to_int64(mData)); + SFTRACE_INT64(mName.c_str(), to_int64(mData)); if (mHasGoneNegative) { - ATRACE_INT64(mNameNegative.c_str(), 0); + SFTRACE_INT64(mNameNegative.c_str(), 0); } } else { - ATRACE_INT64(mNameNegative.c_str(), -to_int64(mData)); - ATRACE_INT64(mName.c_str(), 0); + SFTRACE_INT64(mNameNegative.c_str(), -to_int64(mData)); + SFTRACE_INT64(mName.c_str(), 0); } } diff --git a/services/surfaceflinger/Tracing/LayerTracing.cpp b/services/surfaceflinger/Tracing/LayerTracing.cpp index 41bcdf05c3..d40b888504 100644 --- a/services/surfaceflinger/Tracing/LayerTracing.cpp +++ b/services/surfaceflinger/Tracing/LayerTracing.cpp @@ -24,10 +24,10 @@ #include "Tracing/tools/LayerTraceGenerator.h" #include "TransactionTracing.h" +#include <common/trace.h> #include <log/log.h> #include <perfetto/tracing.h> #include <utils/Timers.h> -#include <utils/Trace.h> namespace android { @@ -134,7 +134,7 @@ void LayerTracing::onStop(Mode mode) { void LayerTracing::addProtoSnapshotToOstream(perfetto::protos::LayersSnapshotProto&& snapshot, Mode mode) { - ATRACE_CALL(); + SFTRACE_CALL(); if (mOutStream) { writeSnapshotToStream(std::move(snapshot)); } else { diff --git a/services/surfaceflinger/Tracing/TransactionRingBuffer.h b/services/surfaceflinger/Tracing/TransactionRingBuffer.h index 7d1d3fd7f2..2b66391853 100644 --- a/services/surfaceflinger/Tracing/TransactionRingBuffer.h +++ b/services/surfaceflinger/Tracing/TransactionRingBuffer.h @@ -19,13 +19,12 @@ #include <android-base/file.h> #include <android-base/stringprintf.h> +#include <common/trace.h> #include <log/log.h> #include <utils/Errors.h> #include <utils/Timers.h> -#include <utils/Trace.h> #include <chrono> #include <fstream> -#include <queue> namespace android { @@ -57,7 +56,7 @@ public: } status_t appendToStream(FileProto& fileProto, std::ofstream& out) { - ATRACE_CALL(); + SFTRACE_CALL(); writeToProto(fileProto); std::string output; if (!fileProto.SerializeToString(&output)) { diff --git a/services/surfaceflinger/TransactionCallbackInvoker.cpp b/services/surfaceflinger/TransactionCallbackInvoker.cpp index 37543ba171..881bf35b58 100644 --- a/services/surfaceflinger/TransactionCallbackInvoker.cpp +++ b/services/surfaceflinger/TransactionCallbackInvoker.cpp @@ -26,12 +26,10 @@ #include "TransactionCallbackInvoker.h" #include "BackgroundExecutor.h" #include "Utils/FenceUtils.h" -#include "utils/Trace.h" - -#include <cinttypes> #include <binder/IInterface.h> #include <common/FlagManager.h> +#include <common/trace.h> #include <utils/RefBase.h> namespace android { @@ -209,7 +207,7 @@ void TransactionCallbackInvoker::sendCallbacks(bool onCommitOnly) { BackgroundExecutor::getInstance().sendCallbacks( {[listenerStatsToSend = std::move(listenerStatsToSend)]() { - ATRACE_NAME("TransactionCallbackInvoker::sendCallbacks"); + SFTRACE_NAME("TransactionCallbackInvoker::sendCallbacks"); for (auto& stats : listenerStatsToSend) { interface_cast<ITransactionCompletedListener>(stats.listener) ->onTransactionCompleted(stats); diff --git a/services/surfaceflinger/WindowInfosListenerInvoker.cpp b/services/surfaceflinger/WindowInfosListenerInvoker.cpp index effbfdb896..895e0543e1 100644 --- a/services/surfaceflinger/WindowInfosListenerInvoker.cpp +++ b/services/surfaceflinger/WindowInfosListenerInvoker.cpp @@ -17,8 +17,8 @@ #include <android/gui/BnWindowInfosPublisher.h> #include <android/gui/IWindowInfosPublisher.h> #include <android/gui/WindowInfosListenerInfo.h> +#include <common/trace.h> #include <gui/ISurfaceComposer.h> -#include <gui/TraceUtils.h> #include <gui/WindowInfosUpdate.h> #include <scheduler/Time.h> @@ -42,7 +42,7 @@ void WindowInfosListenerInvoker::addWindowInfosListener(sp<IWindowInfosListener> BackgroundExecutor::getInstance().sendCallbacks( {[this, listener = std::move(listener), listenerId]() { - ATRACE_NAME("WindowInfosListenerInvoker::addWindowInfosListener"); + SFTRACE_NAME("WindowInfosListenerInvoker::addWindowInfosListener"); sp<IBinder> asBinder = IInterface::asBinder(listener); asBinder->linkToDeath(sp<DeathRecipient>::fromExisting(this)); mWindowInfosListeners.try_emplace(asBinder, @@ -53,7 +53,7 @@ void WindowInfosListenerInvoker::addWindowInfosListener(sp<IWindowInfosListener> void WindowInfosListenerInvoker::removeWindowInfosListener( const sp<IWindowInfosListener>& listener) { BackgroundExecutor::getInstance().sendCallbacks({[this, listener]() { - ATRACE_NAME("WindowInfosListenerInvoker::removeWindowInfosListener"); + SFTRACE_NAME("WindowInfosListenerInvoker::removeWindowInfosListener"); sp<IBinder> asBinder = IInterface::asBinder(listener); asBinder->unlinkToDeath(sp<DeathRecipient>::fromExisting(this)); eraseListenerAndAckMessages(asBinder); @@ -62,7 +62,7 @@ void WindowInfosListenerInvoker::removeWindowInfosListener( void WindowInfosListenerInvoker::binderDied(const wp<IBinder>& who) { BackgroundExecutor::getInstance().sendCallbacks({[this, who]() { - ATRACE_NAME("WindowInfosListenerInvoker::binderDied"); + SFTRACE_NAME("WindowInfosListenerInvoker::binderDied"); eraseListenerAndAckMessages(who); }}); } @@ -146,7 +146,7 @@ void WindowInfosListenerInvoker::windowInfosChanged( WindowInfosListenerInvoker::DebugInfo WindowInfosListenerInvoker::getDebugInfo() { DebugInfo result; BackgroundExecutor::getInstance().sendCallbacks({[&, this]() { - ATRACE_NAME("WindowInfosListenerInvoker::getDebugInfo"); + SFTRACE_NAME("WindowInfosListenerInvoker::getDebugInfo"); updateMaxSendDelay(); result = mDebugInfo; result.pendingMessageCount = mUnackedState.size(); @@ -169,7 +169,7 @@ void WindowInfosListenerInvoker::updateMaxSendDelay() { binder::Status WindowInfosListenerInvoker::ackWindowInfosReceived(int64_t vsyncId, int64_t listenerId) { BackgroundExecutor::getInstance().sendCallbacks({[this, vsyncId, listenerId]() { - ATRACE_NAME("WindowInfosListenerInvoker::ackWindowInfosReceived"); + SFTRACE_NAME("WindowInfosListenerInvoker::ackWindowInfosReceived"); auto it = mUnackedState.find(vsyncId); if (it == mUnackedState.end()) { return; diff --git a/services/surfaceflinger/common/include/common/trace.h b/services/surfaceflinger/common/include/common/trace.h new file mode 100644 index 0000000000..c13cdde90d --- /dev/null +++ b/services/surfaceflinger/common/include/common/trace.h @@ -0,0 +1,104 @@ + +/* + * Copyright 2024 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. + */ + +#pragma once + +#include <cutils/trace.h> +#include <stdint.h> + +#define SFTRACE_ENABLED() ATRACE_ENABLED() +#define SFTRACE_BEGIN(name) ATRACE_BEGIN(name) +#define SFTRACE_END() ATRACE_END() +#define SFTRACE_ASYNC_BEGIN(name, cookie) ATRACE_ASYNC_BEGIN(name, cookie) +#define SFTRACE_ASYNC_END(name, cookie) ATRACE_ASYNC_END(name, cookie) +#define SFTRACE_ASYNC_FOR_TRACK_BEGIN(track_name, name, cookie) \ + ATRACE_ASYNC_FOR_TRACK_BEGIN(track_name, name, cookie) +#define SFTRACE_ASYNC_FOR_TRACK_END(track_name, cookie) \ + ATRACE_ASYNC_FOR_TRACK_END(track_name, cookie) +#define SFTRACE_INSTANT(name) ATRACE_INSTANT(name) +#define SFTRACE_INSTANT_FOR_TRACK(trackName, name) ATRACE_INSTANT_FOR_TRACK(trackName, name) +#define SFTRACE_INT(name, value) ATRACE_INT(name, value) +#define SFTRACE_INT64(name, value) ATRACE_INT64(name, value) + +// SFTRACE_NAME traces from its location until the end of its enclosing scope. +#define _PASTE(x, y) x##y +#define PASTE(x, y) _PASTE(x, y) +#define SFTRACE_NAME(name) ::android::ScopedTrace PASTE(___tracer, __LINE__)(ATRACE_TAG, name) + +// SFTRACE_CALL is an ATRACE_NAME that uses the current function name. +#define SFTRACE_CALL() SFTRACE_NAME(__FUNCTION__) + +#define SFTRACE_FORMAT(fmt, ...) \ + TraceUtils::TraceEnder traceEnder = \ + (CC_UNLIKELY(ATRACE_ENABLED()) && \ + (TraceUtils::atraceFormatBegin(fmt, ##__VA_ARGS__), true), \ + TraceUtils::TraceEnder()) + +#define SFTRACE_FORMAT_INSTANT(fmt, ...) \ + (CC_UNLIKELY(ATRACE_ENABLED()) && (TraceUtils::instantFormat(fmt, ##__VA_ARGS__), true)) + +#define ALOGE_AND_TRACE(fmt, ...) \ + do { \ + ALOGE(fmt, ##__VA_ARGS__); \ + SFTRACE_FORMAT_INSTANT(fmt, ##__VA_ARGS__); \ + } while (false) + +namespace android { + +class TraceUtils { +public: + class TraceEnder { + public: + ~TraceEnder() { ATRACE_END(); } + }; + + static void atraceFormatBegin(const char* fmt, ...) { + const int BUFFER_SIZE = 256; + va_list ap; + char buf[BUFFER_SIZE]; + + va_start(ap, fmt); + vsnprintf(buf, BUFFER_SIZE, fmt, ap); + va_end(ap); + + SFTRACE_BEGIN(buf); + } + + static void instantFormat(const char* fmt, ...) { + const int BUFFER_SIZE = 256; + va_list ap; + char buf[BUFFER_SIZE]; + + va_start(ap, fmt); + vsnprintf(buf, BUFFER_SIZE, fmt, ap); + va_end(ap); + + SFTRACE_INSTANT(buf); + } +}; + +class ScopedTrace { +public: + inline ScopedTrace(uint64_t tag, const char* name) : mTag(tag) { atrace_begin(mTag, name); } + + inline ~ScopedTrace() { atrace_end(mTag); } + +private: + uint64_t mTag; +}; + +} // namespace android |