1 /*
2  * Copyright (C) 2019 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License
15  */
16 
17 package com.android.loganalysis.parser;
18 
19 
20 import com.android.loganalysis.item.GenericTimingItem;
21 import com.android.loganalysis.item.IItem;
22 import com.android.loganalysis.item.SystemServicesTimingItem;
23 
24 import java.io.BufferedReader;
25 import java.io.IOException;
26 import java.text.DateFormat;
27 import java.text.ParseException;
28 import java.text.SimpleDateFormat;
29 import java.util.ArrayList;
30 import java.util.HashMap;
31 import java.util.HashSet;
32 import java.util.List;
33 import java.util.Map;
34 import java.util.Set;
35 import java.util.regex.Matcher;
36 import java.util.regex.Pattern;
37 
38 /**
39  * An {@link IParser} to parse boot metrics from logcat. It currently assumes "threadtime" format of
40  * logcat. It will parse duration metrics for some system services like System Server, Zygote,
41  * System UI, e.t.c.
42  *
43  */
44 public class TimingsLogParser implements IParser {
45 
46     private static final String SYSTEM_SERVICES_TIME_PREFIX =
47             "^\\d*-\\d*\\s*\\d*:\\d*:\\d*.\\d*\\s*"
48                     + "\\d*\\s*\\d*\\s*[DV]\\s*(?<componentname>.*):\\s*(?<subname>\\S*)\\s*";
49     private static final String SYSTEM_SERVICES_TIME_SUFFIX = ":\\s*(?<time>.*)ms\\s*$";
50 
51     /** Used to parse time info from logcat lines */
52     private static final DateFormat DEFAULT_TIME_FORMAT =
53             new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
54 
55     /**
56      * Year is not important in timing info. Always use Unix time starting year for timestamp
57      * conversion with simplicity
58      */
59     private static final String DEFAULT_YEAR = "1970";
60 
61     /**
62      * Match the line with system services duration info like:
63      *
64      * <p>03-10 21:43:40.328 1005 1005 V SystemServerTiming:
65      * StartKeyAttestationApplicationIdProviderService took to complete: 3474ms
66      */
67     private static final Pattern SYSTEM_SERVICES_DURATION =
68             Pattern.compile(
69                     String.format(
70                             "%stook to complete%s",
71                             SYSTEM_SERVICES_TIME_PREFIX, SYSTEM_SERVICES_TIME_SUFFIX));
72     /**
73      * Match the line with system services start time info like:
74      *
75      * <p>01-10 01:25:57.249 989 989 D BootAnimation: BootAnimationStartTiming start time: 8343ms
76      */
77     private static final Pattern SYSTEM_SERVICES_START_TIME =
78             Pattern.compile(
79                     String.format(
80                             "%sstart time%s",
81                             SYSTEM_SERVICES_TIME_PREFIX, SYSTEM_SERVICES_TIME_SUFFIX));
82 
83     private List<DurationPattern> durationPatterns = new ArrayList<>();
84 
85     private static class DurationPattern {
86         String mName;
87         Pattern mStartTimePattern;
88         Pattern mEndTimePattern;
89 
DurationPattern(String name, Pattern startTimePattern, Pattern endTimePattern)90         DurationPattern(String name, Pattern startTimePattern, Pattern endTimePattern) {
91             mName = name;
92             mStartTimePattern = startTimePattern;
93             mEndTimePattern = endTimePattern;
94         }
95     }
96 
97     @Override
parse(List<String> lines)98     public IItem parse(List<String> lines) {
99         throw new UnsupportedOperationException(
100                 "Method has not been implemented in lieu of others");
101     }
102 
103     /**
104      * Add a pair of patterns matching the start and end signals in logcat for a duration metric
105      *
106      * @param name the name of the duration metric, it should be unique
107      * @param startTimePattern the pattern matches the logcat line indicating start of duration
108      * @param endTimePattern the pattern matches the logcat line indicating end of duration
109      */
addDurationPatternPair( String name, Pattern startTimePattern, Pattern endTimePattern)110     public void addDurationPatternPair(
111             String name, Pattern startTimePattern, Pattern endTimePattern) {
112         DurationPattern durationPattern =
113                 new DurationPattern(name, startTimePattern, endTimePattern);
114         durationPatterns.add(durationPattern);
115     }
116 
117     /** Cleanup added duration patterns */
clearDurationPatterns()118     public void clearDurationPatterns() {
119         durationPatterns.clear();
120     }
121 
122     /**
123      * Parse logcat lines with the added duration patterns and generate a list of {@link
124      * GenericTimingItem} representing the duration items. Note, a duration pattern could have zero
125      * or multiple matches
126      *
127      * @param input logcat lines
128      * @return list of {@link GenericTimingItem}
129      * @throws IOException
130      */
parseGenericTimingItems(BufferedReader input)131     public List<GenericTimingItem> parseGenericTimingItems(BufferedReader input)
132             throws IOException {
133         List<GenericTimingItem> items = new ArrayList<>();
134         String line;
135         //Timing items that are partially matched after captured start time
136         Map<String, Double> pendingItems = new HashMap<>();
137         while ((line = input.readLine()) != null) {
138             items.addAll(parseGenericTimingItem(line, pendingItems));
139         }
140         return items;
141     }
142 
143     /**
144      * Parse a particular logcat line to get duration items. One line could have be matched by
145      * multiple patterns
146      *
147      * @param line logcat line
148      * @param pendingItems timing items that are half-matched with only start time.
149      * @return list of {@link GenericTimingItem}
150      */
parseGenericTimingItem( String line, Map<String, Double> pendingItems)151     private List<GenericTimingItem> parseGenericTimingItem(
152             String line, Map<String, Double> pendingItems) {
153         List<GenericTimingItem> items = new ArrayList<>();
154         for (DurationPattern durationPattern : durationPatterns) {
155             Matcher matcher = durationPattern.mStartTimePattern.matcher(line);
156             if (matcher.find()) {
157                 double startTimeMillis = parseTime(line);
158                 pendingItems.put(durationPattern.mName, startTimeMillis);
159                 continue;
160             }
161             matcher = durationPattern.mEndTimePattern.matcher(line);
162             if (matcher.find()) {
163                 double endTimeMillis = parseTime(line);
164                 Double startTimeMillis = pendingItems.get(durationPattern.mName);
165                 if (startTimeMillis != null) {
166                     GenericTimingItem newItem = new GenericTimingItem();
167                     newItem.setName(durationPattern.mName);
168                     newItem.setStartAndEnd(startTimeMillis, endTimeMillis);
169                     items.add(newItem);
170                     pendingItems.remove(durationPattern.mName);
171                 }
172             }
173         }
174         return items;
175     }
176 
177     /**
178      * Get timestamp of current logcat line based on DEFAULT_YEAR
179      *
180      * @param line logcat line
181      * @return timestamp
182      */
parseTime(String line)183     private double parseTime(String line) {
184         String timeStr = String.format("%s-%s", DEFAULT_YEAR, line);
185         try {
186             return DEFAULT_TIME_FORMAT.parse(timeStr).getTime();
187         } catch (ParseException e) {
188             throw new RuntimeException(e);
189         }
190     }
191 
192     /**
193      * A method that parses the logcat input for system services timing information. It will ignore
194      * duplicated log lines and will keep multiple values for the same timing metric generated at
195      * different time in the log
196      *
197      * @param input Logcat input as a {@link BufferedReader}
198      * @return a list of {@link SystemServicesTimingItem}
199      * @throws IOException
200      */
parseSystemServicesTimingItems(BufferedReader input)201     public List<SystemServicesTimingItem> parseSystemServicesTimingItems(BufferedReader input)
202             throws IOException {
203         Set<String> matchedLines = new HashSet<>();
204         List<SystemServicesTimingItem> items = new ArrayList<>();
205         String line;
206         while ((line = input.readLine()) != null) {
207             if (matchedLines.contains(line)) {
208                 continue;
209             }
210             SystemServicesTimingItem item = parseSystemServicesTimingItem(line);
211             if (item == null) {
212                 continue;
213             }
214             items.add(item);
215             matchedLines.add(line);
216         }
217         return items;
218     }
219 
220     /**
221      * Parse a particular log line to see if it matches the system service timing pattern and return
222      * a {@link SystemServicesTimingItem} if matches, otherwise return null.
223      *
224      * @param line a single log line
225      * @return a {@link SystemServicesTimingItem}
226      */
parseSystemServicesTimingItem(String line)227     private SystemServicesTimingItem parseSystemServicesTimingItem(String line) {
228         Matcher matcher = SYSTEM_SERVICES_DURATION.matcher(line);
229         boolean durationMatched = matcher.matches();
230         if (!durationMatched) {
231             matcher = SYSTEM_SERVICES_START_TIME.matcher(line);
232         }
233         if (!matcher.matches()) {
234             return null;
235         }
236         SystemServicesTimingItem item = new SystemServicesTimingItem();
237         item.setComponent(matcher.group("componentname").trim());
238         item.setSubcomponent(matcher.group("subname").trim());
239         if (durationMatched) {
240             item.setDuration(Double.parseDouble(matcher.group("time")));
241         } else {
242             item.setStartTime(Double.parseDouble(matcher.group("time")));
243         }
244         return item;
245     }
246 }
247