1#!/usr/bin/python3 2# ------------------------------------------- 3# logcat analysis 4# ------------------------------------------- 5from ast import keyword 6from curses import keyname 7import argparse 8import os 9from string import digits 10from sbtaTools import TextFile 11import datetime 12import re 13import shlex 14import glob 15 16class LCItem: 17 def __init__(self, lCTimeProcessor): 18 self.dateTime = 0 19 self.relativeTime = 0 20 self.key = "" 21 self.moduleName = "" 22 self.keyword = "" 23 self.valueMsec = 0 24 self.lCTimeProcessor = lCTimeProcessor 25 self.lines = [] 26 27 def set(self, dateTime, moduleName, keyText, valueMsec): 28 try: 29 self.dateTime = dateTime 30 self.relativeTime = self.lCTimeProcessor.toRelativeTime(self.dateTime) 31 self.moduleName = moduleName 32 self.keyword = keyText 33 self.key = moduleName+":" + keyText 34 self.valueMsec = valueMsec 35 except Exception as e: 36 errLine = "LCItem:set() ERROR Failed: " + str(e) 37 assert False, errLine 38 39 def copy(self, otherLCItem): 40 self.dateTime = otherLCItem.dataTime 41 self.relativeTime = otherLCItem.relativeTime 42 self.key = otherLCItem.key 43 self.moduleName = otherLCItem.moduleName 44 self.keyword = otherLCItem.keyword 45 self.valueMsec = otherLCItem.valueMsec 46 self.lCTimeProcessor = otherLCItem.lcTimeProcessor 47 self.lines = otherLCItem.lines 48 49 def appendLine(self, line): 50 self.lines.append(line) 51 52 def keyEqual(self, otherItem): 53 if self.key != otherItem.key: 54 return False 55 return True 56 57 def add(self, otherItem): 58 assert(self.key==otherItem.key) 59 self.lines.extend(otherItem.lines) 60 self.valueMsec = self.valueMsec + otherItem.valueMsec 61 return True 62 63 def addValue(self, otherLCItem): 64 if self.key=="": 65 self.copy(otherLCItem) 66 else: 67 assert(self.key==otherLCItem.key) 68 self.valueMsec = self.valueMsec + otherLCItem.valueMsec 69 return True 70 71 def divideValue(self, number): # scaler divide 72 self.valueMsec = self.valueMsec / number 73 return True 74 75 def key(self): 76 return self.key 77 78 def print(self): 79 #systemTime = self.lCTimeProcessor.toSystemTime(self.dateTime) 80 #relativeTime = self.lCTimeProcessor.toRelativeTime(self.dateTime) 81 newTimeString = str(self.relativeTime) 82 if (len(self.lines)>0): 83 print("{} {}: {} {:.4f} - {}".format(newTimeString, self.moduleName, self.keyword, self.valueMsec, self.lines[0])) 84 else: 85 print("{} {}: {} {:.4f} -".format(newTimeString, self.moduleName, self.keyword, self.valueMsec)) 86 87 def printLines(self, prefix, min): 88 if (len(self.lines)<min): 89 return 90 for line in self.lines: 91 print(" {}{}".format(prefix, line)) 92 93 def findModuleName(self, lineTextWords): 94 colonIndex = -1 95 try: 96 colonIndex = lineTextWords.index(":") 97 # address case of colon with no space 98 moduleName = lineTextWords[colonIndex-1] 99 except: 100 moduleName = "" 101 if colonIndex==-1: 102 for word in reversed(lineTextWords): 103 index = word.find(":") 104 if index!=-1: 105 moduleName = word[:index] 106 break 107 moduleName = moduleName.strip() 108 return colonIndex, moduleName 109 110 def parseLineWithTook(self, line): 111 maxLineLength = 100 112 stage = 0 113 try: 114 words = line.split(" ") 115 dataTimeO = self.lCTimeProcessor.parseTimeStamp(line) 116 if line.find("took to complete") != -1: 117 stage = 1 118 tookIndex = line.find(" took to complete:") 119 uptoEnd= line[:tookIndex] 120 lineTextWords = uptoEnd.split() 121 colonIndex, moduleName = self.findModuleName(lineTextWords) 122 keyword = " ".join([lineTextWords[6]]) 123 value = re.findall(r'\d+', line[tookIndex:])[-1] 124 value = float(value) 125 126 elif line.find("took") != -1: 127 stage = 2 128 tookIndex = line.find(" took") 129 uptoEnd= line[:tookIndex] 130 uptoBracket = uptoEnd.rfind("(") 131 if uptoBracket != -1: 132 uptoEnd = uptoEnd[:uptoBracket] 133 #uptoEnd = uptoEnd.replace(":", "") 134 lineTextWords = shlex.split(uptoEnd) 135 colonIndex, moduleName = self.findModuleName(lineTextWords) 136 # if there is colon only take words after it 137 if colonIndex!=-1: 138 lineTextWords = lineTextWords[colonIndex+1:] 139 numWords = len(lineTextWords) 140 keyword = "" 141 stage = 3 142 try: 143 for i in range(max(numWords-3, 0), numWords, 1): 144 keyword = keyword + " " + lineTextWords[i] 145 except Exception as e: 146 errLine = "LCItem:parseLineWithTook() ERROR Failed to parse1: " + str(e) 147 print(errLine) 148 assert False, errLine 149 150 # reduce length 151 keyword = keyword[:maxLineLength] 152 keyword = keyword.strip() 153 # using regex expression to replace all numbers 154 keyword = re.sub(r'\d', "_", keyword) 155 value = 0 156 stage = 4 157 try: 158 multplier = 1 159 tookSubstring = line[tookIndex:] 160 secondsIndex = tookSubstring.find("seconds") 161 msIndex = tookSubstring.find("ms") 162 if (secondsIndex!=-1): 163 tookSubstring = tookSubstring[:secondsIndex] 164 multiplier = 1000 165 elif msIndex != -1: 166 tookSubstring = tookSubstring[:msIndex] 167 else: 168 # known exception 169 if tookSubstring.find("properties")==-1: 170 errLine = "LCItem:parseLineWithTook() ERROR invalid took in substring 1B {}".format(line) 171 print(errLine) 172 assert False, errLine 173 return False 174 175 values = re.findall(r'[\d\.\d]+', tookSubstring) 176 while "." in values: 177 values.remove(".") 178 value = float(values[-1]) 179 if line.find("seconds") != -1: 180 value = value * multiplier 181 except Exception as e: 182 errLine = "LCItem:parseLineWithTook() ERROR Failed to parse2: " + str(e) 183 print(errLine) 184 assert False, errLine 185 stage = 5 186 187 else: 188 return False 189 190 stage = 6 191 self.set(dataTimeO, moduleName, keyword, value) 192 stage = 7 193 self.lines.append(line) 194 195 return True 196 197 except Exception as e: 198 errLine = "LCItem:parseLineWithTook() ERROR Failed to parse3:" + str(e) 199 print(errLine, stage) 200 assert False, errLine 201 202 def parseLine(self, line): 203 try: 204 words = line.split(" ") 205 dateTimeO = self.lCTimeProcessor.parseTimeStamp(line) 206 if (dateTimeO!=None): 207 #lcItem = LCItem(self.lCTimeProcessor) 208 newLine = line[19:].rstrip() 209 self.set(dateTimeO, "", newLine, 0) 210 #self.print() 211 return 212 else: 213 return None 214 215 except Exception as e: 216 errLine = "LCItem:parseLine() ERROR Failed to parse3:" + str(e) 217 print(errLine) 218 assert False, errLine 219 220 def find(self, keyword): 221 if self.key.find(keyword)!=-1: 222 return True 223 for line in self.lines: 224 if line.find(keyword)!=-1: 225 return True 226 227 def createLogLine(self): 228 line = "" 229 msecs = self.dateTime.strftime("%f") 230 timeString = self.dateTime.strftime("%m-%d %H:%M:%S.") 231 #timeString = timeString + msecs[] 232 return line 233 234class LCItemSet: 235 def __init__(self, item1, item2): 236 self.item1 = item1 237 self.item2 = item2 238 if (item1.key != "" and item2.key != ""): 239 assert(item1.key == item2.key) 240 if (item1.key!=""): 241 self.key = item1.key 242 else: 243 self.key = item2.key 244 self.diff = item2.valueMsec - item1.valueMsec 245 246 def __gt__(self, other): 247 if(self.diff>other.diff): 248 return True 249 else: 250 return False 251 252 def add(item): 253 assert(False) 254 255 def print(self, min, printAll): 256 self.diff = self.item2.valueMsec - self.item1.valueMsec 257 if abs(self.diff)<min: 258 return 259 flag = "12" 260 if self.item1.key=="": 261 flag = "-2" 262 263 if self.item2.key=="": 264 flag = "1-" 265 266 print("{}, {}, {}, {}, {}".format(self.key, self.item1.valueMsec, self.item2.valueMsec, self.diff, flag)) 267 if printAll: 268 self.item1.printLines("1> ", 1) 269 self.item2.printLines("2> ", 1) 270 271class LCItemMap: 272 def __init__(self): 273 self.map = {} 274 275 def put(self, newItem): 276 item = self.map.get(newItem.key) 277 if item==None: 278 self.map[newItem.key] = newItem 279 else: 280 item.add(newItem) 281 282 def print(self): 283 for key in self.map: 284 self.map[key].print() 285 286 def find(self, keyword): 287 lCItems = [] 288 for index, lCItem in self.map: 289 if lCItem.find(keyword): 290 lCItems.append(lCItem) 291 return lCItems 292 293 def addValues(self, other): 294 for index, item in other.map.items(): 295 if item.key in self.map: 296 self.map[item.key].addValue(item) 297 else: 298 self.map[item.key] = item 299 300 def divideValue(self, number): 301 for index, item in self.map: 302 item.divideValue(number) 303 304class LCItemSetMap: 305 def __init__(self): 306 self.map = {} 307 308 def put(self, itemSet): 309 item = self.map.get(itemSet.key) 310 if item==None: 311 self.map[itemSet.key] = itemSet 312 else: 313 item.add(itemSet) 314 315 def printSorted(self, printAll): 316 a = sorted(self.map.items(), key=lambda x: (x[1], x[0]), reverse=True) 317 cumDif = 0 318 print("Key, Value1, Value2, diff") 319 for item in a: 320 item[1].print(1, printAll) 321 cumDif = cumDif + item[1].diff 322 print("CUMULATIVE DIFF: {}".format(cumDif)) 323 324class LCTimeProcessor: 325 def __init__(self): 326 self.firstKernelTimeStamp = 0 327 self.lastKernelTimeStamp = 0 328 self.firstSystemTimesStamp = 0 329 self.lastTimeStamp = 0 330 self.zeroRelativeTime = 0 331 today = datetime.datetime.now() 332 year = str(today.year) 333 self.currentYear = year[-2:] # 2022/2023 334 335 def parseTimeStamp(self, line): 336 try: 337 if len(line)<19: 338 return None 339 currentYear = self.currentYear # 22 340 words = line.split(" ") 341 timeString = words[0] 342 #timeString = re.sub("[^0-9: -.]", "", timeString) 343 timeString = timeString.strip() 344 timeString = timeString[:18] 345 timeString = currentYear + "-" + timeString 346 dataTimeO = datetime.datetime.strptime(timeString, "%Y-%m-%d %H:%M:%S.%f") 347 return dataTimeO 348 except Exception as e: 349 # If no time stamp on this line 350 if line.find("beginning of")!=-1: 351 return None 352 errLine = "LCItem:parseTimeStamp() ERROR Failed to parse:" + str(e) 353 print(errLine) 354 assert False, errLine 355 return None 356 357 358 def process(self, line): 359 timeStamp = self.parseTimeStamp(line) 360 if timeStamp==None: 361 return False 362 363 if self.firstKernelTimeStamp==0: 364 self.firstKernelTimeStamp = timeStamp 365 else: 366 if timeStamp < self.firstKernelTimeStamp: 367 return False 368 369 timeChange = timeStamp - self.lastTimeStamp 370 if (timeChange.total_seconds() > 68*5): 371 if self.firstSystemTimesStamp ==0: 372 self.firstSystemTimesStamp = timeStamp 373 self.lastKernelTimeStamp = self.lastTimeStamp 374 self.zeroRelativeTime = self.toSystemTime(self.firstKernelTimeStamp) 375 376 self.lastTimeStamp = timeStamp 377 return True 378 379 def toSystemTime(self, timeStamp): 380 try: 381 # if no systemTime is found, it must all be system time 382 if self.firstSystemTimesStamp==0: 383 self.firstSystemTimesStamp = self.firstKernelTimeStamp 384 self.lastKernelTimeStamp = self.lastTimeStamp 385 self.zeroRelativeTime = self.firstKernelTimeStamp 386 return timeStamp 387 if timeStamp >= self.firstSystemTimesStamp: 388 return timeStamp 389 else: 390 timeChange = timeStamp - self.lastKernelTimeStamp 391 systemTime = self.firstSystemTimesStamp + timeChange 392 return systemTime 393 except Exception as e: 394 errLine = "LogLine:parseLine() ERROR Failed to parse3:" + str(e) 395 print(errLine) 396 assert False, errLine 397 398 def toRelativeTime(self, timeStamp): 399 systemTime = self.toSystemTime(timeStamp) 400 relativeTime = systemTime - self.zeroRelativeTime 401 return relativeTime 402 403 if timeStamp< self.firstSystemTimesStamp: 404 timeChange = timeStamp - self.lastKernelTimeStamp 405 systemTime = self.firstSystemTimesStamp + timeChange 406 return systemTime 407 else: 408 return timeStamp 409 410 def toString(self, timeStamp): 411 return timeStamp.strftime("%Y-%m-%d %H:%M:%S.%f") 412 413class LCLogLine: 414 def __init__(self, lCTimeProcessor): 415 self.dateTime = 0 416 self.relativeTime = 0 417 self.lineText = "" 418 self.lCTimeProcessor = lCTimeProcessor 419 420 def set(self, dateTime, lineText): 421 self.dateTime = dateTime 422 self.relativeTime = self.lCTimeProcessor.toRelativeTime(self.dateTime) 423 self.lineText = lineText 424 425 def print(self): 426 newTimeString = str(self.relativeTime) 427 print("{}{}".format(newTimeString, self.lineText)) 428 429 def parseLine(self, line): 430 try: 431 dateTimeO = self.lCTimeProcessor.parseTimeStamp(line) 432 if (dateTimeO!=None): 433 lineText = line[19:].rstrip() 434 self.set(dateTimeO, lineText) 435 return 436 else: 437 return None 438 439 except Exception as e: 440 errLine = "LogLine:parseLine() ERROR Failed to parse3:" + str(e) 441 print(errLine) 442 assert False, errLine 443 444 def find(self, word): 445 if (self.lineText.find(word)!=-1): 446 return True 447 else: 448 return False 449 450 def findAll(self, words): 451 for word in words: 452 if (self.lineText.find(word)==-1): 453 return False 454 return True 455 456class LCLogFile(TextFile): 457 priorTimeStamp = 0.0 458 def __init__(self, _fileName = ""): 459 super(LCLogFile, self).__init__(_fileName) 460 self.linesWithTook = [] 461 self.linesWithTookToComplete = [] 462 self.linesWithoutTookToComplete = [] 463 self.firstKernelTimeStamp = 0 464 self.lastKernelTimeStamp = 0 465 self.firstSystemTimesStamp = 0 466 self.lastTimeStamp = 0 467 self.lCTimeProcessor = LCTimeProcessor() 468 self.dumpLinesBeforeBeginning() 469 470 def dumpLinesBeforeBeginning(self): 471 # start from --------- beginning of kernel 472 beginningFound = False 473 _lines = [] 474 for line in self.lines: 475 if beginningFound==True: 476 _lines.append(line) 477 self.lCTimeProcessor.process(line) 478 479 elif line.find("beginning of kernel") != -1: 480 beginningFound = True 481 482 self.lines = _lines 483 484 485 def scanTook(self): 486 lCItemMap = LCItemMap() 487 foundBeginning = False 488 for line in self.lines: 489 # start at beginning 490 if not foundBeginning: 491 if line.find("beginning of kernel=1") != -1: 492 foundBeginning = True 493 continue 494 495 # stop if boot complete 496 if line.find("sys.boot_completed=1") != -1: 497 break 498 499 if line.find("took") != -1: 500 self.linesWithTook.append(line.rstrip()) 501 502 for line in self.linesWithTook: 503 lCItem = LCItem(self.lCTimeProcessor) 504 if lCItem.parseLineWithTook(line)==True: 505 lCItemMap.put(lCItem) 506 507 return lCItemMap 508 509 def print(self, numItems=None): 510 self.scanTook() 511 512 def convert(self, numItems=None): 513 lcLogLines = [] 514 for line in self.lines: 515 lcLogLine = LCLogLine(self.lCTimeProcessor) 516 lcLogLine.parseLine(line) 517 lcLogLines.append(lcLogLine) 518 return lcLogLines 519''' 520 def createLCFile(self, fileName): 521 # create LCTimeProcessor 522 # create LCItem 523 # create LCLogLine 524 # write LCLogLine to file 525''' 526class ScanFile: 527 def __init__(self): 528 self.fileName = "none" 529 530 def scanKeyWords(self, fileName): 531 print("Scanning {}".format(fileName)) 532 cmd = "grep \"apexd: wait for '\/dev\/loop-control'\" {}".format(fileName) 533 x = os.system(cmd) 534 cmd = "grep \"Service 'apexd-bootstrap\" {}".format(fileName) 535 x = os.system(cmd) 536 cmd = "grep apexd.status=activated {}".format(fileName) 537 x = os.system(cmd) 538 cmd = "grep \"Service 'bpfloader'\" {}".format(fileName) 539 x = os.system(cmd) 540 cmd = "grep \"sys.boot_completed=1\" {} | head -n 1".format(fileName) 541 x = os.system(cmd) 542 543 def scanTook(self, fileName): 544 lCLogFile = LCLogFile(fileName) 545 lCItemMap = lCLogFile.scanTook() 546 547 def convert(self, fileName): 548 lCLogFile = LCLogFile(fileName) 549 lcItems = lCLogFile.convert() 550 for lcItem in lcItems: 551 lcItem.print() 552 553 def phases(self, fileName): 554 keywordFile = TextFile("keywords") 555 #keywords = ['init first', 'init second', "Starting phase 200", "boot_completed"] 556 557 lCLogFile = LCLogFile(fileName) 558 keywordSets = [] 559 for line in keywordFile.lines: 560 line = line.strip() 561 keywordSet = line.split(", ") 562 keywordSets.append(keywordSet) 563 564 lcLogLines = lCLogFile.convert() 565 for keywordSet in keywordSets: 566 for lcLogLine in lcLogLines: 567 if lcLogLine.findAll(keywordSet)==True: 568 lcLogLine.print() 569 break 570 571class Compare: 572 def __init__(self): 573 self.fileName = "none" 574 575 def compareLCItemMaps(self, lCItemMap1, lCItemMap2): 576 lCItemSetMap = LCItemSetMap() 577 578 for item1key in lCItemMap1.map: 579 found = False 580 for item2key in lCItemMap2.map: 581 if item2key==item1key: 582 lcItemSet = LCItemSet(lCItemMap1.map[item1key], lCItemMap2.map[item2key]) 583 lCItemSetMap.put(lcItemSet) 584 found = True 585 break 586 # if item1Key is not in ItemMap2, add a null item 587 if found==False: 588 lCTimeProcessor = LCTimeProcessor() 589 nullLCItem = LCItem(lCTimeProcessor) 590 lcItemSet = LCItemSet(nullLCItem, lCItemMap1.map[item1key]) 591 lCItemSetMap.put(lcItemSet) 592 found = True 593 594 lCItemSetMap.printSorted(printAll) 595 return lCItemSetMap 596 597 def compareFiles(self, fileName1, fileName2, printAll): 598 print("---------------------------------------------------------------") 599 print("lcan.py -cmp {} {}".format(fileName1, fileName2)) 600 print("---------------------------------------------------------------") 601 lCLogFile1 = LCLogFile(fileName1) 602 lCItemMap1 = lCLogFile1.scanTook() 603 lCLogFile2 = LCLogFile(fileName2) 604 lCItemMap2 = lCLogFile2.scanTook() 605 606 lCItemSetMap = LCItemSetMap() 607 608 for item1key in lCItemMap1.map: 609 found = False 610 for item2key in lCItemMap2.map: 611 if item2key==item1key: 612 lcItemSet = LCItemSet(lCItemMap1.map[item1key], lCItemMap2.map[item2key]) 613 lCItemSetMap.put(lcItemSet) 614 found = True 615 break 616 # if item1Key is not in ItemMap2, add a null item 617 if found==False: 618 lCTimeProcessor = LCTimeProcessor() 619 nullLCItem = LCItem(lCTimeProcessor) 620 lcItemSet = LCItemSet(nullLCItem, lCItemMap1.map[item1key]) 621 lCItemSetMap.put(lcItemSet) 622 found = True 623 624 lCItemSetMap.printSorted(printAll) 625 return lCItemSetMap 626 627 def getAverageOfDir(self, buildId): 628 #get average values for build1 629 dirList = glob.glob("{}/LC-{}*.txt".format(buildId, buildId)) 630 numFiles = len(dirList) 631 #iterate in numerical order 632 lCItemMapS = LCItemMap() 633 for index in range(numFiles): 634 fileName = "{}/LC-{}-{}.txt".format(buildId, buildId, index) 635 #for index, fileName in enumerate(dirList): 636 lCLogFile = LCLogFile(fileName) 637 lCItemMap = lCLogFile.scanTook() 638 lCItemMapS.addValues(lCItemMap) 639 lCItemMapS.divideValue(numFiles) 640 return lCItemMapS 641 642 def compareDirs(self, buildId1, buildId2, printAll): 643 print("---------------------------------------------------------------") 644 print("lcan.py -cmpd {} {} {}".format(buildId1, buildId2, printAll)) 645 print("---------------------------------------------------------------") 646 647 #get average values for build1 648 lCItemMap1 = self.getAverageOfDir(buildId1) 649 lCItemMap2 = self.getAverageOfDir(buildId2) 650 self.compareLCItemMaps(self, lCItemMap1, lCItemMap2) 651 652 653parser = argparse.ArgumentParser() 654parser.add_argument("-c", nargs=1, metavar=('<fileName>'), help="convert Logcat output to start from boot with converted timeStamps") 655parser.add_argument("-k", nargs=1, metavar=('<fileName>'), help="summary on keywords") 656parser.add_argument("-a", nargs=1, metavar=('<fileName>'), help="analyze file") 657parser.add_argument("-cmp", nargs=3, metavar=('<fileName1>', '<fileName2>', '<brief/all>'), help="compare logcat files") 658parser.add_argument("-cmpd", nargs=3, metavar=('<dirName1>', '<dirName2>', '<brief/all>'), help="compare logcat files") 659parser.add_argument("-p", nargs=1, metavar=('<fileName1>'), help="phase report on log files") 660args = parser.parse_args() 661 662if args.k!=None: 663 scanFile = ScanFile() 664 scanFile.scanKeyWords(args.k[0]) 665 666if args.a!=None: 667 scanFile = ScanFile() 668 scanFile.scanTook(args.a[0]) 669 670if args.c!=None: 671 scanFile = ScanFile() 672 scanFile.convert(args.c[0]) 673 674if args.p!=None: 675 scanFile = ScanFile() 676 scanFile.phases(args.p[0]) 677 678if args.cmp!=None: 679 printAll = False 680 compare = Compare() 681 if (len(args.cmp)>2): 682 if (args.cmp[2].find("all")!=-1): 683 printAll = True 684 compare.compareFiles(args.cmp[0], args.cmp[1], printAll) 685 686if args.cmpd!=None: 687 printAll = False 688 compare = Compare() 689 if (len(args.cmpd)>2): 690 if (args.cmpd[2].find("all")!=-1): 691 printAll = True 692 compare.compareDirs(args.cmpd[0], args.cmpd[1], printAll) 693