Merge "Added a new parser for timing metrics from logcat" am: 59fd43d6bf

am: ae1f863454

Change-Id: I1ae55ff45ab403b6eeb0ed7e63d8a7998da4cc65

4 files changed, 331 insertions, 0 deletions

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/TimingsLogParser.java b/src/com/android/loganalysis/parser/TimingsLogParser.java
new file mode 100644
index 0000000..2bafd30
--- /dev/null
+++ b/src/com/android/loganalysis/parser/TimingsLogParser.java
@@ -0,0 +1,128 @@
+/*
+ * 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.IItem;
+import com.android.loganalysis.item.SystemServicesTimingItem;
+
+import java.io.BufferedReader;
+import java.io.IOException;
+import java.util.ArrayList;
+import java.util.HashSet;
+import java.util.List;
+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.
+ *
+ * <p>TODO(b/133166326): Add support for parsing thread time info from log lines, and also support
+ * dynamically adding new log line patterns.
+ */
+public class TimingsLogParser implements IParser {
+
+    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*$";
+
+    /**
+     * 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));
+
+    @Override
+    public IItem parse(List<String> lines) {
+        throw new UnsupportedOperationException(
+                "Method has not been implemented in lieu of others");
+    }
+
+    /**
+     * 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/tests/src/com/android/loganalysis/UnitTests.java b/tests/src/com/android/loganalysis/UnitTests.java
index 68d5bf6..35359ba 100644
--- a/tests/src/com/android/loganalysis/UnitTests.java
+++ b/tests/src/com/android/loganalysis/UnitTests.java
@@ -37,6 +37,7 @@ import com.android.loganalysis.parser.BatteryDischargeStatsInfoParserTest;
 import com.android.loganalysis.parser.BatteryStatsDetailedInfoParserTest;
 import com.android.loganalysis.parser.BatteryStatsSummaryInfoParserTest;
 import com.android.loganalysis.parser.BatteryUsageParserTest;
+import com.android.loganalysis.parser.TimingsLogParserTest;
 import com.android.loganalysis.parser.BugreportParserTest;
 import com.android.loganalysis.parser.CompactMemInfoParserTest;
 import com.android.loganalysis.parser.CpuInfoParserTest;
@@ -124,6 +125,7 @@ import org.junit.runners.Suite.SuiteClasses;
     BatteryStatsDetailedInfoParserTest.class,
     BatteryStatsSummaryInfoParserTest.class,
     BatteryUsageParserTest.class,
+    TimingsLogParserTest.class,
     BugreportParserTest.class,
     CompactMemInfoParserTest.class,
     CpuInfoParserTest.class,
diff --git a/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java b/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java
new file mode 100644
index 0000000..f4a0733
--- /dev/null
+++ b/tests/src/com/android/loganalysis/parser/TimingsLogParserTest.java
@@ -0,0 +1,117 @@
+/*
+ * 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.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;
+
+/** Unit Test for {@link TimingsLogParser} */
+public class TimingsLogParserTest extends TestCase {
+
+    /** Test that system services duration can be parsed as expected */
+    public void testParseSystemServicesTimingInfo_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 =
+                new TimingsLogParser().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 testParse_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 =
+                new TimingsLogParser().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);
+    }
+}