Merge "Added generic logcat timing parsing feature"android-o-mr1-iot-release-1.0.14

3 files changed, 440 insertions, 6 deletions

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 @@ import java.util.regex.Pattern;
  * 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 @@ public class TimingsLogParser implements IParser {
                     + "\\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 @@ public class TimingsLogParser implements IParser {
                             "%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 @@ public class TimingsLogParser implements IParser {
     }
 
     /**
+     * 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.IOException;
 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 @@ public class TimingsLogParserTest extends TestCase {
                         "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 @@ public class TimingsLogParserTest extends TestCase {
     }
 
     /** 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 @@ public class TimingsLogParserTest extends TestCase {
                         "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());