diff options
9 files changed, 33 insertions, 1007 deletions
diff --git a/src/com/android/loganalysis/item/DmesgActionInfoItem.java b/src/com/android/loganalysis/item/DmesgActionInfoItem.java index 482b426..ac73b8e 100644 --- a/src/com/android/loganalysis/item/DmesgActionInfoItem.java +++ b/src/com/android/loganalysis/item/DmesgActionInfoItem.java @@ -27,14 +27,12 @@ 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( - SOURCE_NAME, ACTION_NAME, ACTION_START_TIME)); + ACTION_NAME, ACTION_START_TIME)); /** * The constructor for {@link DmesgActionInfoItem}. @@ -46,28 +44,13 @@ public class DmesgActionInfoItem extends GenericItem { /** * The constructor for {@link DmesgActionInfoItem}. */ - public DmesgActionInfoItem(String source, String name, Long startTime) { + public DmesgActionInfoItem(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() { @@ -97,11 +80,8 @@ public class DmesgActionInfoItem extends GenericItem { @Override public String toString() { - return "ActionInfoItem [" - + "getSourceName()=" + getSourceName() - + ", getActionName()=" + getActionName() - + ", getStartTime()=" + getStartTime() - + "]"; + return "ActionInfoItem [getActionName()=" + getActionName() + ", getStartTime()=" + + getStartTime() + "]"; } } diff --git a/src/com/android/loganalysis/item/GenericTimingItem.java b/src/com/android/loganalysis/item/GenericTimingItem.java deleted file mode 100644 index 088d15b..0000000 --- a/src/com/android/loganalysis/item/GenericTimingItem.java +++ /dev/null @@ -1,79 +0,0 @@ -/* - * 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 deleted file mode 100644 index 79671a2..0000000 --- a/src/com/android/loganalysis/item/SystemServicesTimingItem.java +++ /dev/null @@ -1,84 +0,0 @@ -/* - * 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 9fce9b8..be292ff 100644 --- a/src/com/android/loganalysis/parser/DmesgParser.java +++ b/src/com/android/loganalysis/parser/DmesgParser.java @@ -40,7 +40,6 @@ 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"; @@ -75,13 +74,21 @@ 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 \\((?<%s>.*)\\)|.*)$", - ACTION, SOURCE); + 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); // 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); @@ -235,11 +242,9 @@ public class DmesgParser implements IParser { @VisibleForTesting boolean parseActionInfo(String line) { Matcher match = null; - if ((match = matches(START_PROCESSING_ACTION, line)) != null) { + if ((match = matches(START_PROCESSING_ACTION, line)) != null + || (match = matches(START_PROCESSING_ACTION_LEGACY, 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)); @@ -278,4 +283,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 deleted file mode 100644 index ee3535f..0000000 --- a/src/com/android/loganalysis/parser/TimingsLogParser.java +++ /dev/null @@ -1,246 +0,0 @@ -/* - * 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 deleted file mode 100644 index 648a3af..0000000 --- a/test_framework/com/android/tradefed/device/metric/LogcatTimingMetricCollector.java +++ /dev/null @@ -1,201 +0,0 @@ -/* - * 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 35359ba..68d5bf6 100644 --- a/tests/src/com/android/loganalysis/UnitTests.java +++ b/tests/src/com/android/loganalysis/UnitTests.java @@ -37,7 +37,6 @@ 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; @@ -125,7 +124,6 @@ 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 4362c7a..7cdbd36 100644 --- a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java +++ b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java @@ -215,15 +215,22 @@ public class DmesgParserTest extends TestCase { private static List<DmesgActionInfoItem> getExpectedActionInfoItems() { return Arrays.asList( - 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)); + 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")))); } 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 deleted file mode 100644 index 48881ea..0000000 --- a/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java +++ /dev/null @@ -1,354 +0,0 @@ -/* - * 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); - } -} |