Android MacroBenchmark: FrameTimingMetric test is running only for 1 iteration

Question

I am trying to perform a scroll test on a recycler view using FrameTimingMetric for 5 iterations.

My AppStartup Test using StartupTimingMetric() is working fine and generating results for all 5 iterations.

For scroll test using FrameTimingMetric, it is performing first iteration and recyclerview scrolled, but after that test failed with error (java.lang.IllegalArgumentException: Failed requirement) app exits and didn't iterate for other remaining 4 iterations.

Macrobenchmark class.

@RunWith(AndroidJUnit4.class)
public class ExampleStartupBenchmark {

    @Rule
    public MacrobenchmarkRule mBenchmarkRule = new MacrobenchmarkRule();

    @Test
    public void startup() {
        mBenchmarkRule.measureRepeated(
                "my-app-package-name",
                Collections.singletonList(new StartupTimingMetric()),
                CompilationMode.DEFAULT,
                StartupMode.COLD,
                5,
                scope -> {
                    scope.startActivityAndWait();
                    return Unit.INSTANCE;
                });
    }

    @Test
    public void scroll() {
        mBenchmarkRule.measureRepeated(
                "my-app-package-name",
                Collections.singletonList(new FrameTimingMetric()),
                CompilationMode.DEFAULT,
                StartupMode.COLD,
                5,
                macrobenchmarkScope -> {
                   
                    Log.i("MacrobenchmarkRuleTAG", "justBeforeIntent");

                    Intent intent = new Intent("MarkMainActivity-intentlaunch-string");

                    macrobenchmarkScope.startActivityAndWait(intent);

                    // Wait until activity is shown.
                    Log.i("MacrobenchmarkRuleTAG", "justBeforeMarkMainActivityWait");
                    macrobenchmarkScope.getDevice().wait(
                            Until.hasObject(By.clazz("MarkMainActivity")),
                            10_000L
                    );

                    Log.i("MacrobenchmarkRuleTAG", "justAfterMarkMainActivityWait");
                    return Unit.INSTANCE;
                }, scope ->{

                    UiDevice device = scope.getDevice();

                    UiObject2 recycler = device.findObject(By.res(scope.getPackageName(), "mark_recyclerview"));
                    SearchCondition<Boolean> searchCond2  = Until.hasObject(By.res("mark_adapter_single_view"));
                    recycler.wait(searchCond2, 10_000L); // wait until recyclerview object loads a singleitemview

                    Log.i("MacrobenchmarkRuleTAG", recycler.getClassName());
           
                    recycler.setGestureMargin(device.getDisplayWidth() / 5);

                    Log.i("MacrobenchmarkRuleTAG", "justbeforefling");
                    recycler.scroll(Direction.DOWN, 55);
             
                    return Unit.INSTANCE;
                });
    }
}

My AppStartup test is working fine for 5 iterations and generating results. So my initial benchmark module setup should be fine.

For scroll test, I need to wait till recyclerview loading, as data coming from API calling on Oncreate Method of MarkMainActivity and after that recyclerview is initiating and loading. So I tried to put some wait condition for recycler view ( "mark_recyclerview" is xml Id of recyclerview ) and its singleItem Layout("mark_adapter_single_view" is xml Id for singleItemView).

For this code, my markactivity is opening and recyclerview is loading, then after some seconds ,scroll was performed, and after that my tests stopped with error (java.lang.IllegalArgumentException: Failed requirement) and app closed and didn't perform remaining 4 iterations.

Also, to check with logs, logs were written till last one i.e : Log.i("MacrobenchmarkRuleTAG", "justbeforefling"). And also scroll was performed. So test should be executed through till last line.

if anyone has any inputs or suggestions, please help me on how to perform remaining four iterations for this usecase and generate outputs.

Thanks.

Error code :

java.lang.IllegalArgumentException: Failed requirement.
at androidx.benchmark.macro.perfetto.FrameTimingQuery.getFrameSubMetrics(FrameTimingQuery.kt:182)
at androidx.benchmark.macro.FrameTimingMetric.getMetrics$benchmark_macro_release(Metric.kt:231)
at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmark(Macrobenchmark.kt:209)
at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmarkWithStartupMode(Macrobenchmark.kt:301)
at androidx.benchmark.macro.junit4.MacrobenchmarkRule.measureRepeated(MacrobenchmarkRule.kt:106)
at com.tc.macrobenchmark.ExampleStartupBenchmark.scroll(ExampleStartupBenchmark.java:51)

I am following these guidelines: macrobenchmark

macrobenchmarkcodelab

Answer 1

First you need know ,how the FrameTimingMetric works.

FrameTimingMetric works by perfetto trace. it querys four types of slices from perfetto trace file.

• Expected Slice
• Actual Slice
• Choreographer#doFrame in UiThread
• drawFrames in RenderThread

relate them by FrameId in the slices， and encapsulate related four types slices in FrameData class.

so If there miss any type of slices, or no FrameId in slices， The FrameTimingMetric can't work properly.

Second, FrameTimingQuery.kt is a helper class for FrameTimingMetirc to query frame informations from perfetto trace. Exception is thrown by this class

the "java.lang.IllegalArgumentException: Failed requirement." is a exception that require statement in kotlin language throws.(Macrobenchmark is written in kotlin).

there're three require statemets in FrameTimingQuery.kt class.

require(actualSlices.isEmpty() == newSlicesShouldBeEmpty)
require(expectedSlices.isEmpty() == newSlicesShouldBeEmpty)
require(slices.none { it.frameId == null })

there must be one of them which is not satisfied.

Last, you need debug your testcase by debugger.

adb shell "am instrument -w -e debug true [your instrumentation package name]"

-e debug true makes your instrumentation test waiting for debugger

then you use debugger in android studio to attach the instrumentation process

Cause Where does the FameId in the slice come from?

FrameId comes from the last sub string by dividing slice name with space character.

because the last substring of choreographer#doFrame is this, that cause frameId null. So that's why your testcases don't work.

you need give your feedback at this website( I have done that) or write your own metric.

--TO THE LAST-- I have rewritten the FrameTimingMetric， you can new a class named FrameMetric, copy codes to it, use it in repeat function.

import androidx.benchmark.macro.ExperimentalMetricApi
import androidx.benchmark.macro.TraceMetric
import androidx.benchmark.perfetto.ExperimentalPerfettoTraceProcessorApi
import androidx.benchmark.perfetto.PerfettoTraceProcessor
import androidx.benchmark.perfetto.Row

// Slice类型
enum class FrameSliceType(val value:String) {
    Expected("Expected Timeline"),
    Actual("Actual Timeline"),
    UiThread("UIThread"),
    RenderThread("RenderThread")
}

// 用来保存Slice
data class Slice(
    val type:String,
    val name:String,
    val start:Long,
    val duration:Long
) {
    val end:Long = start + duration

    val frameId:Int? = when(type) {
        FrameSliceType.Actual.value -> name.toIntOrNull()
        FrameSliceType.Expected.value  -> name.toIntOrNull()
        FrameSliceType.UiThread.value -> name.split(" ")[2].toIntOrNull()
        FrameSliceType.RenderThread.value -> name.substringAfter(" ").toIntOrNull()
        else -> { throw IllegalArgumentException("unexpected slice type") }
    }

    fun contains(targetTs:Long):Boolean {

        return targetTs in start..end
    }
}

// 用来将Row快速转换为Slice
@OptIn(ExperimentalPerfettoTraceProcessorApi::class)
fun Sequence<Row>.toSlices():List<Slice> {

    // 转成List<Slice>对象
    val list = map {

        Slice(it.string("type"), it.string("name"), it.long("ts"), it.long("dur"))

    }.toList()

    // 将ts调整为offset模式
    return list.map {

        it.copy(start = (it.start - list.first().start))

    }.filter {

        // 过滤掉没有结束的Slice
        it.duration != -1L
    }
}

enum class SubMetric {
    FrameDurationCpuMs,
    FrameDurationUiMs,
    FrameOverrunMs;
}

// 帧数据
class FrameData (
    private val expected:Slice,
    private val actual:Slice,
    private val uiThread:Slice,
    private val renderThread:Slice
) {

    fun get(subMetric:SubMetric):Long {
        return when(subMetric) {
            SubMetric.FrameDurationCpuMs -> renderThread.end - uiThread.start
            SubMetric.FrameDurationUiMs -> uiThread.duration
            SubMetric.FrameOverrunMs -> maxOf(actual.end, renderThread.end) - expected.end
        }
    }
}

// 使用FrameId查找对应的Slice，找不到就返回Null
fun List<Slice>.binarySearchByFrameId(frameId:Int):Slice? {

    val index = binarySearch { target -> target.frameId!! - frameId }

    return if(index >= 0) {
        // get slice
        get(index)
    } else {
        // null
        null
    }
}




/**
 * get Frame metrics
 */
@OptIn(ExperimentalMetricApi::class)
class FrameMetric:TraceMetric() {

    @OptIn(ExperimentalPerfettoTraceProcessorApi::class)
    override fun getResult(
        captureInfo: CaptureInfo,
        traceSession: PerfettoTraceProcessor.Session
    ): List<Measurement> {

        val rows = traceSession.query(query = FrameMetricQuery.getFullQuery(captureInfo.targetPackageName))
        var slices = rows.toSlices()

        // 对数据分组
        val groupedData = slices.groupBy { it.type }
        var expectedSlices = groupedData.getOrElse(FrameSliceType.Expected.value) { listOf() }
        var actualSlices = groupedData.getOrElse(FrameSliceType.Actual.value) { listOf() }
        var uiThreadSlices = groupedData.getOrElse(FrameSliceType.UiThread.value) { listOf() }
        var renderThreadSlices = groupedData.getOrElse(FrameSliceType.RenderThread.value) { listOf() }

        val frameDataList = renderThreadSlices.mapNotNull { rtSlice ->
            val uiSlice = uiThreadSlices.binarySearchByFrameId(rtSlice.frameId!!)
            if(uiSlice != null) {

                val actualSlice = actualSlices.binarySearchByFrameId(uiSlice.frameId!!)

                if(actualSlice != null) {

                    val expectedSlice = expectedSlices.binarySearchByFrameId(actualSlice.frameId!!)

                    if(expectedSlice != null) {
                        FrameData(
                            expectedSlice,
                            actualSlice,
                            uiSlice,
                            rtSlice
                        )
                    } else { null }
                } else { null }
            } else { null }
        }

        // 先将FrameData数据按照SubMetrics分为几类，然后将得到的Map转换成指标
        return frameDataList.getSubMetrics().map {
            Measurement(it.key.name, it.value.map { v -> v.toDouble() / 1000 / 1000 })
        }
    }
}


// 将FrameData转换为Metric
fun List<FrameData>.getSubMetrics():Map<SubMetric, List<Long>> {

    // associatedWith 将值映射为k,v的Map
    return SubMetric.values().associateWith {
        // 产生对应的List<Long>指标
        map { frameData -> frameData.get(it) }
    }
}


class FrameMetricQuery {

    companion object {
        fun getFullQuery(packageName:String): String {

            return """
                select ts, dur, type, name
                from (
                    --- 查询Expected Timeline与Actual Timeline
                    select process_track.name as type, slice.name as name, slice.ts as ts, slice.dur as dur
                    from slice
                    left join process_track on slice.track_id = process_track.id
                    left join process using(upid)
                    where
                        --- 限定track类型
                        process_track.name in ("Expected Timeline", "Actual Timeline")
                        --- 限定指定的包
                        and (process.name = "$packageName" or process.name like "$packageName:%")
                union
                    --- 查询UIThread中的事件
                    select  "UIThread" as type, slice.name, slice.ts, slice.dur
                    from slice
                    left join thread_track on slice.track_id = thread_track.id
                    left join thread using(utid)
                    left join process using(upid)
                    where
                        --- 限定事件类型
                        (slice.name like "Choreographer#doFrame%" )
                        --- 限定指定的包
                        and (process.name = "$packageName" or process.name like "$packageName:%")
    
                union
                    --- 查询RenderThread中的事件
                    select  "RenderThread" as type, slice.name, slice.ts, slice.dur
                    from slice
                    left join thread_track on slice.track_id = thread_track.id
                    left join thread using(utid)
                    left join process using(upid)
                    where
                        --- 限定事件类型
                        (thread.name like "RenderThread%" and slice.name like "drawFrames%")
                        --- 限定指定的包
                        and (process.name = "$packageName" or process.name like "$packageName:%")
                ) order by ts asc  --- 默认按照ts升序排序
            """.trimIndent()
        }
    }
}

Answer 2

I was able to resolve it by upgrading the dependency from androidx.benchmark:benchmark-macro-junit4:1.1.1 to androidx.benchmark:benchmark-macro-junit4:1.2.2