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
(cherry picked from commit c7bcaba872c7d82286960c750edd67e56ee73712)

9 files changed, 1007 insertions, 33 deletions

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
@@ -27,12 +27,14 @@ 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,13 +46,28 @@ 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
      */
     public String getActionName() {
@@ -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;
+    }
+}
diff --git a/test_framework/com/android/tradefed/device/metric/LogcatTimingMetricCollector.java b/test_framework/com/android/tradefed/device/metric/LogcatTimingMetricCollector.java
new file mode 100644
index 0000000..648a3af
--- /dev/null
+++ b/test_framework/com/android/tradefed/device/metric/LogcatTimingMetricCollector.java
@@ -0,0 +1,201 @@
+/*
+ * 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.tradefed.device.metric;
+
+import com.android.loganalysis.item.GenericTimingItem;
+import com.android.loganalysis.parser.TimingsLogParser;
+import com.android.tradefed.config.Option;
+import com.android.tradefed.config.OptionClass;
+import com.android.tradefed.device.DeviceNotAvailableException;
+import com.android.tradefed.device.ITestDevice;
+import com.android.tradefed.device.LogcatReceiver;
+import com.android.tradefed.log.LogUtil.CLog;
+import com.android.tradefed.metrics.proto.MetricMeasurement.DataType;
+import com.android.tradefed.metrics.proto.MetricMeasurement.Measurements;
+import com.android.tradefed.metrics.proto.MetricMeasurement.Metric;
+import com.android.tradefed.result.InputStreamSource;
+import com.android.tradefed.result.LogDataType;
+import com.android.tradefed.result.TestDescription;
+
+import com.google.common.annotations.VisibleForTesting;
+
+import java.io.BufferedReader;
+import java.io.IOException;
+import java.io.InputStream;
+import java.io.InputStreamReader;
+import java.util.ArrayList;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
+import java.util.regex.Pattern;
+import java.util.stream.Collectors;
+
+/**
+ * A metric collector that collects timing information (e.g. user switch time) from logcat during
+ * one or multiple repeated tests by using given regex patterns to parse start and end signals of an
+ * event from logcat lines.
+ */
+@OptionClass(alias = "timing-metric-collector")
+public class LogcatTimingMetricCollector extends BaseDeviceMetricCollector {
+
+    private static final String LOGCAT_NAME_FORMAT = "device_%s_test_logcat";
+    // Use logcat -T 'count' to only print a few line before we start and not the full buffer
+    private static final String LOGCAT_CMD = "logcat *:D -T 150";
+
+    @Option(
+            name = "start-pattern",
+            description =
+                    "Key-value pairs to specify the timing metric start patterns to capture from"
+                            + " logcat. Key: metric name, value: regex pattern of logcat line"
+                            + " indicating the start of the timing metric")
+    private final Map<String, String> mStartPatterns = new HashMap<>();
+
+    @Option(
+            name = "end-pattern",
+            description =
+                    "Key-value pairs to specify the timing metric end patterns to capture from"
+                            + " logcat. Key: metric name, value: regex pattern of logcat line"
+                            + " indicating the end of the timing metric")
+    private final Map<String, String> mEndPatterns = new HashMap<>();
+
+    @Option(
+            name = "logcat-buffer",
+            description =
+                    "Logcat buffers where the timing metrics are captured. Default buffers will be"
+                            + " used if not specified.")
+    private final List<String> mLogcatBuffers = new ArrayList<>();
+
+    private final Map<ITestDevice, LogcatReceiver> mLogcatReceivers = new HashMap<>();
+    private final TimingsLogParser mParser = new TimingsLogParser();
+
+    @Override
+    public void onTestRunStart(DeviceMetricData testData) {
+        // Adding patterns
+        mParser.clearDurationPatterns();
+        for (Map.Entry<String, String> entry : mStartPatterns.entrySet()) {
+            String name = entry.getKey();
+            if (!mEndPatterns.containsKey(name)) {
+                CLog.w("Metric %s is missing end pattern, skipping.", name);
+                continue;
+            }
+            Pattern start = Pattern.compile(entry.getValue());
+            Pattern end = Pattern.compile(mEndPatterns.get(name));
+            CLog.d("Adding metric: %s", name);
+            mParser.addDurationPatternPair(name, start, end);
+        }
+        // Start receiving logcat
+        String logcatCmd = LOGCAT_CMD;
+        if (!mLogcatBuffers.isEmpty()) {
+            logcatCmd += " -b " + String.join(",", mLogcatBuffers);
+        }
+        for (ITestDevice device : getDevices()) {
+            CLog.d(
+                    "Creating logcat receiver on device %s with command %s",
+                    device.getSerialNumber(), logcatCmd);
+            mLogcatReceivers.put(device, createLogcatReceiver(device, logcatCmd));
+            try {
+                device.executeShellCommand("logcat -c");
+            } catch (DeviceNotAvailableException e) {
+                CLog.e(
+                        "Device not available when clear logcat. Skip logcat collection on %s",
+                        device.getSerialNumber());
+                continue;
+            }
+            mLogcatReceivers.get(device).start();
+        }
+    }
+
+    @Override
+    public void onTestRunEnd(
+            DeviceMetricData testData, final Map<String, Metric> currentTestCaseMetrics) {
+        boolean isMultiDevice = getDevices().size() > 1;
+        for (ITestDevice device : getDevices()) {
+            try (InputStreamSource logcatData = mLogcatReceivers.get(device).getLogcatData()) {
+                Map<String, List<Double>> metrics = parse(logcatData);
+                for (Map.Entry<String, List<Double>> entry : metrics.entrySet()) {
+                    String name = entry.getKey();
+                    List<Double> values = entry.getValue();
+                    if (isMultiDevice) {
+                        testData.addMetricForDevice(device, name, createMetric(values));
+                    } else {
+                        testData.addMetric(name, createMetric(values));
+                    }
+                    CLog.d(
+                            "Metric: %s with value: %s, added to device %s",
+                            name, values, device.getSerialNumber());
+                }
+                testLog(
+                        String.format(LOGCAT_NAME_FORMAT, device.getSerialNumber()),
+                        LogDataType.TEXT,
+                        logcatData);
+            }
+            mLogcatReceivers.get(device).stop();
+            mLogcatReceivers.get(device).clear();
+        }
+    }
+
+    @Override
+    public void onTestFail(DeviceMetricData testData, TestDescription test) {
+        for (ITestDevice device : getDevices()) {
+            try (InputStreamSource logcatData = mLogcatReceivers.get(device).getLogcatData()) {
+                testLog(
+                        String.format(LOGCAT_NAME_FORMAT, device.getSerialNumber()),
+                        LogDataType.TEXT,
+                        logcatData);
+            }
+            mLogcatReceivers.get(device).stop();
+            mLogcatReceivers.get(device).clear();
+        }
+    }
+
+    @VisibleForTesting
+    Map<String, List<Double>> parse(InputStreamSource logcatData) {
+        Map<String, List<Double>> metrics = new HashMap<>();
+        try (InputStream inputStream = logcatData.createInputStream();
+                InputStreamReader logcatReader = new InputStreamReader(inputStream);
+                BufferedReader br = new BufferedReader(logcatReader)) {
+            List<GenericTimingItem> items = mParser.parseGenericTimingItems(br);
+            for (GenericTimingItem item : items) {
+                String metricKey = item.getName();
+                if (!metrics.containsKey(metricKey)) {
+                    metrics.put(metricKey, new ArrayList<>());
+                }
+                metrics.get(metricKey).add(item.getDuration());
+            }
+        } catch (IOException e) {
+            CLog.e("Failed to parse timing metrics from logcat %s", e);
+        }
+        return metrics;
+    }
+
+    @VisibleForTesting
+    LogcatReceiver createLogcatReceiver(ITestDevice device, String logcatCmd) {
+        return new LogcatReceiver(device, logcatCmd, device.getOptions().getMaxLogcatDataSize(), 0);
+    }
+
+    private Metric.Builder createMetric(List<Double> values) {
+        // TODO: Fix post processors to handle double values. For now use concatenated string as we
+        // prefer to use AggregatedPostProcessor
+        String stringValue =
+                values.stream()
+                        .map(value -> Double.toString(value))
+                        .collect(Collectors.joining(","));
+        return Metric.newBuilder()
+                .setType(DataType.RAW)
+                .setMeasurements(Measurements.newBuilder().setSingleString(stringValue));
+    }
+}
diff --git a/tests/src/com/android/loganalysis/UnitTests.java b/tests/src/com/android/loganalysis/UnitTests.java
index 68d5bf6..35359ba 100644
--- a/tests/src/com/android/loganalysis/UnitTests.java
+++ b/tests/src/com/android/loganalysis/UnitTests.java
@@ -37,6 +37,7 @@ import com.android.loganalysis.parser.BatteryDischargeStatsInfoParserTest;
 import com.android.loganalysis.parser.BatteryStatsDetailedInfoParserTest;
 import com.android.loganalysis.parser.BatteryStatsSummaryInfoParserTest;
 import com.android.loganalysis.parser.BatteryUsageParserTest;
+import com.android.loganalysis.parser.TimingsLogParserTest;
 import com.android.loganalysis.parser.BugreportParserTest;
 import com.android.loganalysis.parser.CompactMemInfoParserTest;
 import com.android.loganalysis.parser.CpuInfoParserTest;
@@ -124,6 +125,7 @@ import org.junit.runners.Suite.SuiteClasses;
     BatteryStatsDetailedInfoParserTest.class,
     BatteryStatsSummaryInfoParserTest.class,
     BatteryUsageParserTest.class,
+    TimingsLogParserTest.class,
     BugreportParserTest.class,
     CompactMemInfoParserTest.class,
     CpuInfoParserTest.class,
diff --git a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
index 7cdbd36..4362c7a 100644
--- a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
+++ b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
@@ -215,22 +215,15 @@ public class DmesgParserTest extends TestCase {
 
     private static List<DmesgActionInfoItem> getExpectedActionInfoItems() {
         return Arrays.asList(
-                new DmesgActionInfoItem("early-init", (long) (Double.parseDouble("44942.872"))),
-                new DmesgActionInfoItem(
-                        "set_mmap_rnd_bits", (long) (Double.parseDouble("47233.446"))),
-                new DmesgActionInfoItem(
-                        "set_kptr_restrict", (long) (Double.parseDouble("47240.083"))),
-                new DmesgActionInfoItem("keychord_init", (long) (Double.parseDouble("47245.778"))),
-                new DmesgActionInfoItem(
-                        "persist.sys.usb.config=* boot", (long) (Double.parseDouble("52361.049"))),
-                new DmesgActionInfoItem(
-                        "enable_property_trigger", (long) (Double.parseDouble("52361.108"))),
-                new DmesgActionInfoItem(
-                        "security.perf_harden=1", (long) (Double.parseDouble("52361.313"))),
-                new DmesgActionInfoItem(
-                        "ro.debuggable=1", (long) (Double.parseDouble("52361.495"))),
-                new DmesgActionInfoItem(
-                        "sys.boot_completed=1", (long) (Double.parseDouble("58298.293"))));
+                new DmesgActionInfoItem("/init.rc:13", "early-init", 44942L),
+                new DmesgActionInfoItem("<Builtin Action>:0", "set_mmap_rnd_bits", 47233L),
+                new DmesgActionInfoItem("<Builtin Action>:0", "set_kptr_restrict", 47240L),
+                new DmesgActionInfoItem("<Builtin Action>:0", "keychord_init", 47245L),
+                new DmesgActionInfoItem("<Builtin Action>:0", "persist.sys.usb.config=* boot", 52361L),
+                new DmesgActionInfoItem("<Builtin Action>:0", "enable_property_trigger", 52361L),
+                new DmesgActionInfoItem("/init.rc:677", "security.perf_harden=1", 52361L),
+                new DmesgActionInfoItem("/init.rc:700", "ro.debuggable=1", 52361L),
+                new DmesgActionInfoItem(null, "sys.boot_completed=1", 58298L));
     }
 
     private static List<DmesgStageInfoItem> getExpectedStageInfoItems() {
diff --git a/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java b/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java
new file mode 100644
index 0000000..48881ea
--- /dev/null
+++ b/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java
@@ -0,0 +1,354 @@
+/*
+ * 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.SystemServicesTimingItem;
+
+import junit.framework.TestCase;
+
+import java.io.BufferedReader;
+import java.io.ByteArrayInputStream;
+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 testParseSystemServicesTiming_system_services_duration() throws IOException {
+        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 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.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
+
+        List<SystemServicesTimingItem> items =
+                mParser.parseSystemServicesTimingItems(createBufferedReader(log));
+        assertNotNull(items);
+        assertEquals(6, items.size());
+        assertEquals("SystemServerTiming", items.get(0).getComponent());
+        assertEquals(38.0, items.get(0).getDuration());
+        assertNull(items.get(0).getStartTime());
+        assertEquals("ReadingSystemConfig", items.get(1).getSubcomponent());
+        assertEquals(0.53, items.get(1).getDuration());
+        assertNull(items.get(1).getStartTime());
+        assertEquals("DeviceIdentifiersPolicyService", items.get(2).getSubcomponent());
+        assertEquals("OtherService", items.get(3).getComponent());
+        assertEquals("StartTestStack", items.get(3).getSubcomponent());
+        assertEquals(7.0, items.get(3).getDuration());
+        assertEquals("FakeService", items.get(4).getComponent());
+        assertEquals("Valid", items.get(4).getSubcomponent());
+        assertEquals(8.0, items.get(4).getDuration());
+        assertNull(items.get(4).getStartTime());
+        assertEquals("SystemServerTiming", items.get(5).getComponent());
+        assertEquals("StartWatchdog", items.get(5).getSubcomponent());
+        assertEquals(38.0, items.get(5).getDuration());
+    }
+
+    /** Test that system services start time can be parsed as expected */
+    public void testParseSystemServicesTiming_system_services_start_time() throws IOException {
+        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.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",
+                        "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");
+
+        List<SystemServicesTimingItem> items =
+                mParser.parseSystemServicesTimingItems(createBufferedReader(log));
+        assertNotNull(items);
+        assertEquals(4, items.size());
+        assertEquals("BootAnimation", items.get(0).getComponent());
+        assertEquals("BootAnimationStartTiming", items.get(0).getSubcomponent());
+        assertEquals(8611.0, items.get(0).getStartTime());
+        assertNull(items.get(0).getDuration());
+        assertEquals("BootAnimationPreloadTiming", items.get(1).getSubcomponent());
+        assertEquals("BootAnimation", items.get(2).getComponent());
+        assertEquals("BootAnimationStopTiming", items.get(2).getSubcomponent());
+        assertEquals(24839.0, items.get(2).getStartTime());
+        assertNull(items.get(2).getDuration());
+        assertEquals("FakeService", items.get(3).getComponent());
+        assertEquals("Valid", items.get(3).getSubcomponent());
+        assertEquals(34839.0, items.get(3).getStartTime());
+        assertNull(items.get(3).getDuration());
+    }
+
+    private BufferedReader createBufferedReader(String input) {
+        InputStream inputStream = new ByteArrayInputStream(input.getBytes());
+        InputStreamReader reader = new InputStreamReader(inputStream);
+        return new BufferedReader(reader);
+    }
+}