• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 /*
2  * Copyright (C) 2016 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 import com.android.loganalysis.item.DmesgActionInfoItem;
20 import com.android.loganalysis.item.DmesgItem;
21 import com.android.loganalysis.item.DmesgServiceInfoItem;
22 import com.android.loganalysis.item.DmesgStageInfoItem;
23 import com.android.loganalysis.item.DmesgModuleInfoItem;
24 
25 import com.google.common.annotations.VisibleForTesting;
26 
27 import java.io.BufferedReader;
28 import java.io.IOException;
29 import java.util.List;
30 import java.util.Map;
31 import java.util.regex.Matcher;
32 import java.util.regex.Pattern;
33 
34 
35 /**
36  * Parse the dmesg logs. </p>
37  */
38 public class DmesgParser implements IParser {
39 
40     private static final String SERVICENAME = "SERVICENAME";
41     private static final String TIMESTAMP = "TIMESTAMP";
42     private static final String STAGE = "STAGE";
43     private static final String ACTION = "ACTION";
44     private static final String SOURCE = "SOURCE";
45     private static final String DURATION = "DURATION";
46     private static final String UEVENTD = "ueventd";
47     private static final String INIT = "init";
48     private static final String WAIT_PROPERTY = "Wait for property ";
49     private static final String TOTAL_MODULE = "TOTAL_MODULE";
50     private static final String MOUNT_ALL = "mount_all";
51 
52     // Matches: [ 14.822691] init:
53     private static final String SERVICE_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] init:\\s+",
54             TIMESTAMP);
55     // Matches: [    3.791635] ueventd:
56     private static final String UEVENTD_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] ueventd:\\s+",
57             TIMESTAMP);
58 
59     // Matches: starting service 'ueventd'...
60     private static final String START_SERVICE_SUFFIX = String.format("starting service "
61             + "\\'(?<%s>.*)\\'...", SERVICENAME);
62     // Matches: Service 'ueventd' (pid 439) exited with status 0
63     private static final String EXIT_SERVICE_SUFFIX = String.format("Service \\'(?<%s>.*)\\'\\s+"
64             + "\\((?<PID>.*)\\) exited with status 0.*", SERVICENAME);
65 
66     private static final Pattern START_SERVICE = Pattern.compile(
67             String.format("%s%s", SERVICE_PREFIX, START_SERVICE_SUFFIX));
68     private static final Pattern EXIT_SERVICE = Pattern.compile(
69             String.format("%s%s", SERVICE_PREFIX, EXIT_SERVICE_SUFFIX));
70 
71     // Matches: init first stage started!
72     // Matches: init second stage started!
73     private static final String START_STAGE_PREFIX = String.format("init (?<%s>.*) stage started!",
74             STAGE);
75 
76     // Matches: [   13.647997] init: init first stage started!
77     private static final Pattern START_STAGE = Pattern.compile(
78             String.format("%s%s", SERVICE_PREFIX, START_STAGE_PREFIX));
79 
80     // Matches: init: processing action (early-init) from (/init.rc:14)
81     private static final String START_PROCESSING_ACTION_PREFIX =
82             String.format("processing action \\((?<%s>[^)]*)\\)( from \\((?<%s>.*)\\)|.*)$",
83                     ACTION, SOURCE);
84 
85     // Matches: init: processing action (early-init) from (/init.rc:14)
86     private static final Pattern START_PROCESSING_ACTION =
87             Pattern.compile(String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX));
88 
89     // Matches: [    1.175984] [    T1] init: Loaded 198 kernel modules took 808 ms
90     private static final Pattern MODULES_INFO =
91             Pattern.compile(
92                     String.format(
93                             "%sLoaded (?<count>\\d+) kernel modules took (?<%s>\\d+) ms.*$",
94                             SERVICE_PREFIX, DURATION));
95 
96     // Matches: [    0.503853] [    T1] init: Loading module /lib/modules/exynos_dit.ko with args ''
97     private static final Pattern MODULE_LOADING =
98             Pattern.compile(
99                     String.format(
100                             "%sLoading module \\S+\\/(?<koname>\\S+)\\.ko with args.*",
101                             SERVICE_PREFIX));
102 
103     // Matches: [    0.503803] [    T1] init: Loaded kernel module /lib/modules/boot_device_spi.ko
104     private static final Pattern MODULE_LOADED =
105             Pattern.compile(
106                     String.format(
107                             "%sLoaded kernel module \\S+\\/(?<koname>\\S+)\\.ko", SERVICE_PREFIX));
108 
109     // Matches: [    3.791635] ueventd: Coldboot took 0.695055 seconds
110     private static final String STAGE_SUFFIX =
111             String.format("(?<%s>.*)\\s+took\\s+(?<%s>.*)\\s+seconds$", STAGE, DURATION);
112     private static final Pattern UEVENTD_STAGE_INFO = Pattern.compile(
113             String.format("%s%s", UEVENTD_PREFIX, STAGE_SUFFIX));
114 
115     private static final String PROPERTY_SUFFIX =
116             String.format("Wait for property\\s(?<%s>.*)\\s+took\\s+(?<%s>.*)ms$", STAGE, DURATION);
117     // Matches [    7.270487] init: Wait for property 'apexd.status=ready' took 230ms
118     private static final Pattern WAIT_FOR_PROPERTY_INFO = Pattern.compile(
119             String.format("%s%s", SERVICE_PREFIX, PROPERTY_SUFFIX));
120 
121     // Matches: [    2.295667] init: Command 'mount_all --late' action=late-fs
122     // (/vendor/etc/init/init.rc:347) took 250ms and succeeded
123     private static final String MOUNT_SUFFIX =
124             String.format(
125                     "Command 'mount_all (?<%s>/\\S+|.*)?--(?<%s>.+)'.* took (?<%s>\\d+)ms.*",
126                     SOURCE, STAGE, DURATION);
127     private static final Pattern MOUNT_STAGE_INFO =
128             Pattern.compile(String.format("%s%s", SERVICE_PREFIX, MOUNT_SUFFIX));
129 
130     private DmesgItem mDmesgItem = new DmesgItem();
131 
132     /**
133      * {@inheritDoc}
134      */
135     @Override
parse(List<String> lines)136     public DmesgItem parse(List<String> lines) {
137         for (String line : lines) {
138             parse(line);
139         }
140 
141         return mDmesgItem;
142     }
143 
144     /**
145      * Parse the kernel log till EOF to retrieve the duration of the service calls, start times of
146      * different boot stages and actions taken. Besides, while parsing these informations are stored
147      * in the intermediate {@link DmesgServiceInfoItem}, {@link DmesgStageInfoItem} and {@link
148      * DmesgActionInfoItem} objects
149      *
150      * @param bufferedLog dmesg log
151      * @throws IOException
152      */
parseInfo(BufferedReader bufferedLog)153     public DmesgItem parseInfo(BufferedReader bufferedLog) throws IOException {
154         String line;
155         while ((line = bufferedLog.readLine()) != null) {
156             parse(line);
157         }
158 
159         return mDmesgItem;
160     }
161 
162     /**
163      * <p>
164      * Parse single line of the dmesg log to retrieve the duration of the service calls or start
165      * times of different boot stages or start times of actions taken based on the info contained in
166      * the line.
167      * </p>
168      * <p>
169      * Besides, while parsing these informations are stored in the intermediate
170      * {@link DmesgServiceInfoItem}, {@link DmesgStageInfoItem} and {@link DmesgActionInfoItem}
171      * objects
172      * </p>
173      *
174      * @param line individual line of the dmesg log
175      */
parse(String line)176     private void parse(String line) {
177 
178         if (parseServiceInfo(line)) {
179             return;
180         }
181         if (parseStageInfo(line)) {
182             return;
183         }
184         if (parseActionInfo(line)) {
185             return;
186         }
187         if (parseModuleInfo(line)) {
188             return;
189         }
190     }
191 
192     /**
193      * Parse init services {@code start time} and {@code end time} from each {@code line} of dmesg
194      * log and store the {@code duration} it took to complete the service if the end time stamp is
195      * available in {@link DmesgServiceInfoItem}.
196      *
197      * @param line individual line of the dmesg log
198      * @return {@code true}, if the {@code line} indicates start or end of a service, {@code false},
199      *     otherwise
200      */
201     @VisibleForTesting
parseServiceInfo(String line)202     boolean parseServiceInfo(String line) {
203         Matcher match = null;
204         if ((match = matches(START_SERVICE, line)) != null) {
205             DmesgServiceInfoItem serviceItem = new DmesgServiceInfoItem();
206             serviceItem.setServiceName(match.group(SERVICENAME));
207             serviceItem.setStartTime((long) (Double.parseDouble(
208                     match.group(TIMESTAMP)) * 1000));
209             getServiceInfoItems().put(match.group(SERVICENAME), serviceItem);
210             return true;
211         } else if ((match = matches(EXIT_SERVICE, line)) != null) {
212             if (getServiceInfoItems().containsKey(match.group(SERVICENAME))) {
213                 DmesgServiceInfoItem serviceItem = getServiceInfoItems().get(
214                         match.group(SERVICENAME));
215                 serviceItem.setEndTime((long) (Double.parseDouble(
216                         match.group(TIMESTAMP)) * 1000));
217             }
218             return true;
219         }
220         return false;
221     }
222 
223     /**
224      * Parse init stages log from each {@code line} of dmesg log and store the stage name, start
225      * time and duration if available in a {@link DmesgStageInfoItem} object
226      *
227      * @param line individual line of the dmesg log
228      * @return {@code true}, if the {@code line} indicates start of a boot stage, {@code false},
229      *     otherwise
230      */
231     @VisibleForTesting
parseStageInfo(String line)232     boolean parseStageInfo(String line) {
233         Matcher match = null;
234         if ((match = matches(START_STAGE, line)) != null) {
235             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
236             stageInfoItem.setStageName(match.group(STAGE));
237             stageInfoItem.setStartTime((long) (Double.parseDouble(
238                     match.group(TIMESTAMP)) * 1000));
239             mDmesgItem.addStageInfoItem(stageInfoItem);
240             return true;
241         }
242         if((match = matches(UEVENTD_STAGE_INFO, line)) != null) {
243             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
244             stageInfoItem.setStageName(String.format("%s_%s", UEVENTD, match.group(STAGE)));
245             stageInfoItem.setDuration((long) (Double.parseDouble(
246                     match.group(DURATION)) * 1000));
247             mDmesgItem.addStageInfoItem(stageInfoItem);
248             return true;
249         }
250         if((match = matches(WAIT_FOR_PROPERTY_INFO, line)) != null) {
251             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
252             stageInfoItem.setStageName(
253                     String.format("%s_%s%s", INIT, WAIT_PROPERTY, match.group(STAGE)));
254             stageInfoItem.setDuration((long) Double.parseDouble(match.group(DURATION)));
255             mDmesgItem.addStageInfoItem(stageInfoItem);
256             return true;
257         }
258         if ((match = matches(MOUNT_STAGE_INFO, line)) != null) {
259             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
260             if (match.group(SOURCE).isEmpty()) {
261                 stageInfoItem.setStageName(
262                         String.format("%s_%s_%s", INIT, MOUNT_ALL, match.group(STAGE)));
263             } else {
264                 stageInfoItem.setStageName(
265                         String.format(
266                                 "%s_%s_%s_%s",
267                                 INIT, MOUNT_ALL, match.group(STAGE), match.group(SOURCE).trim()));
268             }
269             stageInfoItem.setDuration((long) Double.parseDouble(match.group(DURATION)));
270             mDmesgItem.addStageInfoItem(stageInfoItem);
271             return true;
272         }
273         return false;
274     }
275 
276     /**
277      * Parse action from each {@code line} of dmesg log and store the action name and start time in
278      * {@link DmesgActionInfoItem} object
279      *
280      * @param line individual {@code line} of the dmesg log
281      * @return {@code true}, if {@code line} indicates starting of processing of action {@code
282      *     false}, otherwise
283      */
284     @VisibleForTesting
parseActionInfo(String line)285     boolean parseActionInfo(String line) {
286         Matcher match = null;
287         if ((match = matches(START_PROCESSING_ACTION, line)) != null) {
288             DmesgActionInfoItem actionInfoItem = new DmesgActionInfoItem();
289             if (match.group(SOURCE) != null) {
290                 actionInfoItem.setSourceName(match.group(SOURCE));
291             }
292             actionInfoItem.setActionName(match.group(ACTION));
293             actionInfoItem.setStartTime((long) (Double.parseDouble(
294                     match.group(TIMESTAMP)) * 1000));
295             mDmesgItem.addActionInfoItem(actionInfoItem);
296             return true;
297         }
298         return false;
299     }
300 
301     /**
302      * Parse modules from each {@code line} of dmesg log and store the module name and loading time
303      * in {@link DmesgModuleInfoItem} object
304      *
305      * @param line individual {@code line} of the dmesg log
306      * @return {@code true}, if {@code line} indicates start, end of a module loading or the summary
307      *     {@code false}, otherwise
308      */
309     @VisibleForTesting
parseModuleInfo(String line)310     boolean parseModuleInfo(String line) {
311         Matcher match = null;
312         if ((match = matches(MODULES_INFO, line)) != null) {
313             DmesgModuleInfoItem moduleInfoItem = new DmesgModuleInfoItem();
314             moduleInfoItem.setModuleName(TOTAL_MODULE);
315             moduleInfoItem.setModuleDuration((long) Double.parseDouble(match.group(DURATION)));
316             moduleInfoItem.setModuleCount(match.group("count"));
317             mDmesgItem.addModuleInfoItem(TOTAL_MODULE, moduleInfoItem);
318             return true;
319         }
320 
321         if ((match = matches(MODULE_LOADING, line)) != null) {
322             DmesgModuleInfoItem moduleInfoItem = new DmesgModuleInfoItem();
323             moduleInfoItem.setModuleName(match.group("koname"));
324             moduleInfoItem.setStartTime((long) (Double.parseDouble(match.group(TIMESTAMP)) * 1000));
325             mDmesgItem.addModuleInfoItem(match.group("koname"), moduleInfoItem);
326             return true;
327         } else if ((match = matches(MODULE_LOADED, line)) != null) {
328             if (getModuleInfoItems().containsKey(match.group("koname"))) {
329                 DmesgModuleInfoItem moduleInfoItem =
330                         getModuleInfoItems().get(match.group("koname"));
331                 moduleInfoItem.setEndTime(
332                         (long) (Double.parseDouble(match.group(TIMESTAMP)) * 1000));
333             }
334             return true;
335         }
336         return false;
337     }
338 
339     /**
340      * Checks whether {@code line} matches the given {@link Pattern}.
341      *
342      * @return The resulting {@link Matcher} obtained by matching the {@code line} against
343      *         {@code pattern}, or null if the {@code line} does not match.
344      */
matches(Pattern pattern, String line)345     private static Matcher matches(Pattern pattern, String line) {
346         Matcher ret = pattern.matcher(line);
347         return ret.matches() ? ret : null;
348     }
349 
getServiceInfoItems()350     public Map<String, DmesgServiceInfoItem> getServiceInfoItems() {
351         return mDmesgItem.getServiceInfoItems();
352     }
353 
setServiceInfoItems(Map<String, DmesgServiceInfoItem> serviceInfoItems)354     public void setServiceInfoItems(Map<String, DmesgServiceInfoItem> serviceInfoItems) {
355         for(String key : serviceInfoItems.keySet()) {
356             mDmesgItem.addServiceInfoItem(key, serviceInfoItems.get(key));
357         }
358     }
359 
getStageInfoItems()360     public List<DmesgStageInfoItem> getStageInfoItems() {
361         return mDmesgItem.getStageInfoItems();
362     }
363 
getActionInfoItems()364     public List<DmesgActionInfoItem> getActionInfoItems() {
365         return mDmesgItem.getActionInfoItems();
366     }
367 
getModuleInfoItems()368     public Map<String, DmesgModuleInfoItem> getModuleInfoItems() {
369         return mDmesgItem.getModuleInfoItems();
370     }
371 }