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 com.android.loganalysis.item.GenericTimingItem; 20 import com.android.loganalysis.item.SystemServicesTimingItem; 21 import com.android.loganalysis.parser.TimingsLogParser; 22 import com.android.tradefed.config.Option; 23 import com.android.tradefed.config.OptionClass; 24 import com.android.tradefed.log.LogUtil; 25 import com.android.tradefed.metrics.proto.MetricMeasurement.Metric; 26 import com.android.tradefed.result.LogFile; 27 import com.android.tradefed.result.TestDescription; 28 29 import com.google.common.collect.ArrayListMultimap; 30 import com.google.common.collect.Multimaps; 31 32 import java.io.BufferedReader; 33 import java.io.File; 34 import java.io.FileInputStream; 35 import java.io.IOException; 36 import java.io.InputStreamReader; 37 import java.util.Arrays; 38 import java.util.HashMap; 39 import java.util.HashSet; 40 import java.util.List; 41 import java.util.Map; 42 import java.util.Set; 43 import java.util.regex.Pattern; 44 import java.util.stream.Collectors; 45 46 /** A Post Processor that processes text file containing logcat logs into key-value pairs */ 47 @OptionClass(alias = "logcat-post-processor") 48 public class LogcatPostProcessor extends BaseBootTimeTestLogPostProcessor { 49 private static final String BOOT_PHASE_1000 = "starting_phase_1000"; 50 /** Matches the line indicating kernel start. It is starting point of the whole boot process */ 51 private static final Pattern KERNEL_START_PATTERN = Pattern.compile("Linux version"); 52 /** Matches the logcat line indicating boot completed */ 53 private static final Pattern LOGCAT_BOOT_COMPLETED = Pattern.compile("Starting phase 1000"); 54 55 // 03-10 21:43:40.328 1005 1005 D SystemServerTiming:StartWifi took to 56 // complete: 3474ms 57 // 03-10 21:43:40.328 1005 1005 D component:subcomponent took to complete: 58 // 3474ms 59 @Option( 60 name = "components", 61 shortName = 'c', 62 description = 63 "Comma separated list of component names to parse the granular boot info" 64 + " printed in the logcat.") 65 private String mComponentNames = null; 66 67 @Option( 68 name = "full-components", 69 shortName = 'f', 70 description = 71 "Comma separated list of component_subcomponent names to parse the granular" 72 + " boot info printed in the logcat.") 73 private String mFullCompNames = null; 74 75 @Option( 76 name = "boot-time-pattern", 77 description = 78 "Named boot time regex patterns which are used to capture signals in logcat and" 79 + " calculate duration between device boot to the signal being logged." 80 + " Key: name of custom boot metric, Value: regex to match single" 81 + " logcat line. Maybe repeated.") 82 private Map<String, String> mBootTimePatterns = new HashMap<>(); 83 84 private List<Double> mDmesgBootCompleteTimes; 85 86 /** {@inheritDoc} */ 87 @Override processTestMetricsAndLogs( TestDescription testDescription, HashMap<String, Metric> testMetrics, Map<String, LogFile> testLogs)88 public Map<String, Metric.Builder> processTestMetricsAndLogs( 89 TestDescription testDescription, 90 HashMap<String, Metric> testMetrics, 91 Map<String, LogFile> testLogs) { 92 LogUtil.CLog.v("Processing test logs for %s", testDescription.getTestName()); 93 if (!testMetrics.containsKey(DMESG_BOOT_COMPLETE_TIME)) { 94 LogUtil.CLog.w( 95 "Dmesg boot complete metric not found. Custom boot metrics will not be " 96 + "calculated"); 97 } else { 98 String dmesgBootCompleteStringValue = 99 testMetrics.get(DMESG_BOOT_COMPLETE_TIME).getMeasurements().getSingleString(); 100 mDmesgBootCompleteTimes = 101 Arrays.asList(dmesgBootCompleteStringValue.split(",")).stream() 102 .map(Double::parseDouble) 103 .toList(); 104 } 105 return processLogcatLogs(filterFiles(testLogs)); 106 } 107 108 /** {@inheritDoc} */ 109 @Override processRunMetricsAndLogs( HashMap<String, Metric> rawMetrics, Map<String, LogFile> runLogs)110 public Map<String, Metric.Builder> processRunMetricsAndLogs( 111 HashMap<String, Metric> rawMetrics, Map<String, LogFile> runLogs) { 112 // noop 113 return new HashMap<>(); 114 } 115 116 /** 117 * Process logcat testLog files reported by the test 118 * 119 * @param files List of logcat files 120 * @return Map with metric keys and stringified double values joined by comma 121 */ processLogcatLogs(List<File> files)122 private Map<String, Metric.Builder> processLogcatLogs(List<File> files) { 123 int iteration = 0; 124 ArrayListMultimap<String, Double> metrics = ArrayListMultimap.create(); 125 for (File file : files) { 126 LogUtil.CLog.d("Parsing logcat file %s", file.getPath()); 127 try { 128 Map<String, Double> granularBootMetricsMap = analyzeGranularBootInfo(file); 129 metrics.putAll(Multimaps.forMap(granularBootMetricsMap)); 130 if (!mBootTimePatterns.isEmpty()) { 131 Map<String, Double> customBootMetricMap = 132 analyzeCustomBootInfo(file, mDmesgBootCompleteTimes.get(iteration)); 133 metrics.putAll(Multimaps.forMap(customBootMetricMap)); 134 } else { 135 LogUtil.CLog.i( 136 "No boot-time-pattern values provided. Skipping analyzeCustomBootInfo"); 137 } 138 } catch (IndexOutOfBoundsException e) { 139 LogUtil.CLog.e("Missing dmesg boot complete signals for iteration %d", iteration); 140 LogUtil.CLog.e(e); 141 } 142 iteration++; 143 } 144 145 return buildTfMetrics(metrics.asMap()); 146 } 147 148 /** 149 * Parse the logcat file for granular boot info (eg different system services start time) based 150 * on the component name or full component name (i.e component_subcompname) 151 */ analyzeGranularBootInfo(File file)152 private Map<String, Double> analyzeGranularBootInfo(File file) { 153 Map<String, Double> metrics = new HashMap<>(); 154 String[] compStr = new String[0]; 155 String[] fullCompStr = new String[0]; 156 boolean isFilterSet = mComponentNames != null || mFullCompNames != null; 157 158 if (mComponentNames != null) { 159 compStr = mComponentNames.split(","); 160 } 161 if (mFullCompNames != null) { 162 fullCompStr = mFullCompNames.split(","); 163 } 164 165 Set<String> compSet = new HashSet<>(Arrays.asList(compStr)); 166 Set<String> fullCompSet = new HashSet<>(Arrays.asList(fullCompStr)); 167 168 try (InputStreamReader ir = new InputStreamReader(new FileInputStream(file)); 169 BufferedReader input = new BufferedReader(ir)) { 170 TimingsLogParser parser = new TimingsLogParser(); 171 List<SystemServicesTimingItem> items = parser.parseSystemServicesTimingItems(input); 172 for (SystemServicesTimingItem item : items) { 173 String componentName = item.getComponent(); 174 String fullCompName = 175 String.format("%s_%s", item.getComponent(), item.getSubcomponent()); 176 // If filter not set then capture timing info for all the components otherwise 177 // only for the given component names and full component names. 178 if (!isFilterSet 179 || compSet.contains(componentName) 180 || fullCompSet.contains(fullCompName)) { 181 Double time = 182 item.getDuration() != null ? item.getDuration() : item.getStartTime(); 183 if (time != null) { 184 metrics.put(fullCompName, time); 185 } 186 } 187 } 188 } catch (IOException ioe) { 189 LogUtil.CLog.e("Problem parsing the granular boot information"); 190 LogUtil.CLog.e(ioe); 191 } 192 return metrics; 193 } 194 195 /** Parse the logcat file to get boot time metrics given patterns defined by tester. */ analyzeCustomBootInfo(File file, double dmesgBootCompleteTime)196 private Map<String, Double> analyzeCustomBootInfo(File file, double dmesgBootCompleteTime) { 197 Map<String, Double> metrics = new HashMap<>(); 198 try (InputStreamReader ir = new InputStreamReader(new FileInputStream(file)); 199 BufferedReader input = new BufferedReader(ir)) { 200 List<GenericTimingItem> items = 201 createCustomTimingsParser().parseGenericTimingItems(input); 202 Map<String, GenericTimingItem> itemsMap = 203 items.stream() 204 .collect(Collectors.toMap(GenericTimingItem::getName, item -> item)); 205 if (!itemsMap.containsKey(BOOT_PHASE_1000)) { 206 LogUtil.CLog.e("Missing boot complete signals from logcat"); 207 return metrics; 208 } 209 for (Map.Entry<String, GenericTimingItem> metric : itemsMap.entrySet()) { 210 GenericTimingItem itemsForMetric = metric.getValue(); 211 if (itemsForMetric.getName().isEmpty()) { 212 LogUtil.CLog.e("Missing value for metric %s", metric.getKey()); 213 continue; 214 } 215 double duration = dmesgBootCompleteTime + itemsForMetric.getDuration(); 216 metrics.put(metric.getKey(), duration); 217 LogUtil.CLog.d( 218 "Added boot metric: %s with duration value: %f", metric.getKey(), duration); 219 } 220 } catch (IOException ioe) { 221 LogUtil.CLog.e("Problem parsing the custom boot information"); 222 LogUtil.CLog.e(ioe); 223 } 224 return metrics; 225 } 226 createCustomTimingsParser()227 private TimingsLogParser createCustomTimingsParser() { 228 TimingsLogParser parser = new TimingsLogParser(); 229 parser.addDurationPatternPair(BOOT_PHASE_1000, KERNEL_START_PATTERN, LOGCAT_BOOT_COMPLETED); 230 for (Map.Entry<String, String> pattern : mBootTimePatterns.entrySet()) { 231 LogUtil.CLog.d( 232 "Adding boot metric with name: %s, pattern: %s", 233 pattern.getKey(), pattern.getValue()); 234 parser.addDurationPatternPair( 235 pattern.getKey(), LOGCAT_BOOT_COMPLETED, Pattern.compile(pattern.getValue())); 236 } 237 return parser; 238 } 239 } 240