commit 4f1218062b09bd6e44bee740ed0bec8f6b17b424
author Jiyong Park <jiyong@google.com> Mon Jun 26 19:24:44 2023 +0900
committer Jiyong Park <jiyong@google.com> Tue Jun 27 01:49:44 2023 +0000
tree 33f90a41059780fe289c403ffffa5af9ee3c91b6
parent 06f8413d6ffe40d722f4663e8beadc26a450d620

Monitor boottime metrics also from liblog logs

b/270566364 changed the Microdroid behavior so that most userspace logs
are emitted to liblog logs. Therefore, to measure the boottime metrics,
we need to read both console and liblog logs.

Bug: 270566364
Bug: 288849786
Test: atest MicrodroidBenchmarkApp
Change-Id: Ia2bff94acf53e51e66f56b00d396dec6e9735287

tests/helper/src/java/com/android/microdroid/test/device/MicrodroidDeviceTestBase.java

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 f58ce81..7e6080f 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
@@ -160,7 +160,7 @@
         private StringBuilder mLogOutput = new StringBuilder();
         private boolean mProcessedBootTimeMetrics = false;
 
-        private void processBootTimeMetrics(String log) {
+        private synchronized void processBootTimeMetrics(String log) {
             if (!mVcpuStartedNanoTime.isPresent()) {
                 mVcpuStartedNanoTime = OptionalLong.of(System.nanoTime());
             }
@@ -177,12 +177,8 @@
         }
 
         private void logVmOutputAndMonitorBootTimeMetrics(
-                String tag,
-                InputStream vmOutputStream,
-                String name,
-                StringBuilder result,
-                boolean monitorEvents) {
-            mProcessedBootTimeMetrics |= monitorEvents;
+                String tag, InputStream vmOutputStream, String name, StringBuilder result) {
+            mProcessedBootTimeMetrics = true;
             new Thread(
                             () -> {
                                 try {
@@ -192,7 +188,7 @@
                                     String line;
                                     while ((line = reader.readLine()) != null
                                             && !Thread.interrupted()) {
-                                        if (monitorEvents) processBootTimeMetrics(line);
+                                        processBootTimeMetrics(line);
                                         Log.i(tag, name + ": " + line);
                                         result.append(line + "\n");
                                     }
@@ -203,17 +199,6 @@
                     .start();
         }
 
-        private void logVmOutputAndMonitorBootTimeMetrics(
-                String tag, InputStream vmOutputStream, String name, StringBuilder result) {
-            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) {
-            logVmOutputAndMonitorBootTimeMetrics(tag, vmOutputStream, name, result, false);
-        }
-
         public void runToFinish(String logTag, VirtualMachine vm)
                 throws VirtualMachineException, InterruptedException {
             vm.setCallback(mExecutorService, this);
@@ -221,7 +206,7 @@
             if (vm.getConfig().isVmOutputCaptured()) {
                 logVmOutputAndMonitorBootTimeMetrics(
                         logTag, vm.getConsoleOutput(), "Console", mConsoleOutput);
-                logVmOutput(logTag, vm.getLogOutput(), "Log", mLogOutput);
+                logVmOutputAndMonitorBootTimeMetrics(logTag, vm.getLogOutput(), "Log", mLogOutput);
             }
             mExecutorService.awaitTermination(300, TimeUnit.SECONDS);
         }