Add perfetto logs to track time spent on part of flicker
Previously we used logcat, but perfetto makes it easier to visualize this data
Bug: 243646243
Test: atest FlickerTests and check the generated perfetto file
Change-Id: I3c79e4e0a80200232bc3eee9b9bf0668f1c16165
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/FlickerTest.kt b/libraries/flicker/src/com/android/server/wm/flicker/FlickerTest.kt
index 91dd7e9..9a60069 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/FlickerTest.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/FlickerTest.kt
@@ -30,6 +30,7 @@
import com.android.server.wm.flicker.traces.windowmanager.WindowManagerStateSubject
import com.android.server.wm.flicker.traces.windowmanager.WindowManagerTraceSubject
import com.android.server.wm.traces.common.IComponentMatcher
+import com.android.server.wm.traces.parser.withPerfettoTrace
/** Specification of a flicker test for JUnit ParameterizedRunner class */
data class FlickerTest(
@@ -60,9 +61,11 @@
* @param assertion Assertion predicate
*/
fun assertWmStart(assertion: WindowManagerStateSubject.() -> Unit) {
- val assertionData =
- wmAssertionFactory.createStartStateAssertion(assertion as FlickerSubject.() -> Unit)
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertWmStart") {
+ val assertionData =
+ wmAssertionFactory.createStartStateAssertion(assertion as FlickerSubject.() -> Unit)
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -71,10 +74,14 @@
* @param assertion Assertion predicate
*/
fun assertWmEnd(assertion: WindowManagerStateSubject.() -> Unit) {
- val wrappedAssertion: (WindowManagerStateSubject) -> Unit = { assertion(it) }
- val assertionData =
- wmAssertionFactory.createEndStateAssertion(wrappedAssertion as (FlickerSubject) -> Unit)
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertWmEnd") {
+ val wrappedAssertion: (WindowManagerStateSubject) -> Unit = { assertion(it) }
+ val assertionData =
+ wmAssertionFactory.createEndStateAssertion(
+ wrappedAssertion as (FlickerSubject) -> Unit
+ )
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -83,11 +90,13 @@
* @param assertion Assertion predicate
*/
fun assertWm(assertion: WindowManagerTraceSubject.() -> Unit) {
- val assertionData =
- wmAssertionFactory.createTraceAssertion(
- assertion as (FlickerTraceSubject<FlickerSubject>) -> Unit
- )
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertWm") {
+ val assertionData =
+ wmAssertionFactory.createTraceAssertion(
+ assertion as (FlickerTraceSubject<FlickerSubject>) -> Unit
+ )
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -96,9 +105,11 @@
* @param assertion Assertion predicate
*/
fun assertWmTag(tag: String, assertion: WindowManagerStateSubject.() -> Unit) {
- val assertionData =
- wmAssertionFactory.createTagAssertion(tag, assertion as FlickerSubject.() -> Unit)
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertWmTag") {
+ val assertionData =
+ wmAssertionFactory.createTagAssertion(tag, assertion as FlickerSubject.() -> Unit)
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -111,8 +122,10 @@
componentMatcher: IComponentMatcher,
assertion: RegionTraceSubject.() -> Unit
) {
- val assertionData = buildWmVisibleRegionAssertion(componentMatcher, assertion)
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertWmVisibleRegion") {
+ val assertionData = buildWmVisibleRegionAssertion(componentMatcher, assertion)
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -121,9 +134,13 @@
* @param assertion Assertion predicate
*/
fun assertLayersStart(assertion: LayerTraceEntrySubject.() -> Unit) {
- val assertionData =
- layersAssertionFactory.createStartStateAssertion(assertion as FlickerSubject.() -> Unit)
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertLayersStart") {
+ val assertionData =
+ layersAssertionFactory.createStartStateAssertion(
+ assertion as FlickerSubject.() -> Unit
+ )
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -132,9 +149,13 @@
* @param assertion Assertion predicate
*/
fun assertLayersEnd(assertion: LayerTraceEntrySubject.() -> Unit) {
- val assertionData =
- layersAssertionFactory.createEndStateAssertion(assertion as FlickerSubject.() -> Unit)
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertLayersEnd") {
+ val assertionData =
+ layersAssertionFactory.createEndStateAssertion(
+ assertion as FlickerSubject.() -> Unit
+ )
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -143,11 +164,13 @@
* @param assertion Assertion predicate
*/
fun assertLayers(assertion: LayersTraceSubject.() -> Unit) {
- val assertionData =
- layersAssertionFactory.createTraceAssertion(
- assertion as (FlickerTraceSubject<FlickerSubject>) -> Unit
- )
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertLayers") {
+ val assertionData =
+ layersAssertionFactory.createTraceAssertion(
+ assertion as (FlickerTraceSubject<FlickerSubject>) -> Unit
+ )
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -156,9 +179,14 @@
* @param assertion Assertion predicate
*/
fun assertLayersTag(tag: String, assertion: LayerTraceEntrySubject.() -> Unit) {
- val assertionData =
- layersAssertionFactory.createTagAssertion(tag, assertion as FlickerSubject.() -> Unit)
- return doRunAssertion(assertionData)
+ withPerfettoTrace("assertLayersTag") {
+ val assertionData =
+ layersAssertionFactory.createTagAssertion(
+ tag,
+ assertion as FlickerSubject.() -> Unit
+ )
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -177,13 +205,15 @@
useCompositionEngineRegionOnly: Boolean = true,
assertion: RegionTraceSubject.() -> Unit
) {
- val assertionData =
- buildLayersVisibleRegionAssertion(
- componentMatcher,
- useCompositionEngineRegionOnly,
- assertion
- )
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertLayersVisibleRegion") {
+ val assertionData =
+ buildLayersVisibleRegionAssertion(
+ componentMatcher,
+ useCompositionEngineRegionOnly,
+ assertion
+ )
+ doRunAssertion(assertionData)
+ }
}
/**
@@ -192,12 +222,14 @@
* @param assertion Assertion predicate
*/
fun assertEventLog(assertion: EventLogSubject.() -> Unit) {
- val assertionData =
- eventLogAssertionFactory.createTagAssertion(
- AssertionTag.ALL,
- assertion as FlickerSubject.() -> Unit
- )
- doRunAssertion(assertionData)
+ withPerfettoTrace("assertEventLog") {
+ val assertionData =
+ eventLogAssertionFactory.createTagAssertion(
+ AssertionTag.ALL,
+ assertion as FlickerSubject.() -> Unit
+ )
+ doRunAssertion(assertionData)
+ }
}
private fun doRunAssertion(assertion: AssertionData) {
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/helpers/StandardAppHelper.kt b/libraries/flicker/src/com/android/server/wm/flicker/helpers/StandardAppHelper.kt
index 084ecc0..7913f96 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/helpers/StandardAppHelper.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/helpers/StandardAppHelper.kt
@@ -34,6 +34,7 @@
import com.android.server.wm.traces.common.WindowManagerConditionsFactory
import com.android.server.wm.traces.common.windowmanager.WindowManagerState
import com.android.server.wm.traces.parser.windowmanager.WindowManagerStateHelper
+import com.android.server.wm.traces.parser.withPerfettoTrace
/**
* Class to take advantage of {@code IAppHelper} interface so the same test can be run against first
@@ -102,14 +103,18 @@
/** {@inheritDoc} */
override fun exit() {
- // Ensure all testing components end up being closed.
- activityManager?.forceStopPackage(packageName)
+ withPerfettoTrace("exit") {
+ // Ensure all testing components end up being closed.
+ activityManager?.forceStopPackage(packageName)
+ }
}
/** Exits the activity and wait for activity destroyed */
fun exit(wmHelper: WindowManagerStateHelper) {
- exit()
- waitForActivityDestroyed(wmHelper)
+ withPerfettoTrace("${this::class.simpleName}#exitAndWait") {
+ exit()
+ waitForActivityDestroyed(wmHelper)
+ }
}
/** Waits the activity until state change to {link WindowManagerState.STATE_DESTROYED} */
@@ -134,10 +139,12 @@
action: String? = null,
stringExtras: Map<String, String> = mapOf()
) {
- val intent = openAppIntent
- intent.action = action
- stringExtras.forEach { intent.putExtra(it.key, it.value) }
- context.startActivity(intent)
+ withPerfettoTrace("${this::class.simpleName}#launchAppViaIntent") {
+ val intent = openAppIntent
+ intent.action = action
+ stringExtras.forEach { intent.putExtra(it.key, it.value) }
+ context.startActivity(intent)
+ }
}
/**
@@ -188,31 +195,40 @@
waitConditions: Array<Condition<DeviceStateDump>> = emptyArray()
) {
launchAppViaIntent(action, stringExtras)
+ doWaitShown(wmHelper, expectedWindowName, waitConditions)
+ }
- val expectedWindow =
- if (expectedWindowName.isNotEmpty()) {
- ComponentNameMatcher("", expectedWindowName)
- } else {
- componentMatcher
+ private fun doWaitShown(
+ wmHelper: WindowManagerStateHelper,
+ expectedWindowName: String = "",
+ waitConditions: Array<Condition<DeviceStateDump>> = emptyArray()
+ ) {
+ withPerfettoTrace("${this::class.simpleName}#doWaitShown") {
+ val expectedWindow =
+ if (expectedWindowName.isNotEmpty()) {
+ ComponentNameMatcher("", expectedWindowName)
+ } else {
+ componentMatcher
+ }
+ val builder =
+ wmHelper
+ .StateSyncBuilder()
+ .add(WindowManagerConditionsFactory.isWMStateComplete())
+ .withAppTransitionIdle()
+ .withWindowSurfaceAppeared(expectedWindow)
+
+ waitConditions.forEach { builder.add(it) }
+ builder.waitForAndVerify()
+
+ // During seamless rotation the app window is shown
+ val currWmState = wmHelper.currentState.wmState
+ if (currWmState.visibleWindows.none { it.isFullscreen }) {
+ wmHelper
+ .StateSyncBuilder()
+ .withNavOrTaskBarVisible()
+ .withStatusBarVisible()
+ .waitForAndVerify()
}
- val builder =
- wmHelper
- .StateSyncBuilder()
- .add(WindowManagerConditionsFactory.isWMStateComplete())
- .withAppTransitionIdle()
- .withWindowSurfaceAppeared(expectedWindow)
-
- waitConditions.forEach { builder.add(it) }
- builder.waitForAndVerify()
-
- // During seamless rotation the app window is shown
- val currWmState = wmHelper.currentState.wmState
- if (currWmState.visibleWindows.none { it.isFullscreen }) {
- wmHelper
- .StateSyncBuilder()
- .withNavOrTaskBarVisible()
- .withStatusBarVisible()
- .waitForAndVerify()
}
}
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/io/ResultWriter.kt b/libraries/flicker/src/com/android/server/wm/flicker/io/ResultWriter.kt
index 2901e66..e58b699 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/io/ResultWriter.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/io/ResultWriter.kt
@@ -23,6 +23,7 @@
import com.android.server.wm.flicker.now
import com.android.server.wm.traces.common.IScenario
import com.android.server.wm.traces.common.Timestamp
+import com.android.server.wm.traces.parser.withPerfettoTrace
import java.io.BufferedInputStream
import java.io.BufferedOutputStream
import java.io.File
@@ -106,31 +107,32 @@
/** @return writes the result artifact to disk and returns it */
open fun write(): ResultData {
- val outputDir = outputDir
- requireNotNull(outputDir) { "Output dir not configured" }
- require(!scenario.isEmpty) { "Scenario shouldn't be empty" }
+ return withPerfettoTrace("write") {
+ val outputDir = outputDir
+ requireNotNull(outputDir) { "Output dir not configured" }
+ require(!scenario.isEmpty) { "Scenario shouldn't be empty" }
+ // Ensure output directory exists
+ outputDir.toFile().mkdirs()
- // Ensure output directory exists
- outputDir.toFile().mkdirs()
-
- if (runStatus == RunStatus.UNDEFINED) {
- Log.w(FLICKER_IO_TAG, "Writing result with $runStatus run status")
- }
-
- val newFileName = "${runStatus.prefix}_$scenario.zip"
- val dstFile = outputDir.resolve(newFileName)
- Log.d(FLICKER_IO_TAG, "Writing artifact file $dstFile")
- createZipFile(dstFile.toFile()).use { zipOutputStream ->
- files.forEach { (descriptor, file) ->
- addFile(zipOutputStream, file, nameInArchive = descriptor.fileNameInArtifact)
+ if (runStatus == RunStatus.UNDEFINED) {
+ Log.w(FLICKER_IO_TAG, "Writing result with $runStatus run status")
}
- }
- return ResultData(
- dstFile,
- TransitionTimeRange(transitionStartTime, transitionEndTime),
- executionError,
- runStatus
- )
+ val newFileName = "${runStatus.prefix}_$scenario.zip"
+ val dstFile = outputDir.resolve(newFileName)
+ Log.d(FLICKER_IO_TAG, "Writing artifact file $dstFile")
+ createZipFile(dstFile.toFile()).use { zipOutputStream ->
+ files.forEach { (descriptor, file) ->
+ addFile(zipOutputStream, file, nameInArchive = descriptor.fileNameInArtifact)
+ }
+ }
+
+ ResultData(
+ dstFile,
+ TransitionTimeRange(transitionStartTime, transitionEndTime),
+ executionError,
+ runStatus
+ )
+ }
}
}
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/junit/FlickerServiceDecorator.kt b/libraries/flicker/src/com/android/server/wm/flicker/junit/FlickerServiceDecorator.kt
index 56b027c..595d068 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/junit/FlickerServiceDecorator.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/junit/FlickerServiceDecorator.kt
@@ -30,7 +30,7 @@
import com.android.server.wm.flicker.service.FlickerService
import com.android.server.wm.flicker.service.FlickerServiceResultsCollector
import com.android.server.wm.flicker.service.assertors.AssertionResult
-import kotlin.system.measureTimeMillis
+import com.android.server.wm.traces.parser.withPerfettoTrace
import org.junit.runner.Description
import org.junit.runners.model.FrameworkMethod
import org.junit.runners.model.Statement
@@ -76,8 +76,10 @@
override fun getTestMethods(test: Any): List<FrameworkMethod> {
val result = inner?.getTestMethods(test)?.toMutableList() ?: mutableListOf()
if (shouldComputeTestMethods()) {
- measureTimeMillis { result.addAll(computeFlickerServiceTests(test)) }
- .also { Log.d(FLICKER_TAG, "Took ${it}ms to compute ${result.size} flicker tests") }
+ withPerfettoTrace("getTestMethods") {
+ result.addAll(computeFlickerServiceTests(test))
+ Log.d(FLICKER_TAG, "Computed ${result.size} flicker tests")
+ }
}
return result
}
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/rules/ChangeDisplayOrientationRule.kt b/libraries/flicker/src/com/android/server/wm/flicker/rules/ChangeDisplayOrientationRule.kt
index 76ac260..46a1658 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/rules/ChangeDisplayOrientationRule.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/rules/ChangeDisplayOrientationRule.kt
@@ -26,6 +26,7 @@
import com.android.server.wm.flicker.FLICKER_TAG
import com.android.server.wm.traces.common.service.PlatformConsts
import com.android.server.wm.traces.parser.windowmanager.WindowManagerStateHelper
+import com.android.server.wm.traces.parser.withPerfettoTrace
import org.junit.rules.TestWatcher
import org.junit.runner.Description
@@ -49,18 +50,23 @@
private var initialOrientation = PlatformConsts.Rotation.ROTATION_0
override fun starting(description: Description?) {
- Log.v(
- FLICKER_TAG,
- "Changing display orientation to " +
- "$targetOrientation ${targetOrientation.description}"
- )
- val wm = instrumentation.context.getSystemService(Context.WINDOW_SERVICE) as WindowManager
- initialOrientation = PlatformConsts.Rotation.getByValue(wm.defaultDisplay.rotation)
- setRotation(targetOrientation, instrumentation, clearCacheAfterParsing)
+ withPerfettoTrace("ChangeDisplayOrientationRule:starting") {
+ Log.v(
+ FLICKER_TAG,
+ "Changing display orientation to " +
+ "$targetOrientation ${targetOrientation.description}"
+ )
+ val wm =
+ instrumentation.context.getSystemService(Context.WINDOW_SERVICE) as WindowManager
+ initialOrientation = PlatformConsts.Rotation.getByValue(wm.defaultDisplay.rotation)
+ setRotation(targetOrientation, instrumentation, clearCacheAfterParsing)
+ }
}
override fun finished(description: Description?) {
- setRotation(initialOrientation, instrumentation, clearCacheAfterParsing)
+ withPerfettoTrace("ChangeDisplayOrientationRule:finished") {
+ setRotation(initialOrientation, instrumentation, clearCacheAfterParsing)
+ }
}
companion object {
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/rules/LaunchAppRule.kt b/libraries/flicker/src/com/android/server/wm/flicker/rules/LaunchAppRule.kt
index 669fc8d..239e5f6 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/rules/LaunchAppRule.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/rules/LaunchAppRule.kt
@@ -23,6 +23,7 @@
import com.android.server.wm.flicker.helpers.StandardAppHelper
import com.android.server.wm.traces.common.ComponentNameMatcher
import com.android.server.wm.traces.parser.windowmanager.WindowManagerStateHelper
+import com.android.server.wm.traces.parser.withPerfettoTrace
import org.junit.rules.TestWatcher
import org.junit.runner.Description
@@ -62,8 +63,10 @@
)
override fun starting(description: Description?) {
- Log.v(FLICKER_TAG, "Launching app $appHelper")
- appHelper.launchViaIntent()
- appHelper.exit(wmHelper)
+ withPerfettoTrace("LaunchAppRule:finished") {
+ Log.v(FLICKER_TAG, "Launching app $appHelper")
+ appHelper.launchViaIntent()
+ appHelper.exit(wmHelper)
+ }
}
}
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/rules/RemoveAllTasksButHomeRule.kt b/libraries/flicker/src/com/android/server/wm/flicker/rules/RemoveAllTasksButHomeRule.kt
index 92192cb..d96b0a6 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/rules/RemoveAllTasksButHomeRule.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/rules/RemoveAllTasksButHomeRule.kt
@@ -20,14 +20,17 @@
import android.app.WindowConfiguration
import android.util.Log
import com.android.server.wm.flicker.FLICKER_TAG
+import com.android.server.wm.traces.parser.withPerfettoTrace
import org.junit.rules.TestWatcher
import org.junit.runner.Description
/** Test rule to ensure no tasks as running before executing the test */
class RemoveAllTasksButHomeRule() : TestWatcher() {
override fun starting(description: Description?) {
- Log.v(FLICKER_TAG, "Removing all tasks (except home)")
- removeAllTasksButHome()
+ withPerfettoTrace("RemoveAllTasksButHomeRule:finished") {
+ Log.v(FLICKER_TAG, "Removing all tasks (except home)")
+ removeAllTasksButHome()
+ }
}
companion object {
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/runner/SetupTeardownRule.kt b/libraries/flicker/src/com/android/server/wm/flicker/runner/SetupTeardownRule.kt
index b3ef438..8d0f5fd 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/runner/SetupTeardownRule.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/runner/SetupTeardownRule.kt
@@ -17,11 +17,11 @@
package com.android.server.wm.flicker.runner
import android.app.Instrumentation
-import android.util.Log
import com.android.server.wm.flicker.IFlickerTestData
import com.android.server.wm.flicker.io.ResultWriter
import com.android.server.wm.traces.common.IScenario
import com.android.server.wm.traces.parser.windowmanager.WindowManagerStateHelper
+import com.android.server.wm.traces.parser.withPerfettoTrace
import org.junit.rules.TestRule
import org.junit.runner.Description
import org.junit.runners.model.Statement
@@ -61,8 +61,8 @@
@Throws(TransitionSetupFailure::class)
private fun doRunTransitionSetup(description: Description?) {
- Log.d(FLICKER_RUNNER_TAG, "doRunTransitionSetup")
- Utils.executeAndNotifyRunner(scenario, "Running transition setup for $description") {
+ withPerfettoTrace("doRunTransitionSetup") {
+ Utils.notifyRunnerProgress(scenario, "Running transition setup for $description")
try {
setupCommands.forEach { it.invoke(flicker) }
Utils.doWaitForUiStabilize(wmHelper)
@@ -74,8 +74,8 @@
@Throws(TransitionTeardownFailure::class)
private fun doRunTransitionTeardown(description: Description?) {
- Log.d(FLICKER_RUNNER_TAG, "doRunTransitionTeardown")
- Utils.executeAndNotifyRunner(scenario, "Running transition teardown for $description") {
+ withPerfettoTrace("doRunTransitionTeardown") {
+ Utils.notifyRunnerProgress(scenario, "Running transition teardown for $description")
try {
teardownCommands.forEach { it.invoke(flicker) }
Utils.doWaitForUiStabilize(wmHelper)
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/runner/TraceMonitorRule.kt b/libraries/flicker/src/com/android/server/wm/flicker/runner/TraceMonitorRule.kt
index 6b313df..b778fce 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/runner/TraceMonitorRule.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/runner/TraceMonitorRule.kt
@@ -23,6 +23,7 @@
import com.android.server.wm.flicker.io.ResultWriter
import com.android.server.wm.traces.common.IScenario
import com.android.server.wm.traces.parser.windowmanager.WindowManagerStateHelper
+import com.android.server.wm.traces.parser.withPerfettoTrace
import org.junit.rules.TestRule
import org.junit.runner.Description
import org.junit.runners.model.Statement
@@ -57,8 +58,8 @@
}
private fun doStartMonitors(description: Description?) {
- Log.d(FLICKER_RUNNER_TAG, "doStartMonitors")
- Utils.executeAndNotifyRunner(scenario, "Starting traces for $description") {
+ withPerfettoTrace("doStartMonitors") {
+ Utils.notifyRunnerProgress(scenario, "Starting traces for $description")
traceMonitors.forEach {
try {
it.start()
@@ -70,8 +71,8 @@
}
private fun doStopMonitors(description: Description?) {
- Log.d(FLICKER_RUNNER_TAG, "doStopMonitors")
- Utils.executeAndNotifyRunner(scenario, "Stopping traces for $description") {
+ withPerfettoTrace("doStopMonitors") {
+ Utils.notifyRunnerProgress(scenario, "Stopping traces for $description")
val errors =
traceMonitors.map {
runCatching {
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/runner/TransitionExecutionRule.kt b/libraries/flicker/src/com/android/server/wm/flicker/runner/TransitionExecutionRule.kt
index 7c745d3..f25894e 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/runner/TransitionExecutionRule.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/runner/TransitionExecutionRule.kt
@@ -24,6 +24,7 @@
import com.android.server.wm.traces.common.IScenario
import com.android.server.wm.traces.parser.getCurrentState
import com.android.server.wm.traces.parser.windowmanager.WindowManagerStateHelper
+import com.android.server.wm.traces.parser.withPerfettoTrace
import java.nio.file.Files
import org.junit.rules.TestRule
import org.junit.runner.Description
@@ -52,27 +53,29 @@
override fun apply(base: Statement?, description: Description?): Statement {
return object : Statement() {
override fun evaluate() {
- try {
- Utils.executeAndNotifyRunner(scenario, "Running transition $description") {
+ withPerfettoTrace("transition") {
+ try {
+ Utils.notifyRunnerProgress(scenario, "Running transition $description")
doRunBeforeTransition()
commands.forEach { it.invoke(flicker) }
base?.evaluate()
+ } catch (e: Throwable) {
+ throw if (e is AssertionError) {
+ e
+ } else {
+ TransitionExecutionFailure(e)
+ }
+ } finally {
+ doRunAfterTransition()
}
- } catch (e: Throwable) {
- throw if (e is AssertionError) {
- e
- } else {
- TransitionExecutionFailure(e)
- }
- } finally {
- doRunAfterTransition()
}
}
}
}
private fun doRunBeforeTransition() {
- Utils.executeAndNotifyRunner(scenario, "Running doRunBeforeTransition") {
+ withPerfettoTrace("doRunBeforeTransition") {
+ Utils.notifyRunnerProgress(scenario, "Running doRunBeforeTransition")
Log.d(FLICKER_RUNNER_TAG, "doRunBeforeTransition")
resultWriter.setTransitionStartTime()
flicker.setCreateTagListener { doCreateTag(it) }
@@ -81,7 +84,8 @@
}
private fun doRunAfterTransition() {
- Utils.executeAndNotifyRunner(scenario, "Running doRunAfterTransition") {
+ withPerfettoTrace("doRunAfterTransition") {
+ Utils.notifyRunnerProgress(scenario, "Running doRunAfterTransition")
Log.d(FLICKER_RUNNER_TAG, "doRunAfterTransition")
Utils.doWaitForUiStabilize(wmHelper)
resultWriter.setTransitionEndTime()
@@ -100,7 +104,8 @@
}
private fun doCreateTag(tag: String) {
- Utils.executeAndNotifyRunner(scenario, "Creating tag $tag") {
+ withPerfettoTrace("doRunAfterTransition") {
+ Utils.notifyRunnerProgress(scenario, "Creating tag $tag")
doValidateTag(tag)
tags.add(tag)
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/runner/TransitionRunner.kt b/libraries/flicker/src/com/android/server/wm/flicker/runner/TransitionRunner.kt
index 13fa708..3fcd047 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/runner/TransitionRunner.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/runner/TransitionRunner.kt
@@ -29,6 +29,7 @@
import com.android.server.wm.flicker.rules.LaunchAppRule
import com.android.server.wm.flicker.rules.RemoveAllTasksButHomeRule
import com.android.server.wm.traces.common.IScenario
+import com.android.server.wm.traces.parser.withPerfettoTrace
import org.junit.rules.RuleChain
import org.junit.runner.Description
@@ -43,16 +44,18 @@
) {
/** Executes [flicker] transition and returns the result */
fun execute(flicker: IFlickerTestData, description: Description?): ResultData {
- resultWriter.forScenario(scenario).withOutputDir(flicker.outputDir)
+ return withPerfettoTrace("TransitionRunner:execute") {
+ resultWriter.forScenario(scenario).withOutputDir(flicker.outputDir)
- val ruleChain = buildTestRuleChain(flicker)
- try {
- ruleChain.apply(/* statement */ null, description).evaluate()
- resultWriter.setRunComplete()
- } catch (e: Throwable) {
- resultWriter.setRunFailed(e)
+ val ruleChain = buildTestRuleChain(flicker)
+ try {
+ ruleChain.apply(/* statement */ null, description).evaluate()
+ resultWriter.setRunComplete()
+ } catch (e: Throwable) {
+ resultWriter.setRunFailed(e)
+ }
+ resultWriter.write()
}
- return resultWriter.write()
}
/**
diff --git a/libraries/flicker/src/com/android/server/wm/flicker/runner/Utils.kt b/libraries/flicker/src/com/android/server/wm/flicker/runner/Utils.kt
index f0a9985..41b3ec9 100644
--- a/libraries/flicker/src/com/android/server/wm/flicker/runner/Utils.kt
+++ b/libraries/flicker/src/com/android/server/wm/flicker/runner/Utils.kt
@@ -24,7 +24,6 @@
import com.android.server.wm.traces.common.IScenario
import com.android.server.wm.traces.common.WindowManagerConditionsFactory
import com.android.server.wm.traces.parser.windowmanager.WindowManagerStateHelper
-import kotlin.system.measureTimeMillis
/** Helper class for flicker transition rules */
object Utils {
@@ -41,22 +40,11 @@
)
private val instrumentation: Instrumentation = InstrumentationRegistry.getInstrumentation()
- /** Execute [predicate] and log [logMessage] in logcat and notify the host side runner */
- internal fun executeAndNotifyRunner(
- scenario: IScenario,
- logMessage: String,
- predicate: () -> Unit
- ) {
- notifyRunnerProgress(scenario, logMessage)
- measureTimeMillis { predicate() }
- .also { notifyRunnerProgress(scenario, "\tDuration ${it}ms") }
- }
-
internal fun doWaitForUiStabilize(wmHelper: WindowManagerStateHelper) {
wmHelper.StateSyncBuilder().add(UI_STABLE_CONDITIONS).waitFor()
}
- private fun notifyRunnerProgress(scenario: IScenario, msg: String) {
+ internal fun notifyRunnerProgress(scenario: IScenario, msg: String) {
Log.d(FLICKER_RUNNER_TAG, "${scenario.key} - $msg")
val results = Bundle()
results.putString(Instrumentation.REPORT_KEY_STREAMRESULT, "$msg\n")
diff --git a/libraries/flicker/src/com/android/server/wm/traces/common/WaitCondition.kt b/libraries/flicker/src/com/android/server/wm/traces/common/WaitCondition.kt
index d7ef0bd..bd58870 100644
--- a/libraries/flicker/src/com/android/server/wm/traces/common/WaitCondition.kt
+++ b/libraries/flicker/src/com/android/server/wm/traces/common/WaitCondition.kt
@@ -50,31 +50,66 @@
@JsName("onLog") private val onLog: ((String, Boolean) -> Unit)?,
@JsName("onFailure") private val onFailure: ((T) -> Any)?,
@JsName("onRetry") private val onRetry: ((T) -> Any)?,
- @JsName("onSuccess") private val onSuccess: ((T) -> Any)?
+ @JsName("onSuccess") private val onSuccess: ((T) -> Any)?,
+ @JsName("onStart") private val onStart: ((String) -> Any)?,
+ @JsName("onEnd") private val onEnd: (() -> Any)?
) {
/** @return `false` if the condition does not satisfy within the time limit. */
@JsName("waitFor")
fun waitFor(): Boolean {
+ onStart?.invoke("waitFor")
+ try {
+ return doWaitFor()
+ } finally {
+ onEnd?.invoke()
+ }
+ }
+
+ private fun doWaitFor(): Boolean {
onLog?.invoke("***Waiting for $condition", /* isError */ false)
var currState: T? = null
+ var success = false
for (i in 0..retryLimit) {
- currState = supplier.invoke()
- if (condition.isSatisfied(currState)) {
- onLog?.invoke("***Waiting for $condition ... Success!", /* isError */ false)
- onSuccess?.invoke(currState)
- return true
- } else {
- val detailedMessage = condition.getMessage(currState)
- onLog?.invoke(
- "***Waiting for $detailedMessage... retry=${i + 1}",
- /* isError */ true
- )
- if (i < retryLimit) {
- onRetry?.invoke(currState)
- }
+ val result = doWaitForRetry(i)
+ success = result.first
+ currState = result.second
+ if (success) {
+ break
+ } else if (i < retryLimit) {
+ onRetry?.invoke(currState)
}
}
+ return if (success) {
+ true
+ } else {
+ doNotifyFailure(currState)
+ false
+ }
+ }
+
+ private fun doWaitForRetry(retryNr: Int): Pair<Boolean, T> {
+ onStart?.invoke("doWaitForRetry")
+ try {
+ val currState = supplier.invoke()
+ return if (condition.isSatisfied(currState)) {
+ onLog?.invoke("***Waiting for $condition ... Success!", /* isError */ false)
+ onSuccess?.invoke(currState)
+ Pair(true, currState)
+ } else {
+ val detailedMessage = condition.getMessage(currState)
+ onLog?.invoke(
+ "***Waiting for $detailedMessage... retry=${retryNr + 1}",
+ /* isError */ true
+ )
+ Pair(false, currState)
+ }
+ } finally {
+ onEnd?.invoke()
+ }
+ }
+
+ private fun doNotifyFailure(currState: T?) {
val detailedMessage =
if (currState != null) {
condition.getMessage(currState)
@@ -86,7 +121,6 @@
require(currState != null) { "Missing last result for failure notification" }
onFailure.invoke(currState)
}
- return false
}
class Builder<T>(
@@ -94,6 +128,8 @@
@JsName("retryLimit") private var retryLimit: Int
) {
@JsName("conditions") private val conditions = mutableListOf<Condition<T>>()
+ private var onStart: ((String) -> Any)? = null
+ private var onEnd: (() -> Any)? = null
private var onFailure: ((T) -> Any)? = null
private var onRetry: ((T) -> Any)? = null
private var onSuccess: ((T) -> Any)? = null
@@ -130,6 +166,14 @@
@JsName("onRetry")
fun onRetry(onRetry: ((T) -> Any)? = null): Builder<T> = apply { this.onRetry = onRetry }
+ @JsName("onStart")
+ fun onStart(onStart: ((String) -> Any)? = null): Builder<T> = apply {
+ this.onStart = onStart
+ }
+
+ @JsName("onEnd")
+ fun onEnd(onEnd: (() -> Any)? = null): Builder<T> = apply { this.onEnd = onEnd }
+
@JsName("onSuccess")
fun onSuccess(onRetry: ((T) -> Any)? = null): Builder<T> = apply {
this.onSuccess = onRetry
@@ -144,7 +188,9 @@
onLog,
onFailure,
onRetry,
- onSuccess
+ onSuccess,
+ onStart,
+ onEnd
)
}
diff --git a/libraries/flicker/src/com/android/server/wm/traces/parser/AbstractParser.kt b/libraries/flicker/src/com/android/server/wm/traces/parser/AbstractParser.kt
index 0f6c61f..f11cf6a 100644
--- a/libraries/flicker/src/com/android/server/wm/traces/parser/AbstractParser.kt
+++ b/libraries/flicker/src/com/android/server/wm/traces/parser/AbstractParser.kt
@@ -16,9 +16,7 @@
package com.android.server.wm.traces.parser
-import android.util.Log
import com.android.server.wm.traces.common.Cache
-import kotlin.system.measureTimeMillis
/** Base parser class */
abstract class AbstractParser<InputTypeTrace, OutputTypeTrace> {
@@ -44,26 +42,20 @@
* @param clearCache If the caching used while parsing the object should be cleared
*/
open fun parse(input: InputTypeTrace, clearCache: Boolean): OutputTypeTrace {
- return try {
- logTime("Parsing objects") { doParse(input) }
- } finally {
- if (clearCache) {
- Cache.clear()
+ return withPerfettoTrace("${this::class.simpleName}#parse") {
+ try {
+ doParse(input)
+ } finally {
+ if (clearCache) {
+ Cache.clear()
+ }
}
}
}
protected fun decodeByteArray(input: ByteArray): InputTypeTrace {
- return logTime("Decoding $traceName proto file") { doDecodeByteArray(input) }
- }
-
- protected fun <T> logTime(msg: String, predicate: () -> T): T {
- var data: T?
- measureTimeMillis { data = predicate() }.also { Log.v(LOG_TAG_TIME, "$msg: ${it}ms") }
- return data ?: error("Unable to process")
- }
-
- companion object {
- private const val LOG_TAG_TIME = "$LOG_TAG-Duration"
+ return withPerfettoTrace("${this::class.simpleName}#decodeByteArray") {
+ doDecodeByteArray(input)
+ }
}
}
diff --git a/libraries/flicker/src/com/android/server/wm/traces/parser/AbstractTraceParser.kt b/libraries/flicker/src/com/android/server/wm/traces/parser/AbstractTraceParser.kt
index 3e86793..841a627 100644
--- a/libraries/flicker/src/com/android/server/wm/traces/parser/AbstractTraceParser.kt
+++ b/libraries/flicker/src/com/android/server/wm/traces/parser/AbstractTraceParser.kt
@@ -80,8 +80,7 @@
if (!selectedInputTimestamps.contains(currTimestamp) || !shouldParseEntry(rawEntry)) {
continue
}
- val parsedEntry =
- logTime("Creating entry for time $currTimestamp") { doParseEntry(rawEntry) }
+ val parsedEntry = withPerfettoTrace("doParseEntry") { doParseEntry(rawEntry) }
parsedEntries.add(parsedEntry)
}
return createTrace(parsedEntries)
@@ -103,11 +102,13 @@
addInitialEntry: Boolean = true,
clearCache: Boolean = true
): OutputTypeTrace {
- return try {
- logTime("Parsing objects") { doParse(input, from, to, addInitialEntry) }
- } finally {
- if (clearCache) {
- Cache.clear()
+ return withPerfettoTrace("${this::class.simpleName}#parse") {
+ try {
+ doParse(input, from, to, addInitialEntry)
+ } finally {
+ if (clearCache) {
+ Cache.clear()
+ }
}
}
}
diff --git a/libraries/flicker/src/com/android/server/wm/traces/parser/DeviceDumpParser.kt b/libraries/flicker/src/com/android/server/wm/traces/parser/DeviceDumpParser.kt
index 07a63ca..eb8edee 100644
--- a/libraries/flicker/src/com/android/server/wm/traces/parser/DeviceDumpParser.kt
+++ b/libraries/flicker/src/com/android/server/wm/traces/parser/DeviceDumpParser.kt
@@ -51,24 +51,26 @@
layersTraceData: ByteArray,
clearCacheAfterParsing: Boolean
): NullableDeviceStateDump {
- return NullableDeviceStateDump(
- wmState =
- if (wmTraceData.isNotEmpty()) {
- WindowManagerDumpParser()
- .parse(wmTraceData, clearCache = clearCacheAfterParsing)
- .first()
- } else {
- null
- },
- layerState =
- if (layersTraceData.isNotEmpty()) {
- LayersTraceParser()
- .parse(layersTraceData, clearCache = clearCacheAfterParsing)
- .first()
- } else {
- null
- }
- )
+ return withPerfettoTrace("fromNullableDump") {
+ NullableDeviceStateDump(
+ wmState =
+ if (wmTraceData.isNotEmpty()) {
+ WindowManagerDumpParser()
+ .parse(wmTraceData, clearCache = clearCacheAfterParsing)
+ .first()
+ } else {
+ null
+ },
+ layerState =
+ if (layersTraceData.isNotEmpty()) {
+ LayersTraceParser()
+ .parse(layersTraceData, clearCache = clearCacheAfterParsing)
+ .first()
+ } else {
+ null
+ }
+ )
+ }
}
/** See [fromNullableDump] */
@@ -78,12 +80,14 @@
layersTraceData: ByteArray,
clearCacheAfterParsing: Boolean
): DeviceStateDump {
- val nullableDump =
- fromNullableDump(wmTraceData, layersTraceData, clearCacheAfterParsing)
- return DeviceStateDump(
- nullableDump.wmState ?: error("WMState dump missing"),
- nullableDump.layerState ?: error("Layer State dump missing")
- )
+ return withPerfettoTrace("fromDump") {
+ val nullableDump =
+ fromNullableDump(wmTraceData, layersTraceData, clearCacheAfterParsing)
+ DeviceStateDump(
+ nullableDump.wmState ?: error("WMState dump missing"),
+ nullableDump.layerState ?: error("Layer State dump missing")
+ )
+ }
}
/**
@@ -104,20 +108,22 @@
layersTraceData: ByteArray,
clearCache: Boolean
): DeviceTraceDump {
- return DeviceTraceDump(
- wmTrace =
- if (wmTraceData.isNotEmpty()) {
- WindowManagerTraceParser().parse(wmTraceData, clearCache = clearCache)
- } else {
- null
- },
- layersTrace =
- if (layersTraceData.isNotEmpty()) {
- LayersTraceParser().parse(layersTraceData, clearCache = clearCache)
- } else {
- null
- }
- )
+ return withPerfettoTrace("fromTrace") {
+ DeviceTraceDump(
+ wmTrace =
+ if (wmTraceData.isNotEmpty()) {
+ WindowManagerTraceParser().parse(wmTraceData, clearCache = clearCache)
+ } else {
+ null
+ },
+ layersTrace =
+ if (layersTraceData.isNotEmpty()) {
+ LayersTraceParser().parse(layersTraceData, clearCache = clearCache)
+ } else {
+ null
+ }
+ )
+ }
}
}
}
diff --git a/libraries/flicker/src/com/android/server/wm/traces/parser/Extensions.kt b/libraries/flicker/src/com/android/server/wm/traces/parser/Extensions.kt
index 30b4015..3e2fd99 100644
--- a/libraries/flicker/src/com/android/server/wm/traces/parser/Extensions.kt
+++ b/libraries/flicker/src/com/android/server/wm/traces/parser/Extensions.kt
@@ -21,6 +21,7 @@
import android.app.UiAutomation
import android.content.ComponentName
import android.os.ParcelFileDescriptor
+import android.os.Trace
import android.util.Log
import com.android.server.wm.traces.common.ComponentNameMatcher
import com.android.server.wm.traces.common.DeviceStateDump
@@ -120,6 +121,15 @@
)
}
+fun <T> withPerfettoTrace(logMsg: String, predicate: () -> T): T {
+ return try {
+ Trace.beginSection(logMsg)
+ predicate()
+ } finally {
+ Trace.endSection()
+ }
+}
+
/** Converts an Android [ComponentName] into a flicker [ComponentNameMatcher] */
fun ComponentName.toFlickerComponent(): ComponentNameMatcher =
ComponentNameMatcher(this.packageName, this.className)
diff --git a/libraries/flicker/src/com/android/server/wm/traces/parser/windowmanager/WindowManagerStateHelper.kt b/libraries/flicker/src/com/android/server/wm/traces/parser/windowmanager/WindowManagerStateHelper.kt
index f038bf6..d71c6e7 100644
--- a/libraries/flicker/src/com/android/server/wm/traces/parser/windowmanager/WindowManagerStateHelper.kt
+++ b/libraries/flicker/src/com/android/server/wm/traces/parser/windowmanager/WindowManagerStateHelper.kt
@@ -20,6 +20,7 @@
import android.app.Instrumentation
import android.app.WindowConfiguration
import android.os.SystemClock
+import android.os.Trace
import android.util.Log
import android.view.Display
import androidx.test.platform.app.InstrumentationRegistry
@@ -112,6 +113,8 @@
private fun createConditionBuilder(): WaitCondition.Builder<DeviceStateDump> =
WaitCondition.Builder(deviceDumpSupplier, numRetries)
+ .onStart { Trace.beginSection(it) }
+ .onEnd { Trace.endSection() }
.onSuccess { updateCurrState(it) }
.onFailure { updateCurrState(it) }
.onLog { msg, isError ->
