From c7bcaba872c7d82286960c750edd67e56ee73712 Mon Sep 17 00:00:00 2001
From: Kimberly Kreider <kkreider@google.com>
Date: Thu, 14 Nov 2019 15:11:53 -0800
Subject: DO NOT MERGE: Adding required loganalysis changes for tradefed merge
 into qt-dev.

Bug: 143908003
Change-Id: Ib3436a42b2ca8c9614939a30fb548ab39bc23e57
Exclude merging into *-plus-aosp branches, since they already include the change.
Merged-In: I2ae86ba9706747873268192988c32879005ed0f7
Merged-In: I38efc115f2c691754d481fdffb6630607ef970e8
---
 .../loganalysis/item/DmesgActionInfoItem.java      |  28 ++-
 .../loganalysis/item/GenericTimingItem.java        |  79 +++++++
 .../loganalysis/item/SystemServicesTimingItem.java |  84 +++++++
 .../android/loganalysis/parser/DmesgParser.java    |  21 +-
 .../loganalysis/parser/TimingsLogParser.java       | 246 +++++++++++++++++++++
 5 files changed, 441 insertions(+), 17 deletions(-)
 create mode 100644 src/com/android/loganalysis/item/GenericTimingItem.java
 create mode 100644 src/com/android/loganalysis/item/SystemServicesTimingItem.java
 create mode 100644 src/com/android/loganalysis/parser/TimingsLogParser.java

(limited to 'src/com/android/loganalysis')

diff --git a/src/com/android/loganalysis/item/DmesgActionInfoItem.java b/src/com/android/loganalysis/item/DmesgActionInfoItem.java
index ac73b8e..482b426 100644
--- a/src/com/android/loganalysis/item/DmesgActionInfoItem.java
+++ b/src/com/android/loganalysis/item/DmesgActionInfoItem.java
@@ -26,13 +26,15 @@ import java.util.Set;
  */
 public class DmesgActionInfoItem extends GenericItem {
 
+    /** Constant for JSON output */
+    public static final String SOURCE_NAME = "SOURCE_NAME";
     /** Constant for JSON output */
     public static final String ACTION_NAME = "ACTION_NAME";
     /** Constant for JSON output */
     public static final String ACTION_START_TIME = "ACTION_START_TIME";
 
     private static final Set<String> ATTRIBUTES = new HashSet<String>(Arrays.asList(
-            ACTION_NAME, ACTION_START_TIME));
+            SOURCE_NAME, ACTION_NAME, ACTION_START_TIME));
 
     /**
      * The constructor for {@link DmesgActionInfoItem}.
@@ -44,12 +46,27 @@ public class DmesgActionInfoItem extends GenericItem {
     /**
      * The constructor for {@link DmesgActionInfoItem}.
      */
-    public DmesgActionInfoItem(String name, Long startTime) {
+    public DmesgActionInfoItem(String source, String name, Long startTime) {
         super(ATTRIBUTES);
+        setAttribute(SOURCE_NAME, source);
         setAttribute(ACTION_NAME, name);
         setAttribute(ACTION_START_TIME, startTime);
     }
 
+    /**
+     * Get the name of the source
+     */
+    public String getSourceName() {
+        return (String) getAttribute(SOURCE_NAME);
+    }
+
+    /**
+     * Set the name of the source
+     */
+    public void setSourceName(String sourceName) {
+        setAttribute(SOURCE_NAME, sourceName);
+    }
+
     /**
      * Get the name of the action
      */
@@ -80,8 +97,11 @@ public class DmesgActionInfoItem extends GenericItem {
 
     @Override
     public String toString() {
-        return "ActionInfoItem [getActionName()=" + getActionName() + ", getStartTime()="
-                + getStartTime() + "]";
+        return "ActionInfoItem ["
+                + "getSourceName()=" + getSourceName()
+                + ", getActionName()=" + getActionName()
+                + ", getStartTime()=" + getStartTime()
+                + "]";
     }
 
 }
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/item/SystemServicesTimingItem.java b/src/com/android/loganalysis/item/SystemServicesTimingItem.java
new file mode 100644
index 0000000..79671a2
--- /dev/null
+++ b/src/com/android/loganalysis/item/SystemServicesTimingItem.java
@@ -0,0 +1,84 @@
+/*
+ * 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;
+
+/**
+ * An {@link IItem} used to store timing information for system services like System Server, Zygote,
+ * System UI, BootAnimation e.t.c.
+ */
+public class SystemServicesTimingItem extends GenericItem {
+    /** Constant for JSON output */
+    public static final String COMPONENT = "COMPONENT";
+    /** Constant for JSON output */
+    public static final String SUBCOMPONENT = "SUBCOMPONENT";
+    /** Constant for JSON output */
+    public static final String DURATION = "DURATION";
+    /** Constant for JSON output */
+    public static final String START_TIME = "START_TIME";
+
+    private static final Set<String> ATTRIBUTES =
+            new HashSet<>(Arrays.asList(COMPONENT, SUBCOMPONENT, DURATION, START_TIME));
+
+    /** Constructor for {@link SystemServicesTimingItem} */
+    public SystemServicesTimingItem() {
+        super(ATTRIBUTES);
+    }
+
+    /** Get the component name for system services timing */
+    public String getComponent() {
+        return (String) getAttribute(COMPONENT);
+    }
+
+    /** Set the component name for system service timing */
+    public void setComponent(String component) {
+        setAttribute(COMPONENT, component);
+    }
+
+    /** Get the sub-component name for system service timing */
+    public String getSubcomponent() {
+        return (String) getAttribute(SUBCOMPONENT);
+    }
+
+    /** Set the sub-component name for system service timing */
+    public void setSubcomponent(String subcomponent) {
+        setAttribute(SUBCOMPONENT, subcomponent);
+    }
+
+    /** Get the duration value for system service timing */
+    public Double getDuration() {
+        return (Double) getAttribute(DURATION);
+    }
+
+    /** Set the duration value for system service timing */
+    public void setDuration(double duration) {
+        setAttribute(DURATION, duration);
+    }
+
+    /** Get the start time value for system service timing */
+    public Double getStartTime() {
+        return (Double) getAttribute(START_TIME);
+    }
+
+    /** Set the start time value for system service timing */
+    public void setStartTime(double startTime) {
+        setAttribute(START_TIME, startTime);
+    }
+}
diff --git a/src/com/android/loganalysis/parser/DmesgParser.java b/src/com/android/loganalysis/parser/DmesgParser.java
index be292ff..9fce9b8 100644
--- a/src/com/android/loganalysis/parser/DmesgParser.java
+++ b/src/com/android/loganalysis/parser/DmesgParser.java
@@ -40,6 +40,7 @@ public class DmesgParser implements IParser {
     private static final String TIMESTAMP = "TIMESTAMP";
     private static final String STAGE = "STAGE";
     private static final String ACTION = "ACTION";
+    private static final String SOURCE = "SOURCE";
     private static final String DURATION = "DURATION";
     private static final String UEVENTD = "ueventd";
     private static final String INIT = "init";
@@ -74,21 +75,13 @@ public class DmesgParser implements IParser {
 
     // Matches: init: processing action (early-init) from (/init.rc:14)
     private static final String START_PROCESSING_ACTION_PREFIX =
-            String.format("processing action \\((?<%s>.*)\\) from.*$", ACTION);
-
-    // Matches: init: processing action (early-init)
-    private static final String START_PROCESSING_ACTION_PREFIX_LEGACY =
-            String.format("processing action \\((?<%s>.*)\\).*$", ACTION);
+            String.format("processing action \\((?<%s>[^)]*)\\)( from \\((?<%s>.*)\\)|.*)$",
+                    ACTION, SOURCE);
 
     // Matches: init: processing action (early-init) from (/init.rc:14)
     private static final Pattern START_PROCESSING_ACTION =
             Pattern.compile(String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX));
 
-    // Matches: init: processing action (early-init)
-    private static final Pattern START_PROCESSING_ACTION_LEGACY =
-            Pattern.compile(
-                    String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX_LEGACY));
-
     // 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);
@@ -242,9 +235,11 @@ public class DmesgParser implements IParser {
     @VisibleForTesting
     boolean parseActionInfo(String line) {
         Matcher match = null;
-        if ((match = matches(START_PROCESSING_ACTION, line)) != null
-                || (match = matches(START_PROCESSING_ACTION_LEGACY, line)) != null) {
+        if ((match = matches(START_PROCESSING_ACTION, line)) != null) {
             DmesgActionInfoItem actionInfoItem = new DmesgActionInfoItem();
+            if (match.group(SOURCE) != null) {
+                actionInfoItem.setSourceName(match.group(SOURCE));
+            }
             actionInfoItem.setActionName(match.group(ACTION));
             actionInfoItem.setStartTime((long) (Double.parseDouble(
                     match.group(TIMESTAMP)) * 1000));
@@ -283,4 +278,4 @@ public class DmesgParser implements IParser {
         return mDmesgItem.getActionInfoItems();
     }
 
-}
+}
\ No newline at end of file
diff --git a/src/com/android/loganalysis/parser/TimingsLogParser.java b/src/com/android/loganalysis/parser/TimingsLogParser.java
new file mode 100644
index 0000000..ee3535f
--- /dev/null
+++ b/src/com/android/loganalysis/parser/TimingsLogParser.java
@@ -0,0 +1,246 @@
+/*
+ * 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.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;
+
+/**
+ * An {@link IParser} to parse boot metrics from logcat. It currently assumes "threadtime" format of
+ * logcat. It will parse duration metrics for some system services like System Server, Zygote,
+ * System UI, e.t.c.
+ *
+ */
+public class TimingsLogParser implements IParser {
+
+    private static final String SYSTEM_SERVICES_TIME_PREFIX =
+            "^\\d*-\\d*\\s*\\d*:\\d*:\\d*.\\d*\\s*"
+                    + "\\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:
+     *
+     * <p>03-10 21:43:40.328 1005 1005 D SystemServerTiming:
+     * StartKeyAttestationApplicationIdProviderService took to complete: 3474ms
+     */
+    private static final Pattern SYSTEM_SERVICES_DURATION =
+            Pattern.compile(
+                    String.format(
+                            "%stook to complete%s",
+                            SYSTEM_SERVICES_TIME_PREFIX, SYSTEM_SERVICES_TIME_SUFFIX));
+    /**
+     * Match the line with system services start time info like:
+     *
+     * <p>01-10 01:25:57.249 989 989 D BootAnimation: BootAnimationStartTiming start time: 8343ms
+     */
+    private static final Pattern SYSTEM_SERVICES_START_TIME =
+            Pattern.compile(
+                    String.format(
+                            "%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(
+                "Method has not been implemented in lieu of others");
+    }
+
+    /**
+     * 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
+     *
+     * @param input Logcat input as a {@link BufferedReader}
+     * @return a list of {@link SystemServicesTimingItem}
+     * @throws IOException
+     */
+    public List<SystemServicesTimingItem> parseSystemServicesTimingItems(BufferedReader input)
+            throws IOException {
+        Set<String> matchedLines = new HashSet<>();
+        List<SystemServicesTimingItem> items = new ArrayList<>();
+        String line;
+        while ((line = input.readLine()) != null) {
+            if (matchedLines.contains(line)) {
+                continue;
+            }
+            SystemServicesTimingItem item = parseSystemServicesTimingItem(line);
+            if (item == null) {
+                continue;
+            }
+            items.add(item);
+            matchedLines.add(line);
+        }
+        return items;
+    }
+
+    /**
+     * Parse a particular log line to see if it matches the system service timing pattern and return
+     * a {@link SystemServicesTimingItem} if matches, otherwise return null.
+     *
+     * @param line a single log line
+     * @return a {@link SystemServicesTimingItem}
+     */
+    private SystemServicesTimingItem parseSystemServicesTimingItem(String line) {
+        Matcher matcher = SYSTEM_SERVICES_DURATION.matcher(line);
+        boolean durationMatched = matcher.matches();
+        if (!durationMatched) {
+            matcher = SYSTEM_SERVICES_START_TIME.matcher(line);
+        }
+        if (!matcher.matches()) {
+            return null;
+        }
+        SystemServicesTimingItem item = new SystemServicesTimingItem();
+        item.setComponent(matcher.group("componentname").trim());
+        item.setSubcomponent(matcher.group("subname").trim());
+        if (durationMatched) {
+            item.setDuration(Double.parseDouble(matcher.group("time")));
+        } else {
+            item.setStartTime(Double.parseDouble(matcher.group("time")));
+        }
+        return item;
+    }
+}
-- 
cgit v1.2.3