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
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 @@
private List<DmesgActionInfoItem> mActionInfoItems = new ArrayList<>();
+ private Map<String, DmesgModuleInfoItem> mModuleInfoItems = new HashMap<>();
+
public DmesgItem() {
super(Collections.emptySet());
}
@@ -80,4 +82,16 @@
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.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 @@
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 @@
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 @@
if (parseActionInfo(line)) {
return;
}
+ if (parseModuleInfo(line)) {
+ return;
+ }
}
/**
@@ -214,7 +240,8 @@
}
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 @@
}
/**
+ * 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 @@
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.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 @@
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 @@
"[ 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 @@
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 @@
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 @@
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 @@
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 @@
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;
+ }
}
