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 24 import com.google.common.annotations.VisibleForTesting; 25 26 import java.io.BufferedReader; 27 import java.io.IOException; 28 import java.util.List; 29 import java.util.Map; 30 import java.util.regex.Matcher; 31 import java.util.regex.Pattern; 32 33 34 /** 35 * Parse the dmesg logs. </p> 36 */ 37 public class DmesgParser implements IParser { 38 39 private static final String SERVICENAME = "SERVICENAME"; 40 private static final String TIMESTAMP = "TIMESTAMP"; 41 private static final String STAGE = "STAGE"; 42 private static final String ACTION = "ACTION"; 43 private static final String DURATION = "DURATION"; 44 private static final String UEVENTD = "ueventd"; 45 private static final String INIT = "init"; 46 47 // Matches: [ 14.822691] init: 48 private static final String SERVICE_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] init:\\s+", 49 TIMESTAMP); 50 // Matches: [ 3.791635] ueventd: 51 private static final String UEVENTD_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] ueventd:\\s+", 52 TIMESTAMP); 53 54 // Matches: starting service 'ueventd'... 55 private static final String START_SERVICE_SUFFIX = String.format("starting service " 56 + "\\'(?<%s>.*)\\'...", SERVICENAME); 57 // Matches: Service 'ueventd' (pid 439) exited with status 0 58 private static final String EXIT_SERVICE_SUFFIX = String.format("Service \\'(?<%s>.*)\\'\\s+" 59 + "\\((?<PID>.*)\\) exited with status 0.*", SERVICENAME); 60 61 private static final Pattern START_SERVICE = Pattern.compile( 62 String.format("%s%s", SERVICE_PREFIX, START_SERVICE_SUFFIX)); 63 private static final Pattern EXIT_SERVICE = Pattern.compile( 64 String.format("%s%s", SERVICE_PREFIX, EXIT_SERVICE_SUFFIX)); 65 66 // Matches: init first stage started! 67 // Matches: init second stage started! 68 private static final String START_STAGE_PREFIX = String.format("init (?<%s>.*) stage started!", 69 STAGE); 70 71 // Matches: [ 13.647997] init: init first stage started! 72 private static final Pattern START_STAGE = Pattern.compile( 73 String.format("%s%s", SERVICE_PREFIX, START_STAGE_PREFIX)); 74 75 // Matches: init: processing action (early-init) from (/init.rc:14) 76 private static final String START_PROCESSING_ACTION_PREFIX = 77 String.format("processing action \\((?<%s>.*)\\) from.*$", ACTION); 78 79 // Matches: init: processing action (early-init) 80 private static final String START_PROCESSING_ACTION_PREFIX_LEGACY = 81 String.format("processing action \\((?<%s>.*)\\).*$", ACTION); 82 83 // Matches: init: processing action (early-init) from (/init.rc:14) 84 private static final Pattern START_PROCESSING_ACTION = 85 Pattern.compile(String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX)); 86 87 // Matches: init: processing action (early-init) 88 private static final Pattern START_PROCESSING_ACTION_LEGACY = 89 Pattern.compile( 90 String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX_LEGACY)); 91 92 // Matches: [ 3.791635] ueventd: Coldboot took 0.695055 seconds 93 private static final String STAGE_SUFFIX= String.format( 94 "(?<%s>.*)\\s+took\\s+(?<%s>.*)\\s+seconds$", STAGE, DURATION); 95 private static final Pattern UEVENTD_STAGE_INFO = Pattern.compile( 96 String.format("%s%s", UEVENTD_PREFIX, STAGE_SUFFIX)); 97 98 private static final String PROPERTY_SUFFIX= String.format( 99 "(?<%s>.*)\\s+took\\s+(?<%s>.*)ms$", STAGE, DURATION); 100 // Matches [ 7.270487] init: Wait for property 'apexd.status=ready' took 230ms 101 private static final Pattern WAIT_FOR_PROPERTY_INFO = Pattern.compile( 102 String.format("%s%s", SERVICE_PREFIX, PROPERTY_SUFFIX)); 103 104 private DmesgItem mDmesgItem = new DmesgItem(); 105 106 /** 107 * {@inheritDoc} 108 */ 109 @Override parse(List<String> lines)110 public DmesgItem parse(List<String> lines) { 111 for (String line : lines) { 112 parse(line); 113 } 114 115 return mDmesgItem; 116 } 117 118 /** 119 * Parse the kernel log till EOF to retrieve the duration of the service calls, start times of 120 * different boot stages and actions taken. Besides, while parsing these informations are stored 121 * in the intermediate {@link DmesgServiceInfoItem}, {@link DmesgStageInfoItem} and 122 * {@link DmesgActionInfoItem} objects 123 * 124 * @param input dmesg log 125 * @throws IOException 126 */ parseInfo(BufferedReader bufferedLog)127 public DmesgItem parseInfo(BufferedReader bufferedLog) throws IOException { 128 String line; 129 while ((line = bufferedLog.readLine()) != null) { 130 parse(line); 131 } 132 133 return mDmesgItem; 134 } 135 136 /** 137 * <p> 138 * Parse single line of the dmesg log to retrieve the duration of the service calls or start 139 * times of different boot stages or start times of actions taken based on the info contained in 140 * the line. 141 * </p> 142 * <p> 143 * Besides, while parsing these informations are stored in the intermediate 144 * {@link DmesgServiceInfoItem}, {@link DmesgStageInfoItem} and {@link DmesgActionInfoItem} 145 * objects 146 * </p> 147 * 148 * @param line individual line of the dmesg log 149 */ parse(String line)150 private void parse(String line) { 151 152 if (parseServiceInfo(line)) { 153 return; 154 } 155 if (parseStageInfo(line)) { 156 return; 157 } 158 if (parseActionInfo(line)) { 159 return; 160 } 161 } 162 163 /** 164 * Parse init services {@code start time} and {@code end time} from each {@code line} of dmesg 165 * log and store the {@code duration} it took to complete the service if the end time stamp is 166 * available in {@link DmesgServiceInfoItem}. 167 * 168 * @param individual line of the dmesg log 169 * @return {@code true}, if the {@code line} indicates start or end of a service, 170 * {@code false}, otherwise 171 */ 172 @VisibleForTesting parseServiceInfo(String line)173 boolean parseServiceInfo(String line) { 174 Matcher match = null; 175 if ((match = matches(START_SERVICE, line)) != null) { 176 DmesgServiceInfoItem serviceItem = new DmesgServiceInfoItem(); 177 serviceItem.setServiceName(match.group(SERVICENAME)); 178 serviceItem.setStartTime((long) (Double.parseDouble( 179 match.group(TIMESTAMP)) * 1000)); 180 getServiceInfoItems().put(match.group(SERVICENAME), serviceItem); 181 return true; 182 } else if ((match = matches(EXIT_SERVICE, line)) != null) { 183 if (getServiceInfoItems().containsKey(match.group(SERVICENAME))) { 184 DmesgServiceInfoItem serviceItem = getServiceInfoItems().get( 185 match.group(SERVICENAME)); 186 serviceItem.setEndTime((long) (Double.parseDouble( 187 match.group(TIMESTAMP)) * 1000)); 188 } 189 return true; 190 } 191 return false; 192 } 193 194 /** 195 * Parse init stages log from each {@code line} of dmesg log and 196 * store the stage name, start time and duration if available in a 197 * {@link DmesgStageInfoItem} object 198 * 199 * @param individual line of the dmesg log 200 * @return {@code true}, if the {@code line} indicates start of a boot stage, 201 * {@code false}, otherwise 202 */ 203 @VisibleForTesting parseStageInfo(String line)204 boolean parseStageInfo(String line) { 205 Matcher match = null; 206 if ((match = matches(START_STAGE, line)) != null) { 207 DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem(); 208 stageInfoItem.setStageName(match.group(STAGE)); 209 stageInfoItem.setStartTime((long) (Double.parseDouble( 210 match.group(TIMESTAMP)) * 1000)); 211 mDmesgItem.addStageInfoItem(stageInfoItem); 212 return true; 213 } 214 if((match = matches(UEVENTD_STAGE_INFO, line)) != null) { 215 DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem(); 216 stageInfoItem.setStageName(String.format("%s_%s", UEVENTD, match.group(STAGE))); 217 stageInfoItem.setDuration((long) (Double.parseDouble( 218 match.group(DURATION)) * 1000)); 219 mDmesgItem.addStageInfoItem(stageInfoItem); 220 return true; 221 } 222 if((match = matches(WAIT_FOR_PROPERTY_INFO, line)) != null) { 223 DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem(); 224 stageInfoItem.setStageName(String.format("%s_%s", INIT, match.group(STAGE))); 225 stageInfoItem.setDuration((long) (Double.parseDouble( 226 match.group(DURATION)))); 227 mDmesgItem.addStageInfoItem(stageInfoItem); 228 return true; 229 } 230 231 return false; 232 } 233 234 /** 235 * Parse action from each {@code line} of dmesg log and store the action name and start time 236 * in {@link DmesgActionInfoItem} object 237 * 238 * @param individual {@code line} of the dmesg log 239 * @return {@code true}, if {@code line} indicates starting of processing of action 240 * {@code false}, otherwise 241 */ 242 @VisibleForTesting parseActionInfo(String line)243 boolean parseActionInfo(String line) { 244 Matcher match = null; 245 if ((match = matches(START_PROCESSING_ACTION, line)) != null 246 || (match = matches(START_PROCESSING_ACTION_LEGACY, line)) != null) { 247 DmesgActionInfoItem actionInfoItem = new DmesgActionInfoItem(); 248 actionInfoItem.setActionName(match.group(ACTION)); 249 actionInfoItem.setStartTime((long) (Double.parseDouble( 250 match.group(TIMESTAMP)) * 1000)); 251 mDmesgItem.addActionInfoItem(actionInfoItem); 252 return true; 253 } 254 return false; 255 } 256 257 /** 258 * Checks whether {@code line} matches the given {@link Pattern}. 259 * 260 * @return The resulting {@link Matcher} obtained by matching the {@code line} against 261 * {@code pattern}, or null if the {@code line} does not match. 262 */ matches(Pattern pattern, String line)263 private static Matcher matches(Pattern pattern, String line) { 264 Matcher ret = pattern.matcher(line); 265 return ret.matches() ? ret : null; 266 } 267 getServiceInfoItems()268 public Map<String, DmesgServiceInfoItem> getServiceInfoItems() { 269 return mDmesgItem.getServiceInfoItems(); 270 } 271 setServiceInfoItems(Map<String, DmesgServiceInfoItem> serviceInfoItems)272 public void setServiceInfoItems(Map<String, DmesgServiceInfoItem> serviceInfoItems) { 273 for(String key : serviceInfoItems.keySet()) { 274 mDmesgItem.addServiceInfoItem(key, serviceInfoItems.get(key)); 275 } 276 } 277 getStageInfoItems()278 public List<DmesgStageInfoItem> getStageInfoItems() { 279 return mDmesgItem.getStageInfoItems(); 280 } 281 getActionInfoItems()282 public List<DmesgActionInfoItem> getActionInfoItems() { 283 return mDmesgItem.getActionInfoItems(); 284 } 285 286 } 287