1 /*
2  * Copyright (C) 2023 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 android.boottime.postprocessor;
18 
19 import android.boottime.BootTimeTest;
20 
21 import com.android.loganalysis.item.DmesgActionInfoItem;
22 import com.android.loganalysis.item.DmesgItem;
23 import com.android.loganalysis.item.DmesgServiceInfoItem;
24 import com.android.loganalysis.item.DmesgStageInfoItem;
25 import com.android.loganalysis.parser.DmesgParser;
26 import com.android.tradefed.config.Option;
27 import com.android.tradefed.config.OptionClass;
28 import com.android.tradefed.log.LogUtil;
29 import com.android.tradefed.log.LogUtil.CLog;
30 import com.android.tradefed.metrics.proto.MetricMeasurement.Metric;
31 import com.android.tradefed.result.LogFile;
32 import com.android.tradefed.result.TestDescription;
33 
34 import com.google.common.collect.ArrayListMultimap;
35 import com.google.common.collect.Multimaps;
36 
37 import java.io.BufferedReader;
38 import java.io.File;
39 import java.io.FileInputStream;
40 import java.io.IOException;
41 import java.io.InputStreamReader;
42 import java.util.ArrayList;
43 import java.util.Collection;
44 import java.util.HashMap;
45 import java.util.List;
46 import java.util.Map;
47 import java.util.stream.Collectors;
48 
49 /** A Post Processor that processes text file containing dmesg logs into key-value pairs */
50 @OptionClass(alias = "dmesg-post-processor")
51 public class DmesgPostProcessor extends BaseBootTimeTestLogPostProcessor {
52     private static final String INIT = "init_";
53     private static final String START_TIME = "_START_TIME";
54     private static final String DURATION = "_DURATION";
55     private static final String END_TIME = "_END_TIME";
56     private static final String ACTION = "action_";
57     private static final String INIT_STAGE = "init_stage_";
58     private static final String BOOT_COMPLETE_ACTION = "sys.boot_completed=1";
59     private static final String BOOTLOADER_TIME = "bootloader_time";
60     private static final String BOOTLOADER_PREFIX = "bootloader-";
61     private static final String BOOTLOADER_PHASE_SW = "SW";
62     private static final String TOTAL_BOOT_TIME = "TOTAL_BOOT_TIME";
63     private List<String> mBootLoaderPropValues = new ArrayList<>();
64 
65     @Option(name = "bootloader-info", description = "Collect the boot loader timing.")
66     private boolean mBootloaderInfo = false;
67 
68     /** {@inheritDoc} */
69     @Override
processTestMetricsAndLogs( TestDescription testDescription, HashMap<String, Metric> testMetrics, Map<String, LogFile> testLogs)70     public Map<String, Metric.Builder> processTestMetricsAndLogs(
71             TestDescription testDescription,
72             HashMap<String, Metric> testMetrics,
73             Map<String, LogFile> testLogs) {
74         LogUtil.CLog.v("Processing test logs for %s", testDescription.getTestName());
75         if (mBootloaderInfo) {
76             List<String> bootLoaderPropKeys =
77                     testMetrics.keySet().stream()
78                             .filter(key -> key.startsWith(BootTimeTest.getBootTimePropKey()))
79                             .sorted()
80                             .collect(Collectors.toList());
81             for (String key : bootLoaderPropKeys) {
82                 String value = testMetrics.get(key).getMeasurements().getSingleString();
83                 mBootLoaderPropValues.add(value);
84             }
85         }
86         return processDmesgLogs(filterFiles(testLogs));
87     }
88 
89     /** {@inheritDoc} */
90     @Override
processRunMetricsAndLogs( HashMap<String, Metric> rawMetrics, Map<String, LogFile> runLogs)91     public Map<String, Metric.Builder> processRunMetricsAndLogs(
92             HashMap<String, Metric> rawMetrics, Map<String, LogFile> runLogs) {
93         // noop
94         return new HashMap<>();
95     }
96 
97     /**
98      * Process Dmesg testLog files reported by the test
99      *
100      * @param dmesgFiles List of dmesg files
101      * @return Map with metric keys and stringified double values joined by comma
102      */
processDmesgLogs(List<File> dmesgFiles)103     private Map<String, Metric.Builder> processDmesgLogs(List<File> dmesgFiles) {
104         ArrayListMultimap<String, Double> metrics = ArrayListMultimap.create();
105         for (File dmesgFile : dmesgFiles) {
106             CLog.d("Parsing dmesg file %s", dmesgFile.getPath());
107             DmesgParser dmesgLogParser = new DmesgParser();
108             try (InputStreamReader ir = new InputStreamReader(new FileInputStream(dmesgFile));
109                     BufferedReader input = new BufferedReader(ir)) {
110                 DmesgItem dmesgItem = dmesgLogParser.parseInfo(input);
111                 if (!dmesgItem.getServiceInfoItems().isEmpty()) {
112                     metrics.putAll(
113                             Multimaps.forMap(
114                                     analyzeDmesgServiceInfo(
115                                             dmesgItem.getServiceInfoItems().values())));
116                 }
117                 if (!dmesgItem.getStageInfoItems().isEmpty()) {
118                     metrics.putAll(
119                             Multimaps.forMap(analyzeDmesgStageInfo(dmesgItem.getStageInfoItems())));
120                 }
121                 if (!dmesgItem.getActionInfoItems().isEmpty()) {
122                     metrics.putAll(
123                             Multimaps.forMap(
124                                     analyzeDmesgActionInfo(dmesgItem.getActionInfoItems())));
125                 }
126             } catch (IOException ioe) {
127                 CLog.e("Failed to analyze the dmesg logs");
128                 CLog.e(ioe);
129             }
130         }
131         if (mBootloaderInfo) {
132             ArrayListMultimap<String, Double> bootLoaderTimingInfos =
133                     analyzeBootLoaderTimingInfo(metrics.get(DMESG_BOOT_COMPLETE_TIME));
134             metrics.putAll(bootLoaderTimingInfos);
135         }
136         return buildTfMetrics(metrics.asMap());
137     }
138 
139     /**
140      * Analyze the services info parsed from the dmesg logs and construct the metrics as a part of
141      * boot time data.
142      *
143      * @param serviceInfoItems contains the start time, end time and the duration of each service
144      *     logged in the dmesg log file.
145      * @return Map with dmesg metrics from info items
146      */
analyzeDmesgServiceInfo( Collection<DmesgServiceInfoItem> serviceInfoItems)147     private Map<String, Double> analyzeDmesgServiceInfo(
148             Collection<DmesgServiceInfoItem> serviceInfoItems) {
149         Map<String, Double> metrics = new HashMap<>();
150         for (DmesgServiceInfoItem infoItem : serviceInfoItems) {
151             String key = null;
152             if (infoItem.getStartTime() != null) {
153                 key = String.format("%s%s%s", INIT, infoItem.getServiceName(), START_TIME);
154             } else if (infoItem.getServiceDuration() != -1L) {
155                 key = String.format("%s%s%s", INIT, infoItem.getServiceName(), DURATION);
156             } else if (infoItem.getEndTime() != null) {
157                 key = String.format("%s%s%s", INIT, infoItem.getServiceName(), END_TIME);
158             }
159             if (key != null) {
160                 Double value = infoItem.getStartTime().doubleValue();
161                 metrics.put(key, value);
162             }
163         }
164         return metrics;
165     }
166 
167     /**
168      * Analyze the boot stages info parsed from the dmesg logs and construct the metrics as a part
169      * of boot time data.
170      *
171      * @param stageInfoItems contains the start time of each stage logged in the dmesg log file.
172      * @return Map with dmesg metrics from info items
173      */
analyzeDmesgStageInfo( Collection<DmesgStageInfoItem> stageInfoItems)174     private Map<String, Double> analyzeDmesgStageInfo(
175             Collection<DmesgStageInfoItem> stageInfoItems) {
176         Map<String, Double> metrics = new HashMap<>();
177         for (DmesgStageInfoItem stageInfoItem : stageInfoItems) {
178             if (stageInfoItem.getStartTime() != null) {
179                 String key =
180                         String.format(
181                                 "%s%s%s", INIT_STAGE, stageInfoItem.getStageName(), START_TIME);
182                 metrics.put(key, stageInfoItem.getStartTime().doubleValue());
183             }
184             if (stageInfoItem.getDuration() != null) {
185                 metrics.put(
186                         stageInfoItem.getStageName(), stageInfoItem.getDuration().doubleValue());
187             }
188         }
189         return metrics;
190     }
191 
192     /**
193      * Analyze each action info parsed from the dmesg logs and construct the metrics as a part of
194      * boot time data.
195      *
196      * @param actionInfoItems contains the start time of processing of each action logged in the
197      *     dmesg log file.
198      * @return Map with dmesg metrics from info items
199      */
analyzeDmesgActionInfo( Collection<DmesgActionInfoItem> actionInfoItems)200     private Map<String, Double> analyzeDmesgActionInfo(
201             Collection<DmesgActionInfoItem> actionInfoItems) {
202         boolean isFirstBootCompletedAction = true;
203         Map<String, Double> metrics = new HashMap<>();
204         for (DmesgActionInfoItem actionInfoItem : actionInfoItems) {
205             if (actionInfoItem.getStartTime() != null) {
206                 if (actionInfoItem.getActionName().startsWith(BOOT_COMPLETE_ACTION)
207                         && isFirstBootCompletedAction) {
208                     CLog.i(
209                             "Using Action: %s_%s for first boot complete timestamp :%s",
210                             actionInfoItem.getActionName(),
211                             actionInfoItem.getSourceName(),
212                             actionInfoItem.getStartTime().doubleValue());
213                     // Record the first boot complete time stamp.
214                     metrics.put(
215                             DMESG_BOOT_COMPLETE_TIME, actionInfoItem.getStartTime().doubleValue());
216                     isFirstBootCompletedAction = false;
217                 }
218                 String key =
219                         String.format(
220                                 "%s%s_%s%s",
221                                 ACTION,
222                                 actionInfoItem.getActionName(),
223                                 actionInfoItem.getSourceName() != null
224                                         ? actionInfoItem.getSourceName()
225                                         : "",
226                                 START_TIME);
227                 metrics.put(key, actionInfoItem.getStartTime().doubleValue());
228             }
229         }
230         return metrics;
231     }
232 
analyzeBootLoaderTimingInfo( List<Double> dmesgBootCompleteTimes)233     private ArrayListMultimap<String, Double> analyzeBootLoaderTimingInfo(
234             List<Double> dmesgBootCompleteTimes) {
235         int iteration = 0;
236         ArrayListMultimap<String, Double> metrics = ArrayListMultimap.create();
237         if (dmesgBootCompleteTimes.size() != mBootLoaderPropValues.size()) {
238             CLog.w(
239                     String.format(
240                             "Bootloader prop values list size does not match dmesg boot complete "
241                                     + "time list size. %d vs %d",
242                             mBootLoaderPropValues.size(), dmesgBootCompleteTimes.size()));
243         }
244         for (String bootLoaderVal : mBootLoaderPropValues) {
245             if (!bootLoaderVal.isEmpty() && bootLoaderVal.split(",").length >= 2) {
246                 String[] bootLoaderPhases = bootLoaderVal.split(",");
247                 double bootLoaderTotalTime = 0d;
248                 for (String bootLoaderPhase : bootLoaderPhases) {
249                     String[] bootKeyVal = bootLoaderPhase.split(":");
250                     String key = String.format("%s%s", BOOTLOADER_PREFIX, bootKeyVal[0]);
251                     metrics.put(key, Double.parseDouble(bootKeyVal[1]));
252                     // SW is the time spent on the warning screen. So ignore it in
253                     // final boot time calculation.
254                     if (!BOOTLOADER_PHASE_SW.equalsIgnoreCase(bootKeyVal[0])) {
255                         bootLoaderTotalTime += Double.parseDouble(bootKeyVal[1]);
256                     }
257                 }
258 
259                 // Report bootloader time as well in the dashboard.
260                 CLog.i("Bootloader time is: %s", bootLoaderTotalTime);
261                 metrics.put(BOOTLOADER_TIME, bootLoaderTotalTime);
262 
263                 // First "action_sys.boot_completed=1_START_TIME" is parsed already from dmesg logs.
264                 // Calculate the sum of bootLoaderTotalTime and boot completed flag set time.
265                 double bootCompleteTime =
266                         iteration >= dmesgBootCompleteTimes.size()
267                                 ? 0L
268                                 : dmesgBootCompleteTimes.get(iteration);
269                 double totalBootTime = bootLoaderTotalTime + bootCompleteTime;
270                 metrics.put(TOTAL_BOOT_TIME, totalBootTime);
271             } else {
272                 CLog.w(
273                         "Boot time prop value is empty for iteration %d. Skipping metric"
274                                 + " calculation",
275                         iteration);
276             }
277             iteration++;
278         }
279         return metrics;
280     }
281 }
282