commit cf486d5095a10360d51a618efed258e5cdeb2ed2
author David Brazdil <dbrazdil@google.com> Sat Jan 07 11:50:21 2023 +0000
committer David Brazdil <dbrazdil@google.com> Mon Jan 09 00:42:34 2023 +0000
tree 7ce2c455fe4bb5f00a1869308b07d99244aa377e
parent 4280d7c8e79b49c3857b379ce18519d4e83954c2

Measure Microdroid boot time in non-debug mode

Our current benchmarks measure boot time in DEBUG_MODE_FULL and try to
parse the console output to identify time spent in individual boot
stages. That is helpful data but it means that the reported overall boot
time is not representative of production environment.

Rename the existing test to testMicrodroidBootTimeDebug and add
testMicrodroidBootTime that runs in DEBUG_MODE_NONE.

Test: atest MicrodroidBenchmarkApp
Change-Id: Iab706340803957ef26c6ec2cede75485c2e04808

tests/benchmark/src/java/com/android/microdroid/benchmark/MicrodroidBenchmarks.java

diff --git a/tests/benchmark/src/java/com/android/microdroid/benchmark/MicrodroidBenchmarks.java b/tests/benchmark/src/java/com/android/microdroid/benchmark/MicrodroidBenchmarks.java
index 3c3faf2..cba29a6 100644
--- a/tests/benchmark/src/java/com/android/microdroid/benchmark/MicrodroidBenchmarks.java
+++ b/tests/benchmark/src/java/com/android/microdroid/benchmark/MicrodroidBenchmarks.java
@@ -65,6 +65,7 @@
 
     private static final String APEX_ETC_FS = "/apex/com.android.virt/etc/fs/";
     private static final double SIZE_MB = 1024.0 * 1024.0;
+    private static final double NANO_TO_MILLI = 1000000.0;
     private static final String MICRODROID_IMG_PREFIX = "microdroid_";
     private static final String MICRODROID_IMG_SUFFIX = ".img";
 
@@ -140,19 +141,12 @@
 
         final int trialCount = 10;
 
-        List<Double> vmStartingTimeMetrics = new ArrayList<>();
         List<Double> bootTimeMetrics = new ArrayList<>();
-        List<Double> bootloaderTimeMetrics = new ArrayList<>();
-        List<Double> kernelBootTimeMetrics = new ArrayList<>();
-        List<Double> userspaceBootTimeMetrics = new ArrayList<>();
-
         for (int i = 0; i < trialCount; i++) {
-
-            // To grab boot events from log, set debug mode to FULL
             VirtualMachineConfig normalConfig =
                     newVmConfigBuilder()
                             .setPayloadBinaryPath("MicrodroidIdleNativeLib.so")
-                            .setDebugLevel(DEBUG_LEVEL_FULL)
+                            .setDebugLevel(DEBUG_LEVEL_NONE)
                             .setMemoryMib(256)
                             .build();
             forceCreateNewVirtualMachine("test_vm_boot_time", normalConfig);
@@ -160,12 +154,43 @@
             BootResult result = tryBootVm(TAG, "test_vm_boot_time");
             assertThat(result.payloadStarted).isTrue();
 
-            final double nanoToMilli = 1000000.0;
-            vmStartingTimeMetrics.add(result.getVMStartingElapsedNanoTime() / nanoToMilli);
-            bootTimeMetrics.add(result.endToEndNanoTime / nanoToMilli);
-            bootloaderTimeMetrics.add(result.getBootloaderElapsedNanoTime() / nanoToMilli);
-            kernelBootTimeMetrics.add(result.getKernelElapsedNanoTime() / nanoToMilli);
-            userspaceBootTimeMetrics.add(result.getUserspaceElapsedNanoTime() / nanoToMilli);
+            bootTimeMetrics.add(result.endToEndNanoTime / NANO_TO_MILLI);
+        }
+
+        reportMetrics(bootTimeMetrics, "boot_time", "ms");
+    }
+
+    @Test
+    public void testMicrodroidDebugBootTime()
+            throws VirtualMachineException, InterruptedException, IOException {
+        assume().withMessage("Skip on CF; too slow").that(isCuttlefish()).isFalse();
+
+        final int trialCount = 10;
+
+        List<Double> vmStartingTimeMetrics = new ArrayList<>();
+        List<Double> bootTimeMetrics = new ArrayList<>();
+        List<Double> bootloaderTimeMetrics = new ArrayList<>();
+        List<Double> kernelBootTimeMetrics = new ArrayList<>();
+        List<Double> userspaceBootTimeMetrics = new ArrayList<>();
+
+        for (int i = 0; i < trialCount; i++) {
+            // To grab boot events from log, set debug mode to FULL
+            VirtualMachineConfig normalConfig =
+                    newVmConfigBuilder()
+                            .setPayloadBinaryPath("MicrodroidIdleNativeLib.so")
+                            .setDebugLevel(DEBUG_LEVEL_FULL)
+                            .setMemoryMib(256)
+                            .build();
+            forceCreateNewVirtualMachine("test_vm_boot_time_debug", normalConfig);
+
+            BootResult result = tryBootVm(TAG, "test_vm_boot_time_debug");
+            assertThat(result.payloadStarted).isTrue();
+
+            vmStartingTimeMetrics.add(result.getVMStartingElapsedNanoTime() / NANO_TO_MILLI);
+            bootTimeMetrics.add(result.endToEndNanoTime / NANO_TO_MILLI);
+            bootloaderTimeMetrics.add(result.getBootloaderElapsedNanoTime() / NANO_TO_MILLI);
+            kernelBootTimeMetrics.add(result.getKernelElapsedNanoTime() / NANO_TO_MILLI);
+            userspaceBootTimeMetrics.add(result.getUserspaceElapsedNanoTime() / NANO_TO_MILLI);
         }
 
         reportMetrics(vmStartingTimeMetrics, "vm_starting_time", "ms");