diff options
author | Android Build Coastguard Worker <android-build-coastguard-worker@google.com> | 2023-07-07 05:14:30 +0000 |
---|---|---|
committer | Android Build Coastguard Worker <android-build-coastguard-worker@google.com> | 2023-07-07 05:14:30 +0000 |
commit | d7eb2f58a59ed3cc377797b81448cbe3bc8fb946 (patch) | |
tree | b4b31b522dc65628f02c9bb21f346636c86f3a9b | |
parent | bfcdff0b140b1a6bb4f6f059cc0231ec6bdac0f0 (diff) | |
parent | 1ed1e0c89b5956db27834f9339bd9149a53034d0 (diff) | |
download | loganalysis-android14-mainline-os-statsd-release.tar.gz |
Snap for 10453563 from 1ed1e0c89b5956db27834f9339bd9149a53034d0 to mainline-os-statsd-releaseaml_sta_341615000aml_sta_341511040aml_sta_341410000aml_sta_341311010aml_sta_341114000aml_sta_341111000aml_sta_341010020aml_sta_340912000aml_sta_340911000aml_net_341111030android14-mainline-os-statsd-release
Change-Id: Ic2c0b496d4ab4620789bff7cd66b8e877befbf5e
-rw-r--r-- | Android.bp | 2 | ||||
-rw-r--r-- | javatests/com/android/loganalysis/parser/DmesgParserTest.java | 38 | ||||
-rw-r--r-- | javatests/com/android/loganalysis/parser/TimingsLogParserTest.java | 30 | ||||
-rw-r--r-- | src/com/android/loganalysis/item/DvmLockSampleItem.java | 22 | ||||
-rw-r--r-- | src/com/android/loganalysis/parser/DmesgParser.java | 81 | ||||
-rw-r--r-- | src/com/android/loganalysis/parser/TimingsLogParser.java | 2 |
6 files changed, 119 insertions, 56 deletions
@@ -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 = |