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