Merge "lcan.py logcat analyzer for comparing logcats"

1 files changed, 692 insertions, 0 deletions

diff --git a/perf_tools/bats/lcan.py b/perf_tools/bats/lcan.py
new file mode 100755
index 00000000..cfe381a4
--- /dev/null
+++ b/perf_tools/bats/lcan.py
@@ -0,0 +1,692 @@
+#!/usr/bin/python3
+# -------------------------------------------
+# logcat analysis
+# -------------------------------------------
+from ast import keyword
+from curses import keyname
+import argparse
+import os
+from string import digits
+from sbtaTools import TextFile
+import datetime
+import re
+import shlex
+import glob
+
+class LCItem:
+	def __init__(self, lCTimeProcessor):
+		self.dateTime = 0
+		self.relativeTime = 0
+		self.key = ""
+		self.moduleName = ""
+		self.keyword = ""
+		self.valueMsec = 0
+		self.lCTimeProcessor = lCTimeProcessor
+		self.lines = []
+
+	def set(self, dateTime, moduleName, keyText, valueMsec):
+		try:
+			self.dateTime = dateTime
+			self.relativeTime = self.lCTimeProcessor.toRelativeTime(self.dateTime)
+			self.moduleName = moduleName
+			self.keyword = keyText
+			self.key = moduleName+":" + keyText
+			self.valueMsec = valueMsec
+		except Exception as e:
+			errLine = "LCItem:set() ERROR Failed: " + str(e)
+			assert False, errLine
+
+	def copy(self, otherLCItem):
+		self.dateTime = otherLCItem.dataTime
+		self.relativeTime = otherLCItem.relativeTime
+		self.key = otherLCItem.key
+		self.moduleName = otherLCItem.moduleName
+		self.keyword = otherLCItem.keyword
+		self.valueMsec = otherLCItem.valueMsec
+		self.lCTimeProcessor = otherLCItem.lcTimeProcessor
+		self.lines = otherLCItem.lines
+
+	def appendLine(self, line):
+		self.lines.append(line)
+
+	def keyEqual(self, otherItem):
+		if self.key != otherItem.key:
+			return False
+		return True
+
+	def add(self, otherItem):
+		assert(self.key==otherItem.key)
+		self.lines.extend(otherItem.lines)
+		self.valueMsec = self.valueMsec + otherItem.valueMsec
+		return True
+
+	def addValue(self, otherLCItem):
+		if self.key=="":
+			self.copy(otherLCItem)
+		else:
+			assert(self.key==otherLCItem.key)
+			self.valueMsec = self.valueMsec + otherLCItem.valueMsec
+		return True
+
+	def divideValue(self, number):	# scaler divide
+		self.valueMsec = self.valueMsec / number
+		return True
+
+	def key(self):
+		return self.key
+
+	def print(self):
+		#systemTime = self.lCTimeProcessor.toSystemTime(self.dateTime)
+		#relativeTime = self.lCTimeProcessor.toRelativeTime(self.dateTime)
+		newTimeString = str(self.relativeTime)
+		if (len(self.lines)>0):
+			print("{} {}: {} {:.4f} - {}".format(newTimeString, self.moduleName, self.keyword, self.valueMsec, self.lines[0]))
+		else:
+			print("{} {}: {} {:.4f} -".format(newTimeString, self.moduleName, self.keyword, self.valueMsec))
+
+	def printLines(self, prefix, min):
+		if (len(self.lines)<min):
+			return
+		for line in self.lines:
+			print("     {}{}".format(prefix, line))
+
+	def findModuleName(self, lineTextWords):
+		colonIndex = -1
+		try:
+			colonIndex = lineTextWords.index(":")
+			# address case of colon with no space
+			moduleName = lineTextWords[colonIndex-1]
+		except:
+			moduleName = ""
+		if colonIndex==-1:
+			for word in reversed(lineTextWords):
+				index = word.find(":")
+				if index!=-1:
+					moduleName = word[:index]
+					break
+		moduleName = moduleName.strip()
+		return colonIndex, moduleName
+
+	def parseLineWithTook(self, line):
+		maxLineLength = 100
+		stage = 0
+		try:
+			words = line.split("  ")
+			dataTimeO = self.lCTimeProcessor.parseTimeStamp(line)
+			if line.find("took to complete") != -1:
+				stage = 1
+				tookIndex = line.find(" took to complete:")
+				uptoEnd= line[:tookIndex]
+				lineTextWords = uptoEnd.split()
+				colonIndex, moduleName = self.findModuleName(lineTextWords)
+				keyword  = " ".join([lineTextWords[6]])
+				value = re.findall(r'\d+', line[tookIndex:])[-1]
+				value = float(value)
+
+			elif line.find("took") != -1:
+				stage = 2
+				tookIndex = line.find(" took")
+				uptoEnd= line[:tookIndex]
+				uptoBracket = uptoEnd.rfind("(")
+				if uptoBracket != -1:
+					uptoEnd = uptoEnd[:uptoBracket]
+				#uptoEnd = uptoEnd.replace(":", "")
+				lineTextWords = shlex.split(uptoEnd)
+				colonIndex, moduleName = self.findModuleName(lineTextWords)
+				# if there is colon only take words after it
+				if colonIndex!=-1:
+					lineTextWords = lineTextWords[colonIndex+1:]
+				numWords = len(lineTextWords)
+				keyword = ""
+				stage = 3
+				try:
+					for i in range(max(numWords-3, 0), numWords, 1):
+						keyword  = keyword + " " + lineTextWords[i]
+				except Exception as e:
+					errLine = "LCItem:parseLineWithTook() ERROR Failed to parse1: " + str(e)
+					print(errLine)
+					assert False, errLine
+
+				# reduce length
+				keyword = keyword[:maxLineLength]
+				keyword = keyword.strip()
+				# using regex expression to replace all numbers
+				keyword = re.sub(r'\d', "_", keyword)
+				value = 0
+				stage = 4
+				try:
+					multplier = 1
+					tookSubstring = line[tookIndex:]
+					secondsIndex = tookSubstring.find("seconds")
+					msIndex = tookSubstring.find("ms")
+					if (secondsIndex!=-1):
+						tookSubstring = tookSubstring[:secondsIndex]
+						multiplier = 1000
+					elif msIndex != -1:
+						tookSubstring = tookSubstring[:msIndex]
+					else:
+						# known exception
+						if tookSubstring.find("properties")==-1:
+							errLine = "LCItem:parseLineWithTook() ERROR invalid took in substring 1B {}".format(line)
+							print(errLine)
+							assert False, errLine
+							return False
+
+					values = re.findall(r'[\d\.\d]+', tookSubstring)
+					while "." in values:
+						values.remove(".")
+					value = float(values[-1])
+					if line.find("seconds") != -1:
+						value = value * multiplier
+				except Exception as e:
+					errLine = "LCItem:parseLineWithTook() ERROR Failed to parse2: " + str(e)
+					print(errLine)
+					assert False, errLine
+				stage = 5
+
+			else:
+				return False
+
+			stage = 6
+			self.set(dataTimeO, moduleName, keyword, value)
+			stage = 7
+			self.lines.append(line)
+
+			return True
+
+		except Exception as e:
+			errLine = "LCItem:parseLineWithTook() ERROR Failed to parse3:" + str(e)
+			print(errLine, stage)
+			assert False, errLine
+
+	def parseLine(self, line):
+		try:
+			words = line.split("  ")
+			dateTimeO = self.lCTimeProcessor.parseTimeStamp(line)
+			if (dateTimeO!=None):
+				#lcItem = LCItem(self.lCTimeProcessor)
+				newLine = line[19:].rstrip()
+				self.set(dateTimeO, "", newLine, 0)
+				#self.print()
+				return
+			else:
+				return None
+
+		except Exception as e:
+			errLine = "LCItem:parseLine() ERROR Failed to parse3:" + str(e)
+			print(errLine)
+			assert False, errLine
+
+	def find(self, keyword):
+		if self.key.find(keyword)!=-1:
+			return True
+		for line in self.lines:
+			if line.find(keyword)!=-1:
+				return True
+
+	def createLogLine(self):
+		line = ""
+		msecs = self.dateTime.strftime("%f")
+		timeString = self.dateTime.strftime("%m-%d %H:%M:%S.")
+		#timeString = timeString + msecs[]
+		return line
+
+class LCItemSet:
+	def __init__(self, item1, item2):
+		self.item1 = item1
+		self.item2 = item2
+		if (item1.key != "" and item2.key != ""):
+			assert(item1.key == item2.key)
+		if (item1.key!=""):
+			self.key = item1.key
+		else:
+			self.key = item2.key
+		self.diff = item2.valueMsec - item1.valueMsec
+
+	def __gt__(self, other):
+			if(self.diff>other.diff):
+				return True
+			else:
+				return False
+
+	def add(item):
+		assert(False)
+
+	def print(self, min, printAll):
+		self.diff = self.item2.valueMsec - self.item1.valueMsec
+		if abs(self.diff)<min:
+			return
+		flag = "12"
+		if self.item1.key=="":
+			flag = "-2"
+
+		if self.item2.key=="":
+			flag = "1-"
+
+		print("{}, {}, {}, {}, {}".format(self.key, self.item1.valueMsec, self.item2.valueMsec, self.diff, flag))
+		if printAll:
+			self.item1.printLines("1> ", 1)
+			self.item2.printLines("2> ", 1)
+
+class LCItemMap:
+	def __init__(self):
+		self.map = {}
+
+	def put(self, newItem):
+		item = self.map.get(newItem.key)
+		if item==None:
+			self.map[newItem.key] = newItem
+		else:
+			item.add(newItem)
+
+	def print(self):
+		for key in self.map:
+			self.map[key].print()
+
+	def find(self, keyword):
+		lCItems = []
+		for index, lCItem in self.map:
+			if lCItem.find(keyword):
+				lCItems.append(lCItem)
+		return lCItems
+
+	def addValues(self, other):
+		for index, item in other.map.items():
+			if item.key in self.map:
+				self.map[item.key].addValue(item)
+			else:
+				self.map[item.key] = item
+
+	def divideValue(self, number):
+		for index, item in self.map:
+			item.divideValue(number)
+
+class LCItemSetMap:
+	def __init__(self):
+		self.map = {}
+
+	def put(self, itemSet):
+		item = self.map.get(itemSet.key)
+		if item==None:
+			self.map[itemSet.key] = itemSet
+		else:
+			item.add(itemSet)
+
+	def printSorted(self, printAll):
+		a = sorted(self.map.items(), key=lambda x: (x[1], x[0]), reverse=True)
+		cumDif = 0
+		print("Key, Value1, Value2, diff")
+		for item in a:
+			item[1].print(1, printAll)
+			cumDif = cumDif + item[1].diff
+		print("CUMULATIVE DIFF: {}".format(cumDif))
+
+class LCTimeProcessor:
+	def __init__(self):
+		self.firstKernelTimeStamp = 0
+		self.lastKernelTimeStamp = 0
+		self.firstSystemTimesStamp = 0
+		self.lastTimeStamp = 0
+		self.zeroRelativeTime = 0
+		today = datetime.datetime.now()
+		year = str(today.year)
+		self.currentYear = year[-2:] # 2022/2023
+
+	def parseTimeStamp(self, line):
+		try:
+			if len(line)<19:
+				return None
+			currentYear = self.currentYear	# 22
+			words = line.split("  ")
+			timeString = words[0]
+			#timeString = re.sub("[^0-9: -.]", "", timeString)
+			timeString = timeString.strip()
+			timeString = timeString[:18]
+			timeString = currentYear + "-" + timeString
+			dataTimeO = datetime.datetime.strptime(timeString, "%Y-%m-%d %H:%M:%S.%f")
+			return dataTimeO
+		except Exception as e:
+			# If no time stamp on this line
+			if line.find("beginning of")!=-1:
+				return None
+			errLine = "LCItem:parseTimeStamp() ERROR Failed to parse:" + str(e)
+			print(errLine)
+			assert False, errLine
+			return None
+
+
+	def process(self, line):
+		timeStamp = self.parseTimeStamp(line)
+		if timeStamp==None:
+			return False
+
+		if self.firstKernelTimeStamp==0:
+			self.firstKernelTimeStamp = timeStamp
+		else:
+			if timeStamp < self.firstKernelTimeStamp:
+				return False
+
+			timeChange = timeStamp - self.lastTimeStamp
+			if (timeChange.total_seconds() > 68*5):
+				if self.firstSystemTimesStamp ==0:
+					self.firstSystemTimesStamp = timeStamp
+					self.lastKernelTimeStamp = self.lastTimeStamp
+					self.zeroRelativeTime = self.toSystemTime(self.firstKernelTimeStamp)
+
+		self.lastTimeStamp = timeStamp
+		return True
+
+	def toSystemTime(self, timeStamp):
+		try:
+			# if no systemTime is found, it must all be system time
+			if self.firstSystemTimesStamp==0:
+				self.firstSystemTimesStamp = self.firstKernelTimeStamp
+				self.lastKernelTimeStamp = self.lastTimeStamp
+				self.zeroRelativeTime = self.firstKernelTimeStamp
+				return timeStamp
+			if timeStamp >= self.firstSystemTimesStamp:
+				return timeStamp
+			else:
+				timeChange = timeStamp - self.lastKernelTimeStamp
+				systemTime = self.firstSystemTimesStamp + timeChange
+				return systemTime
+		except Exception as e:
+			errLine = "LogLine:parseLine() ERROR Failed to parse3:" + str(e)
+			print(errLine)
+			assert False, errLine
+
+	def toRelativeTime(self, timeStamp):
+		systemTime = self.toSystemTime(timeStamp)
+		relativeTime = systemTime - self.zeroRelativeTime
+		return relativeTime
+
+		if timeStamp< self.firstSystemTimesStamp:
+			timeChange = timeStamp - self.lastKernelTimeStamp
+			systemTime = self.firstSystemTimesStamp + timeChange
+			return systemTime
+		else:
+			return timeStamp
+
+	def toString(self, timeStamp):
+		return timeStamp.strftime("%Y-%m-%d %H:%M:%S.%f")
+
+class LCLogLine:
+	def __init__(self, lCTimeProcessor):
+		self.dateTime = 0
+		self.relativeTime = 0
+		self.lineText = ""
+		self.lCTimeProcessor = lCTimeProcessor
+
+	def set(self, dateTime, lineText):
+		self.dateTime = dateTime
+		self.relativeTime = self.lCTimeProcessor.toRelativeTime(self.dateTime)
+		self.lineText = lineText
+
+	def print(self):
+		newTimeString = str(self.relativeTime)
+		print("{}{}".format(newTimeString, self.lineText))
+
+	def parseLine(self, line):
+		try:
+			dateTimeO = self.lCTimeProcessor.parseTimeStamp(line)
+			if (dateTimeO!=None):
+				lineText = line[19:].rstrip()
+				self.set(dateTimeO, lineText)
+				return
+			else:
+				return None
+
+		except Exception as e:
+			errLine = "LogLine:parseLine() ERROR Failed to parse3:" + str(e)
+			print(errLine)
+			assert False, errLine
+
+	def find(self, word):
+		if (self.lineText.find(word)!=-1):
+			return True
+		else:
+			return False
+
+	def findAll(self, words):
+		for word in words:
+			if (self.lineText.find(word)==-1):
+				return False
+		return True
+
+class LCLogFile(TextFile):
+	priorTimeStamp = 0.0
+	def __init__(self, _fileName = ""):
+		super(LCLogFile, self).__init__(_fileName)
+		self.linesWithTook = []
+		self.linesWithTookToComplete = []
+		self.linesWithoutTookToComplete = []
+		self.firstKernelTimeStamp = 0
+		self.lastKernelTimeStamp = 0
+		self.firstSystemTimesStamp = 0
+		self.lastTimeStamp = 0
+		self.lCTimeProcessor = LCTimeProcessor()
+		self.dumpLinesBeforeBeginning()
+
+	def dumpLinesBeforeBeginning(self):
+		# start from --------- beginning of kernel
+		beginningFound = False
+		_lines = []
+		for line in self.lines:
+			if beginningFound==True:
+				_lines.append(line)
+				self.lCTimeProcessor.process(line)
+
+			elif line.find("beginning of kernel") != -1:
+				beginningFound = True
+
+		self.lines = _lines
+
+
+	def scanTook(self):
+		lCItemMap = LCItemMap()
+		foundBeginning = False
+		for line in self.lines:
+			# start at beginning
+			if not foundBeginning:
+				if line.find("beginning of kernel=1") != -1:
+					foundBeginning = True
+					continue
+
+			# stop if boot complete
+			if line.find("sys.boot_completed=1") != -1:
+				break
+
+			if line.find("took") != -1:
+				self.linesWithTook.append(line.rstrip())
+
+		for line in self.linesWithTook:
+			lCItem = LCItem(self.lCTimeProcessor)
+			if lCItem.parseLineWithTook(line)==True:
+				lCItemMap.put(lCItem)
+
+		return lCItemMap
+
+	def print(self, numItems=None):
+		self.scanTook()
+
+	def convert(self, numItems=None):
+		lcLogLines = []
+		for line in self.lines:
+			lcLogLine = LCLogLine(self.lCTimeProcessor)
+			lcLogLine.parseLine(line)
+			lcLogLines.append(lcLogLine)
+		return lcLogLines
+'''
+	def createLCFile(self, fileName):
+		# create LCTimeProcessor
+		# create LCItem
+		# create LCLogLine
+		# write LCLogLine to file
+'''
+class ScanFile:
+	def __init__(self):
+		self.fileName = "none"
+
+	def scanKeyWords(self, fileName):
+		print("Scanning {}".format(fileName))
+		cmd = "grep \"apexd: wait for '\/dev\/loop-control'\" {}".format(fileName)
+		x = os.system(cmd)
+		cmd = "grep \"Service 'apexd-bootstrap\" {}".format(fileName)
+		x = os.system(cmd)
+		cmd = "grep apexd.status=activated {}".format(fileName)
+		x = os.system(cmd)
+		cmd = "grep \"Service 'bpfloader'\" {}".format(fileName)
+		x = os.system(cmd)
+		cmd = "grep \"sys.boot_completed=1\" {} | head -n 1".format(fileName)
+		x = os.system(cmd)
+
+	def scanTook(self, fileName):
+		lCLogFile = LCLogFile(fileName)
+		lCItemMap = lCLogFile.scanTook()
+
+	def convert(self, fileName):
+		lCLogFile = LCLogFile(fileName)
+		lcItems = lCLogFile.convert()
+		for lcItem in lcItems:
+			lcItem.print()
+
+	def phases(self, fileName):
+		keywordFile = TextFile("keywords")
+		#keywords = ['init first', 'init second', "Starting phase 200", "boot_completed"]
+
+		lCLogFile = LCLogFile(fileName)
+		keywordSets = []
+		for line in keywordFile.lines:
+			line = line.strip()
+			keywordSet = line.split(", ")
+			keywordSets.append(keywordSet)
+
+		lcLogLines = lCLogFile.convert()
+		for keywordSet in keywordSets:
+			for lcLogLine in lcLogLines:
+				if lcLogLine.findAll(keywordSet)==True:
+					lcLogLine.print()
+					break
+
+class Compare:
+	def __init__(self):
+		self.fileName = "none"
+
+	def compareLCItemMaps(self, lCItemMap1, lCItemMap2):
+		lCItemSetMap = LCItemSetMap()
+
+		for item1key in lCItemMap1.map:
+			found = False
+			for item2key in lCItemMap2.map:
+				if item2key==item1key:
+					lcItemSet = LCItemSet(lCItemMap1.map[item1key], lCItemMap2.map[item2key])
+					lCItemSetMap.put(lcItemSet)
+					found = True
+					break
+			# if item1Key is not in ItemMap2, add a null item
+			if found==False:
+				lCTimeProcessor = LCTimeProcessor()
+				nullLCItem = LCItem(lCTimeProcessor)
+				lcItemSet = LCItemSet(nullLCItem, lCItemMap1.map[item1key])
+				lCItemSetMap.put(lcItemSet)
+				found = True
+
+		lCItemSetMap.printSorted(printAll)
+		return lCItemSetMap
+
+	def compareFiles(self, fileName1, fileName2, printAll):
+		print("---------------------------------------------------------------")
+		print("lcan.py -cmp {} {}".format(fileName1, fileName2))
+		print("---------------------------------------------------------------")
+		lCLogFile1 = LCLogFile(fileName1)
+		lCItemMap1 = lCLogFile1.scanTook()
+		lCLogFile2 = LCLogFile(fileName2)
+		lCItemMap2 = lCLogFile2.scanTook()
+
+		lCItemSetMap = LCItemSetMap()
+
+		for item1key in lCItemMap1.map:
+			found = False
+			for item2key in lCItemMap2.map:
+				if item2key==item1key:
+					lcItemSet = LCItemSet(lCItemMap1.map[item1key], lCItemMap2.map[item2key])
+					lCItemSetMap.put(lcItemSet)
+					found = True
+					break
+			# if item1Key is not in ItemMap2, add a null item
+			if found==False:
+				lCTimeProcessor = LCTimeProcessor()
+				nullLCItem = LCItem(lCTimeProcessor)
+				lcItemSet = LCItemSet(nullLCItem, lCItemMap1.map[item1key])
+				lCItemSetMap.put(lcItemSet)
+				found = True
+
+		lCItemSetMap.printSorted(printAll)
+		return lCItemSetMap
+
+	def getAverageOfDir(self, buildId):
+		#get average values for build1
+		dirList = glob.glob("{}/LC-{}*.txt".format(buildId, buildId))
+		numFiles = len(dirList)
+		#iterate in numerical order
+		lCItemMapS = LCItemMap()
+		for index in range(numFiles):
+			fileName = "{}/LC-{}-{}.txt".format(buildId, buildId, index)
+		#for index, fileName in enumerate(dirList):
+			lCLogFile = LCLogFile(fileName)
+			lCItemMap = lCLogFile.scanTook()
+			lCItemMapS.addValues(lCItemMap)
+		lCItemMapS.divideValue(numFiles)
+		return lCItemMapS
+
+	def compareDirs(self, buildId1, buildId2, printAll):
+		print("---------------------------------------------------------------")
+		print("lcan.py -cmpd {} {} {}".format(buildId1, buildId2, printAll))
+		print("---------------------------------------------------------------")
+
+		#get average values for build1
+		lCItemMap1 = self.getAverageOfDir(buildId1)
+		lCItemMap2 = self.getAverageOfDir(buildId2)
+		self.compareLCItemMaps(self, lCItemMap1, lCItemMap2)
+
+
+parser = argparse.ArgumentParser()
+parser.add_argument("-c", nargs=1, metavar=('<fileName>'), help="convert Logcat output to start from boot with converted timeStamps")
+parser.add_argument("-k", nargs=1, metavar=('<fileName>'), help="summary on keywords")
+parser.add_argument("-a", nargs=1, metavar=('<fileName>'), help="analyze file")
+parser.add_argument("-cmp", nargs=3, metavar=('<fileName1>', '<fileName2>', '<brief/all>'), help="compare logcat files")
+parser.add_argument("-cmpd", nargs=3, metavar=('<dirName1>', '<dirName2>', '<brief/all>'), help="compare logcat files")
+parser.add_argument("-p", nargs=1, metavar=('<fileName1>'), help="phase report on log files")
+args = parser.parse_args()
+
+if args.k!=None:
+	scanFile = ScanFile()
+	scanFile.scanKeyWords(args.k[0])
+
+if args.a!=None:
+	scanFile = ScanFile()
+	scanFile.scanTook(args.a[0])
+
+if args.c!=None:
+	scanFile = ScanFile()
+	scanFile.convert(args.c[0])
+
+if args.p!=None:
+	scanFile = ScanFile()
+	scanFile.phases(args.p[0])
+
+if args.cmp!=None:
+	printAll = False
+	compare = Compare()
+	if (len(args.cmp)>2):
+		if (args.cmp[2].find("all")!=-1):
+			printAll = True
+	compare.compareFiles(args.cmp[0], args.cmp[1], printAll)
+
+if args.cmpd!=None:
+	printAll = False
+	compare = Compare()
+	if (len(args.cmpd)>2):
+		if (args.cmpd[2].find("all")!=-1):
+			printAll = True
+	compare.compareDirs(args.cmpd[0], args.cmpd[1], printAll)