Snap for 10453563 from 1ed1e0c89b5956db27834f9339bd9149a53034d0 to mainline-sdkext-releaseaml_sdk_341510000aml_sdk_341410000aml_sdk_341110080aml_sdk_341110000aml_sdk_341010000aml_sdk_340912010android14-mainline-sdkext-release

Change-Id: I96fc0adda6b729012156469a2aa1f0641820d18b

6 files changed, 119 insertions, 56 deletions

diff --git a/Android.bp b/Android.bp
index 0e77526..6791bf4 100644
--- a/Android.bp
+++ b/Android.bp
@@ -26,4 +26,6 @@ tradefed_java_library_host {
     "guava",
     "json-prebuilt",
   ],
+  // b/267831518: Pin tradefed and dependencies to Java 11.
+  java_version: "11",
 }
diff --git a/javatests/com/android/loganalysis/parser/DmesgParserTest.java b/javatests/com/android/loganalysis/parser/DmesgParserTest.java
index e4ea7af..a7705e3 100644
--- a/javatests/com/android/loganalysis/parser/DmesgParserTest.java
+++ b/javatests/com/android/loganalysis/parser/DmesgParserTest.java
@@ -50,6 +50,8 @@ public class DmesgParserTest extends TestCase {
                 "[    1.115467] init: Loaded 198 kernel modules took 748 ms",
                 "[    2.471163] init: Wait for property 'apexd.status=ready' took 403ms",
                 "[    3.786943] ueventd: Coldboot took 0.701291 seconds",
+                "[    4.295667] init: Command 'mount_all --late' action=late-fs "
+                        + "/vendor/etc/init/hw/init.rc:347) took 250ms and succeeded",
                 "[   22.962730] init: starting service 'bootanim'...",
                 "[   23.252321] init: starting service 'netd'...",
                 "[   29.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA",
@@ -113,7 +115,9 @@ public class DmesgParserTest extends TestCase {
 
         assertEquals("Service info items list size should be 2", 2,
                 dmesgParser.getServiceInfoItems().size());
-        assertEquals("Stage info items list size should be 3",3,
+        assertEquals(
+                "Stage info items list size should be 4",
+                4,
                 dmesgParser.getStageInfoItems().size());
         assertEquals("Action info items list size should be 9",9,
                 dmesgParser.getActionInfoItems().size());
@@ -138,7 +142,9 @@ public class DmesgParserTest extends TestCase {
             dmesgParser.parseInfo(bufferedReader);
             assertEquals("Service info items list size should be 2", 2,
                     dmesgParser.getServiceInfoItems().size());
-            assertEquals("Stage info items list size should be 3", 3,
+            assertEquals(
+                    "Stage info items list size should be 4",
+                    4,
                     dmesgParser.getStageInfoItems().size());
             assertEquals("Action info items list size should be 9",9,
                     dmesgParser.getActionInfoItems().size());
@@ -214,6 +220,31 @@ public class DmesgParserTest extends TestCase {
         assertEquals("No service info should be available", 0, serviceInfoItems.size());
     }
 
+    public void testCompleteStageInfo_onKernel_5_15() {
+        DmesgParser dmesgParser = new DmesgParser();
+        String[] lines =
+                new String[] {
+                    "[    0.370107] [@2 init][....] init: Loading module /lib/modules/foo.ko "
+                            + "with args ''",
+                    "[    0.372497] [@2 init][....] init: Loaded kernel module /lib/modules/foo.ko",
+                    "[    0.372500] [@2 init][....] init: Loading module /lib/modules/bar.ko "
+                            + "with args ''",
+                    "[    1.115467] [@2 init][....] init: Loaded 198 kernel modules took 748 ms",
+                    "[    2.471163] [@2 init][....] init: Wait for property 'apexd.status=ready' "
+                            + "took 403ms",
+                    "[    3.786943] [@2 init][....] ueventd: Coldboot took 0.701291 seconds",
+                    "[    4.295667] [@2 init][....] init: Command 'mount_all --late' action=late-fs"
+                            + " /vendor/etc/init/hw/init.rc:347) took 250ms and succeeded",
+                    "[   41.665818] [@2 init][....] init: init first stage started!"
+                };
+        for (String line : lines) {
+            dmesgParser.parseStageInfo(line);
+        }
+        List<DmesgStageInfoItem> stageInfoItems = dmesgParser.getStageInfoItems();
+        assertEquals(4, stageInfoItems.size());
+        assertEquals(EXPECTED_STAGE_INFO_ITEMS, stageInfoItems);
+    }
+
     /**
      * Test init stages' start time logs
      */
@@ -223,7 +254,7 @@ public class DmesgParserTest extends TestCase {
             dmesgParser.parseStageInfo(line);
         }
         List<DmesgStageInfoItem> stageInfoItems = dmesgParser.getStageInfoItems();
-        assertEquals(3, stageInfoItems.size());
+        assertEquals(4, stageInfoItems.size());
         assertEquals(EXPECTED_STAGE_INFO_ITEMS, stageInfoItems);
     }
 
@@ -272,6 +303,7 @@ public class DmesgParserTest extends TestCase {
         return Arrays.asList(
                 new DmesgStageInfoItem("init_Wait for property 'apexd.status=ready'", null, 403L),
                 new DmesgStageInfoItem("ueventd_Coldboot", null, 701L),
+                new DmesgStageInfoItem("init_mount_all_late", null, 250L),
                 new DmesgStageInfoItem("first", 41665L, null));
     }
 
diff --git a/javatests/com/android/loganalysis/parser/TimingsLogParserTest.java b/javatests/com/android/loganalysis/parser/TimingsLogParserTest.java
index 48881ea..af8d7e0 100644
--- a/javatests/com/android/loganalysis/parser/TimingsLogParserTest.java
+++ b/javatests/com/android/loganalysis/parser/TimingsLogParserTest.java
@@ -272,20 +272,20 @@ public class TimingsLogParserTest extends TestCase {
         String log =
                 String.join(
                         "\n",
-                        "01-10 01:25:57.675   981   981 D SystemServerTiming: StartWatchdog took to complete: 38ms",
+                        "01-10 01:25:57.675   981   981 V SystemServerTiming: StartWatchdog took to complete: 38ms",
                         "01-10 01:25:57.675   981   981 I SystemServer: Reading configuration...",
                         "01-10 01:25:57.675   981   981 I SystemServer: ReadingSystemConfig",
-                        "01-10 01:25:57.676   981   981 D SystemServerTiming: ReadingSystemConfig took to complete: 0.53ms",
-                        "01-10 01:25:57.676   981   981 D SystemServerTiming: ReadingSystemConfig took to complete: 0.53ms", // Parser should skip duplicated log line
+                        "01-10 01:25:57.676   981   981 V SystemServerTiming: ReadingSystemConfig took to complete: 0.53ms",
+                        "01-10 01:25:57.676   981   981 V SystemServerTiming: ReadingSystemConfig took to complete: 0.53ms", // Parser should skip duplicated log line
                         "01-10 01:25:57.677   465   465 I snet_event_log: [121035042,-1,]",
                         "01-10 01:25:57.678   900   900 I FakeComponent: FakeSubcomponent wrong format took to complete: 10ms",
                         "01-10 01:25:57.678   900   900 I FakeComponent: FakeSubcomponent took to complete: 20s",
-                        "01-10 01:25:57.680   981   981 D SystemServerTiming: StartInstaller took to complete: 5ms wrong format",
-                        "01-10 01:25:57.682   981   981 D SystemServerTiming: DeviceIdentifiersPolicyService took to complete: 2ms",
-                        "01-10 01:25:57.682   981   981 D SystemServerTiming: DeviceIdentifiersPolicyService took to complete: 2ms",
-                        "06-06 19:23:54.410  1295  1295 D OtherService  : StartTestStack took to complete: 7ms",
-                        "06-06 19:23:55.410   129   129 D FakeService  : Validtook to complete: 8ms",
-                        "06-06 19:23:56.410   981   981 D SystemServerTiming: StartWatchdog took to complete: 38ms"); //Parser should parse the same metric at a different time
+                        "01-10 01:25:57.680   981   981 V SystemServerTiming: StartInstaller took to complete: 5ms wrong format",
+                        "01-10 01:25:57.682   981   981 V SystemServerTiming: DeviceIdentifiersPolicyService took to complete: 2ms",
+                        "01-10 01:25:57.682   981   981 V SystemServerTiming: DeviceIdentifiersPolicyService took to complete: 2ms",
+                        "06-06 19:23:54.410  1295  1295 V OtherService  : StartTestStack took to complete: 7ms",
+                        "06-06 19:23:55.410   129   129 V FakeService  : Validtook to complete: 8ms",
+                        "06-06 19:23:56.410   981   981 V SystemServerTiming: StartWatchdog took to complete: 38ms"); //Parser should parse the same metric at a different time
 
         List<SystemServicesTimingItem> items =
                 mParser.parseSystemServicesTimingItems(createBufferedReader(log));
@@ -315,17 +315,17 @@ public class TimingsLogParserTest extends TestCase {
         String log =
                 String.join(
                         "\n",
-                        "01-10 01:24:45.536  1079  1079 D BootAnimation: BootAnimationStartTiming start time: 8611ms",
-                        "01-10 01:24:45.537  1079  1079 D BootAnimation: BootAnimationPreloadTiming start time: 8611ms",
+                        "01-10 01:24:45.536  1079  1079 V BootAnimation: BootAnimationStartTiming start time: 8611ms",
+                        "01-10 01:24:45.537  1079  1079 V BootAnimation: BootAnimationPreloadTiming start time: 8611ms",
                         "01-10 01:24:45.556   874  1021 I ServiceManager: Waiting for service 'package_native' on '/dev/binder'...",
                         "01-10 01:24:45.561   466   466 I snet_event_log: [121035042,-1,]",
                         "01-10 01:24:45.583  1080  1080 I SystemServer: InitBeforeStartServices start time: 2345ms wrong format",
-                        "01-10 01:25:24.095  1014  1111 D BootAnimation: BootAnimationShownTiming start time: 9191s",
+                        "01-10 01:25:24.095  1014  1111 V BootAnimation: BootAnimationShownTiming start time: 9191s",
                         "06-06 19:23:49.299   603   603 E qdmetadata: Unknown paramType 2",
                         "06-06 19:23:49.299   603   603 I FakeComponent : wrong subcomponent start time: 234ms",
-                        "06-06 19:23:49.299   603   603 D FakeComponent: Subcomponent start time 234ms",
-                        "06-06 19:23:49.299  1079  1079 D BootAnimation: BootAnimationStopTiming start time: 24839ms",
-                        "06-06 19:23:59.299   179   179 D FakeService  : Validstart time: 34839ms");
+                        "06-06 19:23:49.299   603   603 V FakeComponent: Subcomponent start time 234ms",
+                        "06-06 19:23:49.299  1079  1079 V BootAnimation: BootAnimationStopTiming start time: 24839ms",
+                        "06-06 19:23:59.299   179   179 V FakeService  : Validstart time: 34839ms");
 
         List<SystemServicesTimingItem> items =
                 mParser.parseSystemServicesTimingItems(createBufferedReader(log));
diff --git a/src/com/android/loganalysis/item/DvmLockSampleItem.java b/src/com/android/loganalysis/item/DvmLockSampleItem.java
index 01372a4..10edebc 100644
--- a/src/com/android/loganalysis/item/DvmLockSampleItem.java
+++ b/src/com/android/loganalysis/item/DvmLockSampleItem.java
@@ -17,7 +17,6 @@ package com.android.loganalysis.item;
 
 
 import java.util.Arrays;
-import java.util.HashMap;
 import java.util.HashSet;
 import java.util.Map;
 import java.util.Set;
@@ -43,17 +42,16 @@ public class DvmLockSampleItem extends GenericItem {
             OWNER_ACQUIRE_SOURCE_LINE, SAMPLE_PERCENTAGE));
 
     @SuppressWarnings("serial")
-    private static final Map<String, Class<?>> TYPES = new HashMap<String, Class<?>>() {{
-        put(PROCESS_NAME, String.class);
-        put(SENSITIVITY_FLAG, Boolean.class);
-        put(WAITING_THREAD_NAME, String.class);
-        put(WAIT_TIME, Integer.class);
-        put(WAITING_SOURCE_FILE, String.class);
-        put(WAITING_SOURCE_LINE, Integer.class);
-        put(OWNER_FILE_NAME, String.class);
-        put(OWNER_ACQUIRE_SOURCE_LINE, Integer.class);
-        put(SAMPLE_PERCENTAGE, Integer.class);
-    }};
+    private static final Map<String, Class<?>> TYPES = Map.of(
+        PROCESS_NAME, String.class,
+        SENSITIVITY_FLAG, Boolean.class,
+        WAITING_THREAD_NAME, String.class,
+        WAIT_TIME, Integer.class,
+        WAITING_SOURCE_FILE, String.class,
+        WAITING_SOURCE_LINE, Integer.class,
+        OWNER_FILE_NAME, String.class,
+        OWNER_ACQUIRE_SOURCE_LINE, Integer.class,
+        SAMPLE_PERCENTAGE, Integer.class);
 
     public DvmLockSampleItem() {
         super(ATTRIBUTES);
diff --git a/src/com/android/loganalysis/parser/DmesgParser.java b/src/com/android/loganalysis/parser/DmesgParser.java
index 53514d2..1b83ca4 100644
--- a/src/com/android/loganalysis/parser/DmesgParser.java
+++ b/src/com/android/loganalysis/parser/DmesgParser.java
@@ -47,13 +47,22 @@ public class DmesgParser implements IParser {
     private static final String INIT = "init";
     private static final String WAIT_PROPERTY = "Wait for property ";
     private static final String TOTAL_MODULE = "TOTAL_MODULE";
+    private static final String MOUNT_ALL = "mount_all";
+
+    private static final String TIMESTAMP_PATTERN =
+            String.format("\\[\\s+(?<%s>[\\d.]+)]", TIMESTAMP);
+
+    // This is optionally present in dmesg output on some kernels
+    // Matches possibly repeated pairs of square brackets enclosing arbitrary text
+    // An example is [   10.258464] [@3 insmod][....] aml dvb init
+    private static final String CPU_INFO_PATTERN = "(\\[[^]]+])+";
 
     // Matches: [ 14.822691] init:
-    private static final String SERVICE_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] init:\\s+",
-            TIMESTAMP);
+    private static final String SERVICE_PREFIX =
+            String.format("^%s( %s)? init:\\s+", TIMESTAMP_PATTERN, CPU_INFO_PATTERN);
     // Matches: [    3.791635] ueventd:
-    private static final String UEVENTD_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] ueventd:\\s+",
-            TIMESTAMP);
+    private static final String UEVENTD_PREFIX =
+            String.format("^%s( %s)? ueventd:\\s+", TIMESTAMP_PATTERN, CPU_INFO_PATTERN);
 
     // Matches: starting service 'ueventd'...
     private static final String START_SERVICE_SUFFIX = String.format("starting service "
@@ -106,8 +115,8 @@ public class DmesgParser implements IParser {
                             "%sLoaded kernel module \\S+\\/(?<koname>\\S+)\\.ko", SERVICE_PREFIX));
 
     // Matches: [    3.791635] ueventd: Coldboot took 0.695055 seconds
-    private static final String STAGE_SUFFIX= String.format(
-            "(?<%s>.*)\\s+took\\s+(?<%s>.*)\\s+seconds$", STAGE, DURATION);
+    private static final String STAGE_SUFFIX =
+            String.format("(?<%s>.*)\\s+took\\s+(?<%s>.*)\\s+seconds$", STAGE, DURATION);
     private static final Pattern UEVENTD_STAGE_INFO = Pattern.compile(
             String.format("%s%s", UEVENTD_PREFIX, STAGE_SUFFIX));
 
@@ -117,6 +126,15 @@ public class DmesgParser implements IParser {
     private static final Pattern WAIT_FOR_PROPERTY_INFO = Pattern.compile(
             String.format("%s%s", SERVICE_PREFIX, PROPERTY_SUFFIX));
 
+    // Matches: [    2.295667] init: Command 'mount_all --late' action=late-fs
+    // (/vendor/etc/init/init.rc:347) took 250ms and succeeded
+    private static final String MOUNT_SUFFIX =
+            String.format(
+                    "Command 'mount_all (?<%s>/\\S+|.*)?--(?<%s>.+)'.* took (?<%s>\\d+)ms.*",
+                    SOURCE, STAGE, DURATION);
+    private static final Pattern MOUNT_STAGE_INFO =
+            Pattern.compile(String.format("%s%s", SERVICE_PREFIX, MOUNT_SUFFIX));
+
     private DmesgItem mDmesgItem = new DmesgItem();
 
     /**
@@ -134,10 +152,10 @@ public class DmesgParser implements IParser {
     /**
      * Parse the kernel log till EOF to retrieve the duration of the service calls, start times of
      * different boot stages and actions taken. Besides, while parsing these informations are stored
-     * in the intermediate {@link DmesgServiceInfoItem}, {@link DmesgStageInfoItem} and
-     * {@link DmesgActionInfoItem} objects
+     * in the intermediate {@link DmesgServiceInfoItem}, {@link DmesgStageInfoItem} and {@link
+     * DmesgActionInfoItem} objects
      *
-     * @param input dmesg log
+     * @param bufferedLog dmesg log
      * @throws IOException
      */
     public DmesgItem parseInfo(BufferedReader bufferedLog) throws IOException {
@@ -184,9 +202,9 @@ public class DmesgParser implements IParser {
      * log and store the {@code duration} it took to complete the service if the end time stamp is
      * available in {@link DmesgServiceInfoItem}.
      *
-     * @param individual line of the dmesg log
-     * @return {@code true}, if the {@code line} indicates start or end of a service,
-     *         {@code false}, otherwise
+     * @param line individual line of the dmesg log
+     * @return {@code true}, if the {@code line} indicates start or end of a service, {@code false},
+     *     otherwise
      */
     @VisibleForTesting
     boolean parseServiceInfo(String line) {
@@ -211,13 +229,12 @@ public class DmesgParser implements IParser {
     }
 
     /**
-     * Parse init stages log from each {@code line} of dmesg log and
-     * store the stage name, start time and duration if available in a
-     * {@link DmesgStageInfoItem} object
+     * Parse init stages log from each {@code line} of dmesg log and store the stage name, start
+     * time and duration if available in a {@link DmesgStageInfoItem} object
      *
-     * @param individual line of the dmesg log
-     * @return {@code true}, if the {@code line} indicates start of a boot stage,
-     *         {@code false}, otherwise
+     * @param line individual line of the dmesg log
+     * @return {@code true}, if the {@code line} indicates start of a boot stage, {@code false},
+     *     otherwise
      */
     @VisibleForTesting
     boolean parseStageInfo(String line) {
@@ -246,17 +263,31 @@ public class DmesgParser implements IParser {
             mDmesgItem.addStageInfoItem(stageInfoItem);
             return true;
         }
-
+        if ((match = matches(MOUNT_STAGE_INFO, line)) != null) {
+            DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
+            if (match.group(SOURCE).isEmpty()) {
+                stageInfoItem.setStageName(
+                        String.format("%s_%s_%s", INIT, MOUNT_ALL, match.group(STAGE)));
+            } else {
+                stageInfoItem.setStageName(
+                        String.format(
+                                "%s_%s_%s_%s",
+                                INIT, MOUNT_ALL, match.group(STAGE), match.group(SOURCE).trim()));
+            }
+            stageInfoItem.setDuration((long) Double.parseDouble(match.group(DURATION)));
+            mDmesgItem.addStageInfoItem(stageInfoItem);
+            return true;
+        }
         return false;
     }
 
     /**
-     * Parse action from each {@code line} of dmesg log and store the action name and start time
-     * in {@link DmesgActionInfoItem} object
+     * Parse action from each {@code line} of dmesg log and store the action name and start time in
+     * {@link DmesgActionInfoItem} object
      *
-     * @param individual {@code line} of the dmesg log
-     * @return {@code true}, if {@code line} indicates starting of processing of action
-     *         {@code false}, otherwise
+     * @param line individual {@code line} of the dmesg log
+     * @return {@code true}, if {@code line} indicates starting of processing of action {@code
+     *     false}, otherwise
      */
     @VisibleForTesting
     boolean parseActionInfo(String line) {
@@ -279,7 +310,7 @@ public class DmesgParser implements IParser {
      * Parse modules from each {@code line} of dmesg log and store the module name and loading time
      * in {@link DmesgModuleInfoItem} object
      *
-     * @param individual {@code line} of the dmesg log
+     * @param line individual {@code line} of the dmesg log
      * @return {@code true}, if {@code line} indicates start, end of a module loading or the summary
      *     {@code false}, otherwise
      */
diff --git a/src/com/android/loganalysis/parser/TimingsLogParser.java b/src/com/android/loganalysis/parser/TimingsLogParser.java
index 8df5cf7..6cbc993 100644
--- a/src/com/android/loganalysis/parser/TimingsLogParser.java
+++ b/src/com/android/loganalysis/parser/TimingsLogParser.java
@@ -61,7 +61,7 @@ public class TimingsLogParser implements IParser {
     /**
      * Match the line with system services duration info like:
      *
-     * <p>03-10 21:43:40.328 1005 1005 D SystemServerTiming:
+     * <p>03-10 21:43:40.328 1005 1005 V SystemServerTiming:
      * StartKeyAttestationApplicationIdProviderService took to complete: 3474ms
      */
     private static final Pattern SYSTEM_SERVICES_DURATION =