Added generic logcat timing parsing feature

Bug: 133166326
Test: build and run "tools/tradefederation/core/tests/run_tradefed_tests.sh
--class com.android.loganalysis.UnitTests"

Change-Id: Ica363ae379a551b51ca5f64eb62061e0c8baf903

2 files changed, 199 insertions, 2 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