Merge "Refactor Microdroid boot time benchmarks"
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 f17000a..db87126 100644
--- a/tests/benchmark/src/java/com/android/microdroid/benchmark/MicrodroidBenchmarks.java
+++ b/tests/benchmark/src/java/com/android/microdroid/benchmark/MicrodroidBenchmarks.java
@@ -50,8 +50,11 @@
import java.io.IOException;
import java.nio.file.Files;
import java.util.ArrayList;
+import java.util.Collections;
+import java.util.HashMap;
import java.util.List;
import java.util.Map;
+import java.util.OptionalLong;
import java.util.concurrent.atomic.AtomicReference;
import java.util.function.Function;
@@ -136,102 +139,87 @@
mInstrumentation.sendStatus(0, bundle);
}
- @Test
- public void testMicrodroidBootTime()
+ private static class BootTimeStats {
+ private final Map<BootTimeMetric, List<Double>> mData = new HashMap<>();
+
+ public BootTimeStats(int trialCount) {
+ for (BootTimeMetric metric : BootTimeMetric.values()) {
+ mData.put(metric, new ArrayList<>(trialCount));
+ }
+ }
+
+ public void collect(BootResult result) {
+ for (BootTimeMetric metric : BootTimeMetric.values()) {
+ OptionalLong value = result.getBootTimeMetricNanoTime(metric);
+ if (value.isPresent()) {
+ mData.get(metric).add(value.getAsLong() / NANO_TO_MILLI);
+ }
+ }
+ }
+
+ public List<Double> get(BootTimeMetric metric) {
+ return Collections.unmodifiableList(mData.get(metric));
+ }
+ }
+
+ private BootTimeStats runBootTimeTest(
+ String name,
+ Function<VirtualMachineConfig.Builder, VirtualMachineConfig.Builder> fnConfig)
throws VirtualMachineException, InterruptedException, IOException {
assume().withMessage("Skip on CF; too slow").that(isCuttlefish()).isFalse();
final int trialCount = 10;
- List<Double> bootTimeMetrics = new ArrayList<>();
+ BootTimeStats stats = new BootTimeStats(trialCount);
for (int i = 0; i < trialCount; i++) {
- VirtualMachineConfig normalConfig =
+ VirtualMachineConfig.Builder builder =
newVmConfigBuilder()
.setPayloadBinaryName("MicrodroidIdleNativeLib.so")
- .setDebugLevel(DEBUG_LEVEL_NONE)
.setMemoryBytes(256 * ONE_MEBI)
- .build();
- forceCreateNewVirtualMachine("test_vm_boot_time", normalConfig);
+ .setDebugLevel(DEBUG_LEVEL_NONE);
+ VirtualMachineConfig config = fnConfig.apply(builder).build();
+ forceCreateNewVirtualMachine(name, config);
- BootResult result = tryBootVm(TAG, "test_vm_boot_time");
+ BootResult result = tryBootVm(TAG, name);
assertThat(result.payloadStarted).isTrue();
-
- bootTimeMetrics.add(result.endToEndNanoTime / NANO_TO_MILLI);
+ stats.collect(result);
}
+ return stats;
+ }
- reportMetrics(bootTimeMetrics, "boot_time", "ms");
+ @Test
+ public void testMicrodroidBootTime()
+ throws VirtualMachineException, InterruptedException, IOException {
+ BootTimeStats stats = runBootTimeTest("test_vm_boot_time", (builder) -> builder);
+ reportMetrics(stats.get(BootTimeMetric.TOTAL), "boot_time", "ms");
}
@Test
public void testMicrodroidMulticoreBootTime()
throws VirtualMachineException, InterruptedException, IOException {
- assume().withMessage("Skip on CF; too slow").that(isCuttlefish()).isFalse();
-
- final int trialCount = 10;
- final int[] trialNumCpus = {2, 4, 8};
-
- for (int numCpus : trialNumCpus) {
- List<Double> bootTimeMetrics = new ArrayList<>();
- for (int i = 0; i < trialCount; i++) {
- VirtualMachineConfig normalConfig =
- newVmConfigBuilder()
- .setPayloadBinaryName("MicrodroidIdleNativeLib.so")
- .setDebugLevel(DEBUG_LEVEL_NONE)
- .setMemoryBytes(256 * ONE_MEBI)
- .setNumCpus(numCpus)
- .build();
- forceCreateNewVirtualMachine("test_vm_boot_time_multicore", normalConfig);
-
- BootResult result = tryBootVm(TAG, "test_vm_boot_time_multicore");
- assertThat(result.payloadStarted).isTrue();
-
- bootTimeMetrics.add(result.endToEndNanoTime / NANO_TO_MILLI);
- }
-
+ for (int numCpus : new int[] {2, 4, 8}) {
+ BootTimeStats stats =
+ runBootTimeTest(
+ "test_vm_boot_time_multicore",
+ (builder) -> builder.setNumCpus(numCpus));
String metricName = "boot_time_" + numCpus + "cpus";
- reportMetrics(bootTimeMetrics, metricName, "ms");
+ reportMetrics(stats.get(BootTimeMetric.TOTAL), metricName, "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()
- .setPayloadBinaryName("MicrodroidIdleNativeLib.so")
- .setDebugLevel(DEBUG_LEVEL_FULL)
- .setVmOutputCaptured(true)
- .setMemoryBytes(256 * ONE_MEBI)
- .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");
- reportMetrics(bootTimeMetrics, "boot_time", "ms");
- reportMetrics(bootloaderTimeMetrics, "bootloader_time", "ms");
- reportMetrics(kernelBootTimeMetrics, "kernel_boot_time", "ms");
- reportMetrics(userspaceBootTimeMetrics, "userspace_boot_time", "ms");
+ BootTimeStats stats =
+ runBootTimeTest(
+ "test_vm_boot_time_debug",
+ (builder) ->
+ builder.setDebugLevel(DEBUG_LEVEL_FULL).setVmOutputCaptured(true));
+ reportMetrics(stats.get(BootTimeMetric.TOTAL), "boot_time", "ms");
+ reportMetrics(stats.get(BootTimeMetric.VM_START), "vm_starting_time", "ms");
+ reportMetrics(stats.get(BootTimeMetric.BOOTLOADER), "bootloader_time", "ms");
+ reportMetrics(stats.get(BootTimeMetric.KERNEL), "kernel_boot_time", "ms");
+ reportMetrics(stats.get(BootTimeMetric.USERSPACE), "userspace_boot_time", "ms");
}
@Test
diff --git a/tests/helper/src/java/com/android/microdroid/test/device/MicrodroidDeviceTestBase.java b/tests/helper/src/java/com/android/microdroid/test/device/MicrodroidDeviceTestBase.java
index f1da43a..419b250 100644
--- a/tests/helper/src/java/com/android/microdroid/test/device/MicrodroidDeviceTestBase.java
+++ b/tests/helper/src/java/com/android/microdroid/test/device/MicrodroidDeviceTestBase.java
@@ -148,8 +148,9 @@
private OptionalLong mPayloadStartedNanoTime = OptionalLong.empty();
private StringBuilder mConsoleOutput = new StringBuilder();
private StringBuilder mLogOutput = new StringBuilder();
+ private boolean mProcessedBootTimeMetrics = false;
- private void processBootEvents(String log) {
+ private void processBootTimeMetrics(String log) {
if (!mVcpuStartedNanoTime.isPresent()) {
mVcpuStartedNanoTime = OptionalLong.of(System.nanoTime());
}
@@ -165,12 +166,13 @@
}
}
- private void logVmOutputAndMonitorBootEvents(
+ private void logVmOutputAndMonitorBootTimeMetrics(
String tag,
InputStream vmOutputStream,
String name,
StringBuilder result,
boolean monitorEvents) {
+ mProcessedBootTimeMetrics = monitorEvents;
new Thread(
() -> {
try {
@@ -180,7 +182,7 @@
String line;
while ((line = reader.readLine()) != null
&& !Thread.interrupted()) {
- if (monitorEvents) processBootEvents(line);
+ if (monitorEvents) processBootTimeMetrics(line);
Log.i(tag, name + ": " + line);
result.append(line + "\n");
}
@@ -191,15 +193,15 @@
.start();
}
- private void logVmOutputAndMonitorBootEvents(
+ private void logVmOutputAndMonitorBootTimeMetrics(
String tag, InputStream vmOutputStream, String name, StringBuilder result) {
- logVmOutputAndMonitorBootEvents(tag, vmOutputStream, name, result, true);
+ logVmOutputAndMonitorBootTimeMetrics(tag, vmOutputStream, name, result, true);
}
/** Copy output from the VM to logcat. This is helpful when things go wrong. */
protected void logVmOutput(
String tag, InputStream vmOutputStream, String name, StringBuilder result) {
- logVmOutputAndMonitorBootEvents(tag, vmOutputStream, name, result, false);
+ logVmOutputAndMonitorBootTimeMetrics(tag, vmOutputStream, name, result, false);
}
public void runToFinish(String logTag, VirtualMachine vm)
@@ -207,7 +209,7 @@
vm.setCallback(mExecutorService, this);
vm.run();
if (vm.getConfig().isVmOutputCaptured()) {
- logVmOutputAndMonitorBootEvents(
+ logVmOutputAndMonitorBootTimeMetrics(
logTag, vm.getConsoleOutput(), "Console", mConsoleOutput);
logVmOutput(logTag, vm.getLogOutput(), "Log", mLogOutput);
}
@@ -238,6 +240,10 @@
return mLogOutput.toString();
}
+ public boolean hasProcessedBootTimeMetrics() {
+ return mProcessedBootTimeMetrics;
+ }
+
protected void forceStop(VirtualMachine vm) {
try {
vm.stop();
@@ -266,12 +272,21 @@
}
}
+ public enum BootTimeMetric {
+ TOTAL,
+ VM_START,
+ BOOTLOADER,
+ KERNEL,
+ USERSPACE,
+ }
+
public static class BootResult {
public final boolean payloadStarted;
public final int deathReason;
public final long apiCallNanoTime;
public final long endToEndNanoTime;
+ public final boolean processedBootTimeMetrics;
public final OptionalLong vcpuStartedNanoTime;
public final OptionalLong kernelStartedNanoTime;
public final OptionalLong initStartedNanoTime;
@@ -285,6 +300,7 @@
int deathReason,
long apiCallNanoTime,
long endToEndNanoTime,
+ boolean processedBootTimeMetrics,
OptionalLong vcpuStartedNanoTime,
OptionalLong kernelStartedNanoTime,
OptionalLong initStartedNanoTime,
@@ -295,6 +311,7 @@
this.payloadStarted = payloadStarted;
this.deathReason = deathReason;
this.endToEndNanoTime = endToEndNanoTime;
+ this.processedBootTimeMetrics = processedBootTimeMetrics;
this.vcpuStartedNanoTime = vcpuStartedNanoTime;
this.kernelStartedNanoTime = kernelStartedNanoTime;
this.initStartedNanoTime = initStartedNanoTime;
@@ -336,6 +353,31 @@
public long getUserspaceElapsedNanoTime() {
return getPayloadStartedNanoTime() - getInitStartedNanoTime();
}
+
+ public boolean hasProcessedBootTimeMetrics() {
+ return processedBootTimeMetrics;
+ }
+
+ public OptionalLong getBootTimeMetricNanoTime(BootTimeMetric metric) {
+ if (metric == BootTimeMetric.TOTAL) {
+ return OptionalLong.of(endToEndNanoTime);
+ }
+
+ if (processedBootTimeMetrics) {
+ switch (metric) {
+ case VM_START:
+ return OptionalLong.of(getVMStartingElapsedNanoTime());
+ case BOOTLOADER:
+ return OptionalLong.of(getBootloaderElapsedNanoTime());
+ case KERNEL:
+ return OptionalLong.of(getKernelElapsedNanoTime());
+ case USERSPACE:
+ return OptionalLong.of(getUserspaceElapsedNanoTime());
+ }
+ }
+
+ return OptionalLong.empty();
+ }
}
public BootResult tryBootVm(String logTag, String vmName)
@@ -366,6 +408,7 @@
deathReason.getNow(VmEventListener.STOP_REASON_INFRASTRUCTURE_ERROR),
apiCallNanoTime,
endTime.getNow(apiCallNanoTime) - apiCallNanoTime,
+ listener.hasProcessedBootTimeMetrics(),
listener.getVcpuStartedNanoTime(),
listener.getKernelStartedNanoTime(),
listener.getInitStartedNanoTime(),