Snap for 6088402 from 6b5d88ae4cecf048f2d2bd7c48777d5b07cb7823 to qt-d4-release
Change-Id: I8fb7ee77cf66789977facd02b9933186eb72fb41
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 @@
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 @@
/**
* 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 @@
@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 @@
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 @@
// 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 @@
@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 @@
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.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 @@
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 @@
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);
+ }
+}
