src/com/android/loganalysis/parser/TimingsLogParser.java - platform/tools/loganalysis - Git at Google

 /*
  * Copyright (C) 2019 The Android Open Source Project
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
  * You may obtain a copy of the License at
  *
  *      http://www.apache.org/licenses/LICENSE-2.0
  *
  * Unless required by applicable law or agreed to in writing, software
  * distributed under the License is distributed on an "AS IS" BASIS,
  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  * See the License for the specific language governing permissions and
  * limitations under the License
  */

 package com.android.loganalysis.parser;


 import com.android.loganalysis.item.GenericTimingItem;
 import com.android.loganalysis.item.IItem;
 import com.android.loganalysis.item.SystemServicesTimingItem;

 import java.io.BufferedReader;
 import java.io.IOException;
 import java.text.DateFormat;
 import java.text.ParseException;
 import java.text.SimpleDateFormat;
 import java.util.ArrayList;
 import java.util.HashMap;
 import java.util.HashSet;
 import java.util.List;
 import java.util.Map;
 import java.util.Set;
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;

 /**
  * An {@link IParser} to parse boot metrics from logcat. It currently assumes "threadtime" format of
  * logcat. It will parse duration metrics for some system services like System Server, Zygote,
  * System UI, e.t.c.
  *
  */
 public class TimingsLogParser implements IParser {

     private static final String SYSTEM_SERVICES_TIME_PREFIX =
             "^\\d*-\\d*\\s*\\d*:\\d*:\\d*.\\d*\\s*"
                     + "\\d*\\s*\\d*\\s*[DV]\\s*(?<componentname>.*):\\s*(?<subname>\\S*)\\s*";
     private static final String SYSTEM_SERVICES_TIME_SUFFIX = ":\\s*(?<time>.*)ms\\s*$";

     /** Used to parse time info from logcat lines */
     private static final DateFormat DEFAULT_TIME_FORMAT =
             new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");

     /**
      * Year is not important in timing info. Always use Unix time starting year for timestamp
      * conversion with simplicity
      */
     private static final String DEFAULT_YEAR = "1970";

     /**
      * Match the line with system services duration info like:
      *
      * <p>03-10 21:43:40.328 1005 1005 D SystemServerTiming:
      * StartKeyAttestationApplicationIdProviderService took to complete: 3474ms
      */
     private static final Pattern SYSTEM_SERVICES_DURATION =
             Pattern.compile(
                     String.format(
                             "%stook to complete%s",
                             SYSTEM_SERVICES_TIME_PREFIX, SYSTEM_SERVICES_TIME_SUFFIX));
     /**
      * Match the line with system services start time info like:
      *
      * <p>01-10 01:25:57.249 989 989 D BootAnimation: BootAnimationStartTiming start time: 8343ms
      */
     private static final Pattern SYSTEM_SERVICES_START_TIME =
             Pattern.compile(
                     String.format(
                             "%sstart time%s",
                             SYSTEM_SERVICES_TIME_PREFIX, SYSTEM_SERVICES_TIME_SUFFIX));

     private List<DurationPattern> durationPatterns = new ArrayList<>();

     private static class DurationPattern {
         String mName;
         Pattern mStartTimePattern;
         Pattern mEndTimePattern;

         DurationPattern(String name, Pattern startTimePattern, Pattern endTimePattern) {
             mName = name;
             mStartTimePattern = startTimePattern;
             mEndTimePattern = endTimePattern;
         }
     }

     @Override
     public IItem parse(List<String> lines) {
         throw new UnsupportedOperationException(
                 "Method has not been implemented in lieu of others");
     }

     /**
      * Add a pair of patterns matching the start and end signals in logcat for a duration metric
      *
      * @param name the name of the duration metric, it should be unique
      * @param startTimePattern the pattern matches the logcat line indicating start of duration
      * @param endTimePattern the pattern matches the logcat line indicating end of duration
      */
     public void addDurationPatternPair(
             String name, Pattern startTimePattern, Pattern endTimePattern) {
         DurationPattern durationPattern =
                 new DurationPattern(name, startTimePattern, endTimePattern);
         durationPatterns.add(durationPattern);
     }

     /** Cleanup added duration patterns */
     public void clearDurationPatterns() {
         durationPatterns.clear();
     }

     /**
      * Parse logcat lines with the added duration patterns and generate a list of {@link
      * GenericTimingItem} representing the duration items. Note, a duration pattern could have zero
      * or multiple matches
      *
      * @param input logcat lines
      * @return list of {@link GenericTimingItem}
      * @throws IOException
      */
     public List<GenericTimingItem> parseGenericTimingItems(BufferedReader input)
             throws IOException {
         List<GenericTimingItem> items = new ArrayList<>();
         String line;
         //Timing items that are partially matched after captured start time
         Map<String, Double> pendingItems = new HashMap<>();
         while ((line = input.readLine()) != null) {
             items.addAll(parseGenericTimingItem(line, pendingItems));
         }
         return items;
     }

     /**
      * Parse a particular logcat line to get duration items. One line could have be matched by
      * multiple patterns
      *
      * @param line logcat line
      * @param pendingItems timing items that are half-matched with only start time.
      * @return list of {@link GenericTimingItem}
      */
     private List<GenericTimingItem> parseGenericTimingItem(
             String line, Map<String, Double> pendingItems) {
         List<GenericTimingItem> items = new ArrayList<>();
         for (DurationPattern durationPattern : durationPatterns) {
             Matcher matcher = durationPattern.mStartTimePattern.matcher(line);
             if (matcher.find()) {
                 double startTimeMillis = parseTime(line);
                 pendingItems.put(durationPattern.mName, startTimeMillis);
                 continue;
             }
             matcher = durationPattern.mEndTimePattern.matcher(line);
             if (matcher.find()) {
                 double endTimeMillis = parseTime(line);
                 Double startTimeMillis = pendingItems.get(durationPattern.mName);
                 if (startTimeMillis != null) {
                     GenericTimingItem newItem = new GenericTimingItem();
                     newItem.setName(durationPattern.mName);
                     newItem.setStartAndEnd(startTimeMillis, endTimeMillis);
                     items.add(newItem);
                     pendingItems.remove(durationPattern.mName);
                 }
             }
         }
         return items;
     }

     /**
      * Get timestamp of current logcat line based on DEFAULT_YEAR
      *
      * @param line logcat line
      * @return timestamp
      */
     private double parseTime(String line) {
         String timeStr = String.format("%s-%s", DEFAULT_YEAR, line);
         try {
             return DEFAULT_TIME_FORMAT.parse(timeStr).getTime();
         } catch (ParseException e) {
             throw new RuntimeException(e);
         }
     }

     /**
      * A method that parses the logcat input for system services timing information. It will ignore
      * duplicated log lines and will keep multiple values for the same timing metric generated at
      * different time in the log
      *
      * @param input Logcat input as a {@link BufferedReader}
      * @return a list of {@link SystemServicesTimingItem}
      * @throws IOException
      */
     public List<SystemServicesTimingItem> parseSystemServicesTimingItems(BufferedReader input)
             throws IOException {
         Set<String> matchedLines = new HashSet<>();
         List<SystemServicesTimingItem> items = new ArrayList<>();
         String line;
         while ((line = input.readLine()) != null) {
             if (matchedLines.contains(line)) {
                 continue;
             }
             SystemServicesTimingItem item = parseSystemServicesTimingItem(line);
             if (item == null) {
                 continue;
             }
             items.add(item);
             matchedLines.add(line);
         }
         return items;
     }

     /**
      * Parse a particular log line to see if it matches the system service timing pattern and return
      * a {@link SystemServicesTimingItem} if matches, otherwise return null.
      *
      * @param line a single log line
      * @return a {@link SystemServicesTimingItem}
      */
     private SystemServicesTimingItem parseSystemServicesTimingItem(String line) {
         Matcher matcher = SYSTEM_SERVICES_DURATION.matcher(line);
         boolean durationMatched = matcher.matches();
         if (!durationMatched) {
             matcher = SYSTEM_SERVICES_START_TIME.matcher(line);
         }
         if (!matcher.matches()) {
             return null;
         }
         SystemServicesTimingItem item = new SystemServicesTimingItem();
         item.setComponent(matcher.group("componentname").trim());
         item.setSubcomponent(matcher.group("subname").trim());
         if (durationMatched) {
             item.setDuration(Double.parseDouble(matcher.group("time")));
         } else {
             item.setStartTime(Double.parseDouble(matcher.group("time")));
         }
         return item;
     }
 }
	/*
	* Copyright (C) 2019 The Android Open Source Project
	*
	* Licensed under the Apache License, Version 2.0 (the "License");
	* you may not use this file except in compliance with the License.
	* You may obtain a copy of the License at
	*
	* http://www.apache.org/licenses/LICENSE-2.0
	*
	* Unless required by applicable law or agreed to in writing, software
	* distributed under the License is distributed on an "AS IS" BASIS,
	* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
	* See the License for the specific language governing permissions and
	* limitations under the License
	*/

	package com.android.loganalysis.parser;


	import com.android.loganalysis.item.GenericTimingItem;
	import com.android.loganalysis.item.IItem;
	import com.android.loganalysis.item.SystemServicesTimingItem;

	import java.io.BufferedReader;
	import java.io.IOException;
	import java.text.DateFormat;
	import java.text.ParseException;
	import java.text.SimpleDateFormat;
	import java.util.ArrayList;
	import java.util.HashMap;
	import java.util.HashSet;
	import java.util.List;
	import java.util.Map;
	import java.util.Set;
	import java.util.regex.Matcher;
	import java.util.regex.Pattern;

	/**
	* An {@link IParser} to parse boot metrics from logcat. It currently assumes "threadtime" format of
	* logcat. It will parse duration metrics for some system services like System Server, Zygote,
	* System UI, e.t.c.
	*
	*/
	public class TimingsLogParser implements IParser {

	private static final String SYSTEM_SERVICES_TIME_PREFIX =
	"^\\d-\\d\\s\\d:\\d:\\d.\\d\\s"
	+ "\\d\\s\\d\\s[DV]\\s(?<componentname>.):\\s(?<subname>\\S)\\s*";
	private static final String SYSTEM_SERVICES_TIME_SUFFIX = ":\\s(?<time>.)ms\\s*$";

	/** Used to parse time info from logcat lines */
	private static final DateFormat DEFAULT_TIME_FORMAT =
	new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");

	/**
	* Year is not important in timing info. Always use Unix time starting year for timestamp
	* conversion with simplicity
	*/
	private static final String DEFAULT_YEAR = "1970";

	/**
	* Match the line with system services duration info like:
	*
	* <p>03-10 21:43:40.328 1005 1005 D SystemServerTiming:
	* StartKeyAttestationApplicationIdProviderService took to complete: 3474ms
	*/
	private static final Pattern SYSTEM_SERVICES_DURATION =
	Pattern.compile(
	String.format(
	"%stook to complete%s",
	SYSTEM_SERVICES_TIME_PREFIX, SYSTEM_SERVICES_TIME_SUFFIX));
	/**
	* Match the line with system services start time info like:
	*
	* <p>01-10 01:25:57.249 989 989 D BootAnimation: BootAnimationStartTiming start time: 8343ms
	*/
	private static final Pattern SYSTEM_SERVICES_START_TIME =
	Pattern.compile(
	String.format(
	"%sstart time%s",
	SYSTEM_SERVICES_TIME_PREFIX, SYSTEM_SERVICES_TIME_SUFFIX));

	private List<DurationPattern> durationPatterns = new ArrayList<>();

	private static class DurationPattern {
	String mName;
	Pattern mStartTimePattern;
	Pattern mEndTimePattern;

	DurationPattern(String name, Pattern startTimePattern, Pattern endTimePattern) {
	mName = name;
	mStartTimePattern = startTimePattern;
	mEndTimePattern = endTimePattern;
	}
	}

	@Override
	public IItem parse(List<String> lines) {
	throw new UnsupportedOperationException(
	"Method has not been implemented in lieu of others");
	}

	/**
	* Add a pair of patterns matching the start and end signals in logcat for a duration metric
	*
	* @param name the name of the duration metric, it should be unique
	* @param startTimePattern the pattern matches the logcat line indicating start of duration
	* @param endTimePattern the pattern matches the logcat line indicating end of duration
	*/
	public void addDurationPatternPair(
	String name, Pattern startTimePattern, Pattern endTimePattern) {
	DurationPattern durationPattern =
	new DurationPattern(name, startTimePattern, endTimePattern);
	durationPatterns.add(durationPattern);
	}

	/** Cleanup added duration patterns */
	public void clearDurationPatterns() {
	durationPatterns.clear();
	}

	/**
	* Parse logcat lines with the added duration patterns and generate a list of {@link
	* GenericTimingItem} representing the duration items. Note, a duration pattern could have zero
	* or multiple matches
	*
	* @param input logcat lines
	* @return list of {@link GenericTimingItem}
	* @throws IOException
	*/
	public List<GenericTimingItem> parseGenericTimingItems(BufferedReader input)
	throws IOException {
	List<GenericTimingItem> items = new ArrayList<>();
	String line;
	//Timing items that are partially matched after captured start time
	Map<String, Double> pendingItems = new HashMap<>();
	while ((line = input.readLine()) != null) {
	items.addAll(parseGenericTimingItem(line, pendingItems));
	}
	return items;
	}

	/**
	* Parse a particular logcat line to get duration items. One line could have be matched by
	* multiple patterns
	*
	* @param line logcat line
	* @param pendingItems timing items that are half-matched with only start time.
	* @return list of {@link GenericTimingItem}
	*/
	private List<GenericTimingItem> parseGenericTimingItem(
	String line, Map<String, Double> pendingItems) {
	List<GenericTimingItem> items = new ArrayList<>();
	for (DurationPattern durationPattern : durationPatterns) {
	Matcher matcher = durationPattern.mStartTimePattern.matcher(line);
	if (matcher.find()) {
	double startTimeMillis = parseTime(line);
	pendingItems.put(durationPattern.mName, startTimeMillis);
	continue;
	}
	matcher = durationPattern.mEndTimePattern.matcher(line);
	if (matcher.find()) {
	double endTimeMillis = parseTime(line);
	Double startTimeMillis = pendingItems.get(durationPattern.mName);
	if (startTimeMillis != null) {
	GenericTimingItem newItem = new GenericTimingItem();
	newItem.setName(durationPattern.mName);
	newItem.setStartAndEnd(startTimeMillis, endTimeMillis);
	items.add(newItem);
	pendingItems.remove(durationPattern.mName);
	}
	}
	}
	return items;
	}

	/**
	* Get timestamp of current logcat line based on DEFAULT_YEAR
	*
	* @param line logcat line
	* @return timestamp
	*/
	private double parseTime(String line) {
	String timeStr = String.format("%s-%s", DEFAULT_YEAR, line);
	try {
	return DEFAULT_TIME_FORMAT.parse(timeStr).getTime();
	} catch (ParseException e) {
	throw new RuntimeException(e);
	}
	}

	/**
	* A method that parses the logcat input for system services timing information. It will ignore
	* duplicated log lines and will keep multiple values for the same timing metric generated at
	* different time in the log
	*
	* @param input Logcat input as a {@link BufferedReader}
	* @return a list of {@link SystemServicesTimingItem}
	* @throws IOException
	*/
	public List<SystemServicesTimingItem> parseSystemServicesTimingItems(BufferedReader input)
	throws IOException {
	Set<String> matchedLines = new HashSet<>();
	List<SystemServicesTimingItem> items = new ArrayList<>();
	String line;
	while ((line = input.readLine()) != null) {
	if (matchedLines.contains(line)) {
	continue;
	}
	SystemServicesTimingItem item = parseSystemServicesTimingItem(line);
	if (item == null) {
	continue;
	}
	items.add(item);
	matchedLines.add(line);
	}
	return items;
	}

	/**
	* Parse a particular log line to see if it matches the system service timing pattern and return
	* a {@link SystemServicesTimingItem} if matches, otherwise return null.
	*
	* @param line a single log line
	* @return a {@link SystemServicesTimingItem}
	*/
	private SystemServicesTimingItem parseSystemServicesTimingItem(String line) {
	Matcher matcher = SYSTEM_SERVICES_DURATION.matcher(line);
	boolean durationMatched = matcher.matches();
	if (!durationMatched) {
	matcher = SYSTEM_SERVICES_START_TIME.matcher(line);
	}
	if (!matcher.matches()) {
	return null;
	}
	SystemServicesTimingItem item = new SystemServicesTimingItem();
	item.setComponent(matcher.group("componentname").trim());
	item.setSubcomponent(matcher.group("subname").trim());
	if (durationMatched) {
	item.setDuration(Double.parseDouble(matcher.group("time")));
	} else {
	item.setStartTime(Double.parseDouble(matcher.group("time")));
	}
	return item;
	}
	}