Merge "Added generic logcat timing parsing feature"
diff --git a/src/com/android/loganalysis/item/GenericTimingItem.java b/src/com/android/loganalysis/item/GenericTimingItem.java
new file mode 100644
index 0000000..088d15b
--- /dev/null
+++ b/src/com/android/loganalysis/item/GenericTimingItem.java
@@ -0,0 +1,79 @@
+/*
+ * Copyright (C) 2019 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;
+
+public class GenericTimingItem extends GenericItem {
+ /** Constant for JSON output */
+ public static final String NAME = "NAME";
+ /** Constant for JSON output */
+ public static final String START_TIME = "START_TIME";
+ /** Constant for JSON output */
+ public static final String END_TIME = "END_TIME";
+
+ private static final Set<String> ATTRIBUTES =
+ new HashSet<>(Arrays.asList(NAME, END_TIME, START_TIME));
+
+ public GenericTimingItem() {
+ super(ATTRIBUTES);
+ }
+
+ protected GenericTimingItem(Set<String> attributes) {
+ super(getAllAttributes(attributes));
+ }
+
+ /** Get the name of the generic timing item */
+ public String getName() {
+ return (String) getAttribute(NAME);
+ }
+
+ /** Set the name of the generic timing item */
+ public void setName(String name) {
+ setAttribute(NAME, name);
+ }
+
+ /** Get the duration value for the generic timing, it is timestamp in milliseconds */
+ public Double getDuration() {
+ return (Double) getAttribute(END_TIME) - (Double) getAttribute(START_TIME);
+ }
+
+ /** Get the start time value for the generic timing, it is timestamp in milliseconds */
+ public Double getStartTime() {
+ return (Double) getAttribute(START_TIME);
+ }
+
+ /** Get the end time value for the generic timing, it is timestamp in milliseconds */
+ public Double getEndTime() {
+ return (Double) getAttribute(END_TIME);
+ }
+
+ /** Set the start and end time value for the generic timing, it is timestamp in milliseconds */
+ public void setStartAndEnd(double startTime, double endTime) {
+ setAttribute(START_TIME, startTime);
+ setAttribute(END_TIME, endTime);
+ }
+
+ /** Combine an array of attributes with the internal list of attributes. */
+ private static Set<String> getAllAttributes(Set<String> attributes) {
+ Set<String> allAttributes = new HashSet<String>(ATTRIBUTES);
+ allAttributes.addAll(attributes);
+ return allAttributes;
+ }
+}
diff --git a/src/com/android/loganalysis/parser/TimingsLogParser.java b/src/com/android/loganalysis/parser/TimingsLogParser.java
index 2bafd30..ee3535f 100644
--- a/src/com/android/loganalysis/parser/TimingsLogParser.java
+++ b/src/com/android/loganalysis/parser/TimingsLogParser.java
@@ -16,14 +16,21 @@
package com.android.loganalysis.parser;
+
+import com.android.loganalysis.item.GenericTimingItem;
import com.android.loganalysis.item.IItem;
import com.android.loganalysis.item.SystemServicesTimingItem;
import java.io.BufferedReader;
import java.io.IOException;
+import java.text.DateFormat;
+import java.text.ParseException;
+import java.text.SimpleDateFormat;
import java.util.ArrayList;
+import java.util.HashMap;
import java.util.HashSet;
import java.util.List;
+import java.util.Map;
import java.util.Set;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
@@ -33,8 +40,6 @@
* logcat. It will parse duration metrics for some system services like System Server, Zygote,
* System UI, e.t.c.
*
- * <p>TODO(b/133166326): Add support for parsing thread time info from log lines, and also support
- * dynamically adding new log line patterns.
*/
public class TimingsLogParser implements IParser {
@@ -43,6 +48,16 @@
+ "\\d*\\s*\\d*\\s*D\\s*(?<componentname>.*):\\s*(?<subname>\\S*)\\s*";
private static final String SYSTEM_SERVICES_TIME_SUFFIX = ":\\s*(?<time>.*)ms\\s*$";
+ /** Used to parse time info from logcat lines */
+ private static final DateFormat DEFAULT_TIME_FORMAT =
+ new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
+
+ /**
+ * Year is not important in timing info. Always use Unix time starting year for timestamp
+ * conversion with simplicity
+ */
+ private static final String DEFAULT_YEAR = "1970";
+
/**
* Match the line with system services duration info like:
*
@@ -65,6 +80,20 @@
"%sstart time%s",
SYSTEM_SERVICES_TIME_PREFIX, SYSTEM_SERVICES_TIME_SUFFIX));
+ private List<DurationPattern> durationPatterns = new ArrayList<>();
+
+ private static class DurationPattern {
+ String mName;
+ Pattern mStartTimePattern;
+ Pattern mEndTimePattern;
+
+ DurationPattern(String name, Pattern startTimePattern, Pattern endTimePattern) {
+ mName = name;
+ mStartTimePattern = startTimePattern;
+ mEndTimePattern = endTimePattern;
+ }
+ }
+
@Override
public IItem parse(List<String> lines) {
throw new UnsupportedOperationException(
@@ -72,6 +101,95 @@
}
/**
+ * Add a pair of patterns matching the start and end signals in logcat for a duration metric
+ *
+ * @param name the name of the duration metric, it should be unique
+ * @param startTimePattern the pattern matches the logcat line indicating start of duration
+ * @param endTimePattern the pattern matches the logcat line indicating end of duration
+ */
+ public void addDurationPatternPair(
+ String name, Pattern startTimePattern, Pattern endTimePattern) {
+ DurationPattern durationPattern =
+ new DurationPattern(name, startTimePattern, endTimePattern);
+ durationPatterns.add(durationPattern);
+ }
+
+ /** Cleanup added duration patterns */
+ public void clearDurationPatterns() {
+ durationPatterns.clear();
+ }
+
+ /**
+ * Parse logcat lines with the added duration patterns and generate a list of {@link
+ * GenericTimingItem} representing the duration items. Note, a duration pattern could have zero
+ * or multiple matches
+ *
+ * @param input logcat lines
+ * @return list of {@link GenericTimingItem}
+ * @throws IOException
+ */
+ public List<GenericTimingItem> parseGenericTimingItems(BufferedReader input)
+ throws IOException {
+ List<GenericTimingItem> items = new ArrayList<>();
+ String line;
+ //Timing items that are partially matched after captured start time
+ Map<String, Double> pendingItems = new HashMap<>();
+ while ((line = input.readLine()) != null) {
+ items.addAll(parseGenericTimingItem(line, pendingItems));
+ }
+ return items;
+ }
+
+ /**
+ * Parse a particular logcat line to get duration items. One line could have be matched by
+ * multiple patterns
+ *
+ * @param line logcat line
+ * @param pendingItems timing items that are half-matched with only start time.
+ * @return list of {@link GenericTimingItem}
+ */
+ private List<GenericTimingItem> parseGenericTimingItem(
+ String line, Map<String, Double> pendingItems) {
+ List<GenericTimingItem> items = new ArrayList<>();
+ for (DurationPattern durationPattern : durationPatterns) {
+ Matcher matcher = durationPattern.mStartTimePattern.matcher(line);
+ if (matcher.find()) {
+ double startTimeMillis = parseTime(line);
+ pendingItems.put(durationPattern.mName, startTimeMillis);
+ continue;
+ }
+ matcher = durationPattern.mEndTimePattern.matcher(line);
+ if (matcher.find()) {
+ double endTimeMillis = parseTime(line);
+ Double startTimeMillis = pendingItems.get(durationPattern.mName);
+ if (startTimeMillis != null) {
+ GenericTimingItem newItem = new GenericTimingItem();
+ newItem.setName(durationPattern.mName);
+ newItem.setStartAndEnd(startTimeMillis, endTimeMillis);
+ items.add(newItem);
+ pendingItems.remove(durationPattern.mName);
+ }
+ }
+ }
+ return items;
+ }
+
+ /**
+ * Get timestamp of current logcat line based on DEFAULT_YEAR
+ *
+ * @param line logcat line
+ * @return timestamp
+ */
+ private double parseTime(String line) {
+ String timeStr = String.format("%s-%s", DEFAULT_YEAR, line);
+ try {
+ return DEFAULT_TIME_FORMAT.parse(timeStr).getTime();
+ } catch (ParseException e) {
+ throw new RuntimeException(e);
+ }
+ }
+
+ /**
* A method that parses the logcat input for system services timing information. It will ignore
* duplicated log lines and will keep multiple values for the same timing metric generated at
* different time in the log
diff --git a/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java b/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java
index f4a0733..48881ea 100644
--- a/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java
+++ b/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java
@@ -16,6 +16,7 @@
package com.android.loganalysis.parser;
+import com.android.loganalysis.item.GenericTimingItem;
import com.android.loganalysis.item.SystemServicesTimingItem;
import junit.framework.TestCase;
@@ -26,12 +27,248 @@
import java.io.InputStream;
import java.io.InputStreamReader;
import java.util.List;
+import java.util.regex.Pattern;
/** Unit Test for {@link TimingsLogParser} */
public class TimingsLogParserTest extends TestCase {
+ private TimingsLogParser mParser;
+
+ public TimingsLogParserTest() {
+ mParser = new TimingsLogParser();
+ }
+
+ public void testParseGenericTiming_noPattern() throws IOException {
+ // Test when input is empty
+ String log = "";
+ List<GenericTimingItem> items = mParser.parseGenericTimingItems(createBufferedReader(log));
+ assertNotNull(items);
+ assertEquals(0, items.size());
+ // Test when input is not empty
+ log =
+ String.join(
+ "\n",
+ "01-17 01:22:39.513 0 0 I CPU features: detected feature: GIC system register CPU interface",
+ "01-17 01:22:39.513 0 0 I CPU features: kernel page table isolation forced ON by command line option",
+ "01-17 01:22:39.513 0 0 I CPU features: detected feature: 32-bit EL0 Support",
+ "01-17 01:22:59.823 0 0 I init : Service 'bootanim' (pid 1030) exited with status 0",
+ "01-17 01:22:59.966 0 0 I init : processing action (sys.boot_completed=1) from (/init.rc:796)");
+ items = mParser.parseGenericTimingItems(createBufferedReader(log));
+ assertNotNull(items);
+ assertEquals(0, items.size());
+ }
+
+ public void testParseGenericTiming_multiplePattern_oneOccurrenceEach() throws IOException {
+ String log =
+ String.join(
+ "\n",
+ "01-17 01:22:39.503 0 0 I : Linux version 4.4.177 (Kernel Boot Started)",
+ "01-17 01:22:39.513 0 0 I CPU features: detected feature: GIC system register CPU interface",
+ "01-17 01:22:39.513 0 0 I CPU features: kernel page table isolation forced ON by command line option",
+ "01-17 01:22:39.513 0 0 I CPU features: detected feature: 32-bit EL0 Support",
+ "01-17 01:22:43.634 0 0 I init : starting service 'zygote'...",
+ "01-17 01:22:48.634 0 0 I init : 'zygote' started",
+ "01-17 01:22:53.392 0 0 I init : starting service 'fake service'",
+ "01-17 01:22:59.823 0 0 I init : Service 'bootanim' (pid 1030) exited with status 0",
+ "01-17 01:22:60.334 0 0 I init : 'fake service' started",
+ "01-17 01:22:61.362 938 1111 I ActivityManager: my app started",
+ "01-17 01:22:61.977 938 1111 I ActivityManager: my app displayed");
+
+ mParser.addDurationPatternPair(
+ "BootToAnimEnd",
+ Pattern.compile("Linux version"),
+ Pattern.compile("Service 'bootanim'"));
+ mParser.addDurationPatternPair(
+ "ZygoteStartTime",
+ Pattern.compile("starting service 'zygote'"),
+ Pattern.compile("'zygote' started"));
+ mParser.addDurationPatternPair(
+ "FakeServiceStartTime",
+ Pattern.compile("starting service 'fake service'"),
+ Pattern.compile("'fake service' started"));
+ mParser.addDurationPatternPair(
+ "BootToAppStart",
+ Pattern.compile("Linux version"),
+ Pattern.compile("my app displayed"));
+ mParser.addDurationPatternPair(
+ "AppStartTime",
+ Pattern.compile("my app started"),
+ Pattern.compile("my app displayed"));
+ mParser.addDurationPatternPair(
+ "ZygoteToApp",
+ Pattern.compile("'zygote' started"),
+ Pattern.compile("my app started"));
+ List<GenericTimingItem> items = mParser.parseGenericTimingItems(createBufferedReader(log));
+ assertNotNull(items);
+ assertEquals(6, items.size());
+ // 1st item
+ assertEquals("ZygoteStartTime", items.get(0).getName());
+ assertEquals(5000.0, items.get(0).getDuration());
+ // 2nd item
+ assertEquals("BootToAnimEnd", items.get(1).getName());
+ assertEquals(20320.0, items.get(1).getDuration());
+ // 3rd item
+ assertEquals("FakeServiceStartTime", items.get(2).getName());
+ assertEquals(6942.0, items.get(2).getDuration());
+ // 4th item
+ assertEquals("ZygoteToApp", items.get(3).getName());
+ assertEquals(12728.0, items.get(3).getDuration());
+ // 5th item
+ assertEquals("BootToAppStart", items.get(4).getName());
+ assertEquals(22474.0, items.get(4).getDuration());
+ // 6th item
+ assertEquals("AppStartTime", items.get(5).getName());
+ assertEquals(615.0, items.get(5).getDuration());
+ }
+
+ public void testParseGenericTiming_multiplePattern_someNotMatched() throws IOException {
+ String log =
+ String.join(
+ "\n",
+ "01-17 01:22:39.503 0 0 I : Linux version 4.4.177 (Kernel Boot Started)",
+ "01-17 01:22:39.513 0 0 I CPU features: detected feature: GIC system register CPU interface",
+ "01-17 01:22:39.513 0 0 I CPU features: kernel page table isolation forced ON by command line option",
+ "01-17 01:22:39.513 0 0 I CPU features: detected feature: 32-bit EL0 Support",
+ "01-17 01:22:43.634 0 0 I init : starting service 'zygote'...",
+ "01-17 01:22:48.634 0 0 I init : 'zygote' started",
+ "01-17 01:22:53.392 0 0 I init : starting service 'fake service'",
+ "01-17 01:22:59.823 0 0 I init : Service 'bootanim' (pid 1030) exited with status 0",
+ "01-17 01:22:60.334 0 0 I init : 'fake service' started",
+ "01-17 01:22:61.362 938 1111 I ActivityManager: my app started",
+ "01-17 01:22:61.977 938 1111 I ActivityManager: my app displayed");
+
+ mParser.addDurationPatternPair(
+ "BootToAnimEnd",
+ Pattern.compile("Linux version"),
+ Pattern.compile("Service 'bootanim'"));
+ mParser.addDurationPatternPair(
+ "ZygoteStartTime",
+ Pattern.compile("starting service 'zygote'"),
+ Pattern.compile("End line no there"));
+ mParser.addDurationPatternPair(
+ "FakeServiceStartTime",
+ Pattern.compile("Start line not there"),
+ Pattern.compile("'fake service' started"));
+ mParser.addDurationPatternPair(
+ "AppStartTime",
+ Pattern.compile("Start line not there"),
+ Pattern.compile("End line not there"));
+
+ List<GenericTimingItem> items = mParser.parseGenericTimingItems(createBufferedReader(log));
+ assertNotNull(items);
+ assertEquals(1, items.size());
+ assertEquals("BootToAnimEnd", items.get(0).getName());
+ }
+
+ public void testParseGenericTiming_clearExistingPatterns() throws IOException {
+ String log =
+ String.join(
+ "\n",
+ "01-17 01:22:39.503 0 0 I : Linux version 4.4.177 (Kernel Boot Started)",
+ "01-17 01:22:53.392 0 0 I init : starting service 'fake service'",
+ "01-17 01:22:59.823 0 0 I init : Service 'bootanim' (pid 1030) exited with status 0",
+ "01-17 01:22:60.334 0 0 I init : 'fake service' started",
+ "01-17 01:22:61.362 938 1111 I ActivityManager: my app started",
+ "01-17 01:22:61.977 938 1111 I ActivityManager: my app displayed");
+ mParser.addDurationPatternPair(
+ "BootToAnimEnd",
+ Pattern.compile("Linux version"),
+ Pattern.compile("Service 'bootanim'"));
+ List<GenericTimingItem> items = mParser.parseGenericTimingItems(createBufferedReader(log));
+ assertNotNull(items);
+ assertEquals(1, items.size());
+
+ mParser.clearDurationPatterns();
+ items = mParser.parseGenericTimingItems(createBufferedReader(log));
+ assertNotNull(items);
+ assertEquals(0, items.size());
+ }
+
+ public void testParseGenericTiming_multiplePattern_multipleOccurrence() throws IOException {
+ String log =
+ String.join(
+ "\n",
+ "01-17 01:22:39.503 0 0 I : Linux version 4.4.177 (Kernel Boot Started)",
+ "01-17 01:22:39.513 0 0 I CPU features: detected feature: GIC system register CPU interface",
+ "01-17 01:22:39.513 0 0 I CPU features: kernel page table isolation forced ON by command line option",
+ "01-17 01:22:39.513 0 0 I CPU features: detected feature: 32-bit EL0 Support",
+ "01-17 01:22:43.634 0 0 I init : starting service 'zygote'...",
+ "01-17 01:22:48.634 0 0 I init : 'zygote' started",
+ "01-17 01:22:53.392 0 0 I init : starting service 'fake service'",
+ "01-17 01:22:59.823 0 0 I init : 'bootanim' not reported",
+ "01-17 01:22:60.334 0 0 I init : 'fake service' started",
+ "01-17 01:32:39.503 0 0 I : Linux version 4.4.177 (Kernel Boot Started)",
+ "01-17 01:32:39.513 0 0 I CPU features: detected feature: GIC system register CPU interface",
+ "01-17 01:32:39.513 0 0 I CPU features: kernel page table isolation forced ON by command line option",
+ "01-17 01:32:39.513 0 0 I CPU features: detected feature: 32-bit EL0 Support",
+ "01-17 01:32:43.634 0 0 I init : starting service 'zygote'...",
+ "01-17 01:32:48.634 0 0 I init : 'zygote' started",
+ "01-17 01:32:53.392 0 0 I init : starting service 'a different service'",
+ "01-17 01:32:59.823 0 0 I init : Service 'bootanim' (pid 1030) exited with status 0",
+ "01-17 01:32:60.334 0 0 I init : 'fake service' started",
+ "01-17 01:32:61.362 938 1111 I ActivityManager: my app started",
+ "01-17 01:32:61.977 938 1111 I ActivityManager: my app displayed");
+
+ mParser.addDurationPatternPair(
+ "BootToAnimEnd",
+ Pattern.compile("Linux version"),
+ Pattern.compile("Service 'bootanim'"));
+ mParser.addDurationPatternPair(
+ "ZygoteStartTime",
+ Pattern.compile("starting service 'zygote'"),
+ Pattern.compile("'zygote' started"));
+ mParser.addDurationPatternPair(
+ "FakeServiceStartTime",
+ Pattern.compile("starting service 'fake service'"),
+ Pattern.compile("'fake service' started"));
+ mParser.addDurationPatternPair(
+ "AppStartTime",
+ Pattern.compile("my app started"),
+ Pattern.compile("my app displayed"));
+ List<GenericTimingItem> items = mParser.parseGenericTimingItems(createBufferedReader(log));
+ assertNotNull(items);
+ assertEquals(5, items.size());
+ // 1st item
+ assertEquals("ZygoteStartTime", items.get(0).getName());
+ assertEquals(5000.0, items.get(0).getDuration());
+ // 2nd item
+ assertEquals("FakeServiceStartTime", items.get(1).getName());
+ assertEquals(6942.0, items.get(1).getDuration());
+ // 3rd item
+ assertEquals("ZygoteStartTime", items.get(2).getName());
+ assertEquals(5000.0, items.get(2).getDuration());
+ // 4th item
+ assertEquals("BootToAnimEnd", items.get(3).getName());
+ assertEquals(20320.0, items.get(3).getDuration());
+ // 5th item
+ assertEquals("AppStartTime", items.get(4).getName());
+ assertEquals(615.0, items.get(4).getDuration());
+ }
+
+ public void testParseGenericTiming_wrongTimeFormat() throws IOException {
+ String log =
+ String.join(
+ "\n",
+ "1234252.234 0 0 I : Linux version 4.4.177 (Kernel Boot Started)",
+ "1234259.342 0 0 I CPU features: detected feature: GIC system register CPU interface");
+ mParser.addDurationPatternPair(
+ "BootToAnimEnd",
+ Pattern.compile("Linux version"),
+ Pattern.compile("Service 'bootanim'"));
+ try {
+ List<GenericTimingItem> items =
+ mParser.parseGenericTimingItems(createBufferedReader(log));
+ } catch (RuntimeException e) {
+ assertTrue(
+ "Test should report ParseException",
+ e.getCause().toString().startsWith("java.text.ParseException"));
+ return;
+ }
+ fail("Test should throw ParseException");
+ }
+
/** Test that system services duration can be parsed as expected */
- public void testParseSystemServicesTimingInfo_system_services_duration() throws IOException {
+ public void testParseSystemServicesTiming_system_services_duration() throws IOException {
String log =
String.join(
"\n",
@@ -51,7 +288,7 @@
"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
List<SystemServicesTimingItem> items =
- new TimingsLogParser().parseSystemServicesTimingItems(createBufferedReader(log));
+ mParser.parseSystemServicesTimingItems(createBufferedReader(log));
assertNotNull(items);
assertEquals(6, items.size());
assertEquals("SystemServerTiming", items.get(0).getComponent());
@@ -74,7 +311,7 @@
}
/** Test that system services start time can be parsed as expected */
- public void testParse_system_services_start_time() throws IOException {
+ public void testParseSystemServicesTiming_system_services_start_time() throws IOException {
String log =
String.join(
"\n",
@@ -91,7 +328,7 @@
"06-06 19:23:59.299 179 179 D FakeService : Validstart time: 34839ms");
List<SystemServicesTimingItem> items =
- new TimingsLogParser().parseSystemServicesTimingItems(createBufferedReader(log));
+ mParser.parseSystemServicesTimingItems(createBufferedReader(log));
assertNotNull(items);
assertEquals(4, items.size());
assertEquals("BootAnimation", items.get(0).getComponent());
