Add module info to dmesg parser

Parse module name, load duration and count from dmesg.

BUG: 174796470
Test: run_tradefed_tests.sh --class com.android.loganalysis.parser.DmesgParserTest
Change-Id: I4943ed10e7fa73519204cbfa028a3b8d75af2204

4 files changed, 277 insertions, 9 deletions

diff --git a/src/com/android/loganalysis/item/DmesgItem.java b/src/com/android/loganalysis/item/DmesgItem.java
index de70145..43fc04d 100644
--- a/src/com/android/loganalysis/item/DmesgItem.java
+++ b/src/com/android/loganalysis/item/DmesgItem.java
@@ -33,6 +33,8 @@ public class DmesgItem extends GenericItem {
 
     private List<DmesgActionInfoItem> mActionInfoItems = new ArrayList<>();
 
+    private Map<String, DmesgModuleInfoItem> mModuleInfoItems = new HashMap<>();
+
     public DmesgItem() {
         super(Collections.emptySet());
     }
@@ -80,4 +82,16 @@ public class DmesgItem extends GenericItem {
         mActionInfoItems.add(actionInfoItem);
     }
 
+    /** @return moduleInfoItem */
+    public Map<String, DmesgModuleInfoItem> getModuleInfoItems() {
+        return mModuleInfoItems;
+    }
+
+    /**
+     * @param key to identify module info item
+     * @param moduleInfoItem to be added to the list
+     */
+    public void addModuleInfoItem(String key, DmesgModuleInfoItem moduleInfoItem) {
+        mModuleInfoItems.put(key, moduleInfoItem);
+    }
 }
diff --git a/src/com/android/loganalysis/item/DmesgModuleInfoItem.java b/src/com/android/loganalysis/item/DmesgModuleInfoItem.java
new file mode 100644
index 0000000..dca6721
--- /dev/null
+++ b/src/com/android/loganalysis/item/DmesgModuleInfoItem.java
@@ -0,0 +1,122 @@
+/*
+ * Copyright (C) 2021 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.android.loganalysis.item;
+
+import java.util.Arrays;
+import java.util.HashSet;
+import java.util.Set;
+
+/** An {@link IItem} used to store Module info logged in dmesg. */
+public class DmesgModuleInfoItem extends GenericItem {
+
+    /** Constant for JSON output */
+    public static final String MODULE_NAME = "MODULE_NAME";
+
+    public static final String MODULE_START_TIME = "MODULE_START_TIME";
+
+    public static final String MODULE_END_TIME = "MODULE_END_TIME";
+
+    public static final String MODULE_COUNT = "MODULE_COUNT";
+
+    public static final String MODULE_DURATION = "MODULE_DURATION";
+
+    private static final Set<String> ATTRIBUTES =
+            new HashSet<String>(
+                    Arrays.asList(
+                            MODULE_NAME,
+                            MODULE_START_TIME,
+                            MODULE_END_TIME,
+                            MODULE_COUNT,
+                            MODULE_DURATION));
+
+    /** The constructor for {@link DmesgModuleInfoItem}. */
+    public DmesgModuleInfoItem() {
+        super(ATTRIBUTES);
+    }
+
+    /** Set the name of the Module */
+    public void setModuleName(String moduleName) {
+        setAttribute(MODULE_NAME, moduleName);
+    }
+
+    /** Get the name of the Module */
+    public String getModuleName() {
+        return (String) getAttribute(MODULE_NAME);
+    }
+
+    /** Get the count of modules */
+    public String getModuleCount() {
+        return (String) getAttribute(MODULE_COUNT);
+    }
+
+    /** Set the count of modules */
+    public void setModuleCount(String moduleName) {
+        setAttribute(MODULE_COUNT, moduleName);
+    }
+
+    /** Get the start time in msecs */
+    public Long getStartTime() {
+        return (Long) getAttribute(MODULE_START_TIME);
+    }
+
+    /** Set the start time in msecs */
+    public void setStartTime(Long startTime) {
+        setAttribute(MODULE_START_TIME, startTime);
+    }
+
+    /** Get the end time in msecs */
+    public Long getEndTime() {
+        return (Long) getAttribute(MODULE_END_TIME);
+    }
+
+    /** Set the end time in msecs */
+    public void setEndTime(Long endTime) {
+        setAttribute(MODULE_END_TIME, endTime);
+    }
+
+    /**
+     * Get the module loading time in msecs If the start or end time is not present then return -1
+     */
+    public Long getModuleDuration() {
+        if (null != getAttribute(MODULE_DURATION)) {
+            return (Long) getAttribute(MODULE_DURATION);
+        }
+        if (null != getAttribute(MODULE_END_TIME) && null != getAttribute(MODULE_START_TIME)) {
+            long duration = getEndTime() - getStartTime();
+            setModuleDuration(duration);
+            return duration;
+        }
+        return -1L;
+    }
+
+    /** Get the duration in msec */
+    public void setModuleDuration(Long duration) {
+        setAttribute(MODULE_DURATION, duration);
+    }
+
+    @Override
+    public String toString() {
+        return "ModuleInfoItem ["
+                + "getModuleName()="
+                + getModuleName()
+                + ", getStartTime()="
+                + getStartTime()
+                + ", getDuration()="
+                + getModuleDuration()
+                + "]";
+    }
+}
diff --git a/src/com/android/loganalysis/parser/DmesgParser.java b/src/com/android/loganalysis/parser/DmesgParser.java
index ffb6faa..53514d2 100644
--- a/src/com/android/loganalysis/parser/DmesgParser.java
+++ b/src/com/android/loganalysis/parser/DmesgParser.java
@@ -20,6 +20,7 @@ import com.android.loganalysis.item.DmesgActionInfoItem;
 import com.android.loganalysis.item.DmesgItem;
 import com.android.loganalysis.item.DmesgServiceInfoItem;
 import com.android.loganalysis.item.DmesgStageInfoItem;
+import com.android.loganalysis.item.DmesgModuleInfoItem;
 
 import com.google.common.annotations.VisibleForTesting;
 
@@ -44,6 +45,8 @@ public class DmesgParser implements IParser {
     private static final String DURATION = "DURATION";
     private static final String UEVENTD = "ueventd";
     private static final String INIT = "init";
+    private static final String WAIT_PROPERTY = "Wait for property ";
+    private static final String TOTAL_MODULE = "TOTAL_MODULE";
 
     // Matches: [ 14.822691] init:
     private static final String SERVICE_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] init:\\s+",
@@ -82,14 +85,34 @@ public class DmesgParser implements IParser {
     private static final Pattern START_PROCESSING_ACTION =
             Pattern.compile(String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX));
 
+    // Matches: [    1.175984] [    T1] init: Loaded 198 kernel modules took 808 ms
+    private static final Pattern MODULES_INFO =
+            Pattern.compile(
+                    String.format(
+                            "%sLoaded (?<count>\\d+) kernel modules took (?<%s>\\d+) ms.*$",
+                            SERVICE_PREFIX, DURATION));
+
+    // Matches: [    0.503853] [    T1] init: Loading module /lib/modules/exynos_dit.ko with args ''
+    private static final Pattern MODULE_LOADING =
+            Pattern.compile(
+                    String.format(
+                            "%sLoading module \\S+\\/(?<koname>\\S+)\\.ko with args.*",
+                            SERVICE_PREFIX));
+
+    // Matches: [    0.503803] [    T1] init: Loaded kernel module /lib/modules/boot_device_spi.ko
+    private static final Pattern MODULE_LOADED =
+            Pattern.compile(
+                    String.format(
+                            "%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 Pattern UEVENTD_STAGE_INFO = Pattern.compile(
             String.format("%s%s", UEVENTD_PREFIX, STAGE_SUFFIX));
 
-    private static final String PROPERTY_SUFFIX= String.format(
-            "(?<%s>.*)\\s+took\\s+(?<%s>.*)ms$", STAGE, DURATION);
+    private static final String PROPERTY_SUFFIX =
+            String.format("Wait for property\\s(?<%s>.*)\\s+took\\s+(?<%s>.*)ms$", STAGE, DURATION);
     // Matches [    7.270487] init: Wait for property 'apexd.status=ready' took 230ms
     private static final Pattern WAIT_FOR_PROPERTY_INFO = Pattern.compile(
             String.format("%s%s", SERVICE_PREFIX, PROPERTY_SUFFIX));
@@ -151,6 +174,9 @@ public class DmesgParser implements IParser {
         if (parseActionInfo(line)) {
             return;
         }
+        if (parseModuleInfo(line)) {
+            return;
+        }
     }
 
     /**
@@ -214,7 +240,8 @@ public class DmesgParser implements IParser {
         }
         if((match = matches(WAIT_FOR_PROPERTY_INFO, line)) != null) {
             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
-            stageInfoItem.setStageName(String.format("%s_%s", INIT, match.group(STAGE)));
+            stageInfoItem.setStageName(
+                    String.format("%s_%s%s", INIT, WAIT_PROPERTY, match.group(STAGE)));
             stageInfoItem.setDuration((long) Double.parseDouble(match.group(DURATION)));
             mDmesgItem.addStageInfoItem(stageInfoItem);
             return true;
@@ -249,6 +276,44 @@ 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
+     * @return {@code true}, if {@code line} indicates start, end of a module loading or the summary
+     *     {@code false}, otherwise
+     */
+    @VisibleForTesting
+    boolean parseModuleInfo(String line) {
+        Matcher match = null;
+        if ((match = matches(MODULES_INFO, line)) != null) {
+            DmesgModuleInfoItem moduleInfoItem = new DmesgModuleInfoItem();
+            moduleInfoItem.setModuleName(TOTAL_MODULE);
+            moduleInfoItem.setModuleDuration((long) Double.parseDouble(match.group(DURATION)));
+            moduleInfoItem.setModuleCount(match.group("count"));
+            mDmesgItem.addModuleInfoItem(TOTAL_MODULE, moduleInfoItem);
+            return true;
+        }
+
+        if ((match = matches(MODULE_LOADING, line)) != null) {
+            DmesgModuleInfoItem moduleInfoItem = new DmesgModuleInfoItem();
+            moduleInfoItem.setModuleName(match.group("koname"));
+            moduleInfoItem.setStartTime((long) (Double.parseDouble(match.group(TIMESTAMP)) * 1000));
+            mDmesgItem.addModuleInfoItem(match.group("koname"), moduleInfoItem);
+            return true;
+        } else if ((match = matches(MODULE_LOADED, line)) != null) {
+            if (getModuleInfoItems().containsKey(match.group("koname"))) {
+                DmesgModuleInfoItem moduleInfoItem =
+                        getModuleInfoItems().get(match.group("koname"));
+                moduleInfoItem.setEndTime(
+                        (long) (Double.parseDouble(match.group(TIMESTAMP)) * 1000));
+            }
+            return true;
+        }
+        return false;
+    }
+
+    /**
      * Checks whether {@code line} matches the given {@link Pattern}.
      *
      * @return The resulting {@link Matcher} obtained by matching the {@code line} against
@@ -277,4 +342,7 @@ public class DmesgParser implements IParser {
         return mDmesgItem.getActionInfoItems();
     }
 
+    public Map<String, DmesgModuleInfoItem> getModuleInfoItems() {
+        return mDmesgItem.getModuleInfoItems();
+    }
 }
\ No newline at end of file
diff --git a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
index 4362c7a..e4ea7af 100644
--- a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
+++ b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
@@ -20,6 +20,7 @@ import com.android.loganalysis.item.DmesgActionInfoItem;
 import com.android.loganalysis.item.DmesgItem;
 import com.android.loganalysis.item.DmesgServiceInfoItem;
 import com.android.loganalysis.item.DmesgStageInfoItem;
+import com.android.loganalysis.item.DmesgModuleInfoItem;
 import java.io.BufferedReader;
 import java.io.ByteArrayInputStream;
 import java.io.IOException;
@@ -38,8 +39,15 @@ public class DmesgParserTest extends TestCase {
 
     private static final String BOOT_ANIMATION = "bootanim";
     private static final String NETD = "netd";
+    private static final String FOO = "foo";
+    private static final String BAR = "bar";
+    private static final String TOTAL_MODULE = "TOTAL_MODULE";
     private static final String[] LINES =
             new String[] {
+                "[    0.370107] init: Loading module /lib/modules/foo.ko with args ''",
+                "[    0.372497] init: Loaded kernel module /lib/modules/foo.ko",
+                "[    0.372500] init: Loading module /lib/modules/bar.ko with args ''",
+                "[    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",
                 "[   22.962730] init: starting service 'bootanim'...",
@@ -50,12 +58,17 @@ public class DmesgParserTest extends TestCase {
                 "[   39.855818] init: Service 'bootanim' (pid 588) exited with status 0",
                 "[   41.665818] init: init first stage started!",
                 "[   44.942872] init: processing action (early-init) from (/init.rc:13)",
-                "[   47.233446] init: processing action (set_mmap_rnd_bits) from (<Builtin Action>:0)",
-                "[   47.240083] init: processing action (set_kptr_restrict) from (<Builtin Action>:0)",
+                "[   47.233446] init: processing action (set_mmap_rnd_bits) from (<Builtin "
+                        + "Action>:0)",
+                "[   47.240083] init: processing action (set_kptr_restrict) from (<Builtin"
+                        + " Action>:0)",
                 "[   47.245778] init: processing action (keychord_init) from (<Builtin Action>:0)",
-                "[   52.361049] init: processing action (persist.sys.usb.config=* boot) from (<Builtin Action>:0)",
-                "[   52.361108] init: processing action (enable_property_trigger) from (<Builtin Action>:0)",
-                "[   52.361313] init: processing action (security.perf_harden=1) from (/init.rc:677)",
+                "[   52.361049] init: processing action (persist.sys.usb.config=* boot) from"
+                        + " (<Builtin Action>:0)",
+                "[   52.361108] init: processing action (enable_property_trigger) from (<Builtin"
+                        + " Action>:0)",
+                "[   52.361313] init: processing action (security.perf_harden=1) from"
+                        + " (/init.rc:677)",
                 "[   52.361495] init: processing action (ro.debuggable=1) from (/init.rc:700)",
                 "[   58.298293] init: processing action (sys.boot_completed=1)",
                 "[   59.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA",
@@ -73,6 +86,9 @@ public class DmesgParserTest extends TestCase {
     private static final List<DmesgActionInfoItem> EXPECTED_ACTION_INFO_ITEMS =
             getExpectedActionInfoItems();
 
+    private static final Map<String, DmesgModuleInfoItem> EXPECTED_MODULE_INFO_ITEMS =
+            getExpectedModuleInfoItems();
+
     /**
      * Test for empty dmesg logs passed to the DmesgParser
      */
@@ -101,10 +117,15 @@ public class DmesgParserTest extends TestCase {
                 dmesgParser.getStageInfoItems().size());
         assertEquals("Action info items list size should be 9",9,
                 dmesgParser.getActionInfoItems().size());
+        assertEquals(
+                "Module info items list size should be 3",
+                3,
+                dmesgParser.getModuleInfoItems().size());
 
         assertEquals(EXPECTED_SERVICE_INFO_ITEMS, actualDmesgItem.getServiceInfoItems());
         assertEquals(EXPECTED_STAGE_INFO_ITEMS, actualDmesgItem.getStageInfoItems());
         assertEquals(EXPECTED_ACTION_INFO_ITEMS, actualDmesgItem.getActionInfoItems());
+        assertEquals(EXPECTED_MODULE_INFO_ITEMS, actualDmesgItem.getModuleInfoItems());
     }
 
     /**
@@ -121,6 +142,10 @@ public class DmesgParserTest extends TestCase {
                     dmesgParser.getStageInfoItems().size());
             assertEquals("Action info items list size should be 9",9,
                     dmesgParser.getActionInfoItems().size());
+            assertEquals(
+                    "Module info items list size should be 3",
+                    3,
+                    dmesgParser.getModuleInfoItems().size());
         }
     }
 
@@ -213,13 +238,30 @@ public class DmesgParserTest extends TestCase {
         assertEquals(EXPECTED_ACTION_INFO_ITEMS, actualActionInfoItems);
     }
 
+    /** Test incomplete module loaded pattern */
+    public void testIncompleteModuleInfo() {
+        DmesgParser dmesgParser = new DmesgParser();
+        for (String line : LINES) {
+            dmesgParser.parseModuleInfo(line);
+        }
+        List<DmesgModuleInfoItem> actualModuleInfoItems =
+                new ArrayList<>(dmesgParser.getModuleInfoItems().values());
+        assertEquals(EXPECTED_MODULE_INFO_ITEMS, dmesgParser.getModuleInfoItems());
+        assertEquals(3, actualModuleInfoItems.size());
+        assertEquals(
+                "Duration should be -1L",
+                Long.valueOf(-1L),
+                actualModuleInfoItems.get(0).getModuleDuration());
+    }
+
     private static List<DmesgActionInfoItem> getExpectedActionInfoItems() {
         return Arrays.asList(
                 new DmesgActionInfoItem("/init.rc:13", "early-init", 44942L),
                 new DmesgActionInfoItem("<Builtin Action>:0", "set_mmap_rnd_bits", 47233L),
                 new DmesgActionInfoItem("<Builtin Action>:0", "set_kptr_restrict", 47240L),
                 new DmesgActionInfoItem("<Builtin Action>:0", "keychord_init", 47245L),
-                new DmesgActionInfoItem("<Builtin Action>:0", "persist.sys.usb.config=* boot", 52361L),
+                new DmesgActionInfoItem(
+                        "<Builtin Action>:0", "persist.sys.usb.config=* boot", 52361L),
                 new DmesgActionInfoItem("<Builtin Action>:0", "enable_property_trigger", 52361L),
                 new DmesgActionInfoItem("/init.rc:677", "security.perf_harden=1", 52361L),
                 new DmesgActionInfoItem("/init.rc:700", "ro.debuggable=1", 52361L),
@@ -250,4 +292,26 @@ public class DmesgParserTest extends TestCase {
         return serviceInfoItemsMap;
     }
 
+    private static Map<String, DmesgModuleInfoItem> getExpectedModuleInfoItems() {
+        Map<String, DmesgModuleInfoItem> moduleInfoItemsMap = new HashMap<>();
+        DmesgModuleInfoItem fooModuleInfo = new DmesgModuleInfoItem();
+        fooModuleInfo.setModuleName(FOO);
+        fooModuleInfo.setStartTime(370L);
+        fooModuleInfo.setEndTime(372L);
+
+        DmesgModuleInfoItem barModuleInfo = new DmesgModuleInfoItem();
+        barModuleInfo.setModuleName(BAR);
+        barModuleInfo.setStartTime(372L);
+
+        DmesgModuleInfoItem totalInfoItem = new DmesgModuleInfoItem();
+        totalInfoItem.setModuleName(TOTAL_MODULE);
+        totalInfoItem.setModuleCount("198");
+        totalInfoItem.setModuleDuration(748L);
+
+        moduleInfoItemsMap.put(FOO, fooModuleInfo);
+        moduleInfoItemsMap.put(BAR, barModuleInfo);
+        moduleInfoItemsMap.put(TOTAL_MODULE, totalInfoItem);
+
+        return moduleInfoItemsMap;
+    }
 }