perf_tools/parse_timing.py

import sys
import os
from datetime import datetime

# Usage:
# python3 parse_timing.py logcat.txt "08-23 23:10:32.555" 10 200
#
# Description: extract events and timing in the log that start from timestamp "08-23 23:10:32.555"
# till 10 seconds
#
# Usage:
# python3 parse_timing.py logcat1.txt logcat2.txt 10 ts1 ts1 200
#
# Description: report the timing that the differences are bigger than 200
#
# Example:
# python3 log_processing/parse_timing.py 8976224/logcat.txt 8879724/logcat.txt
# "08-23 23:10:32.555" "07-29 06:39:06.254" 200
def main():
   if len(sys.argv) == 5:
      process_one_log()
   elif len(sys.argv) == 6:
      compair_two_log()
   else:
      print("wrong number of arguments")

def compair_two_log():
   filepath1 = sys.argv[1]
   print(filepath1)
   if not os.path.isfile(filepath1):
       print("File path {} does not exist. Exiting...".format(filepath1))
       sys.exit()

   filepath2 = sys.argv[2]
   print(filepath2)
   if not os.path.isfile(filepath2):
       print("File path {} does not exist. Exiting...".format(filepath2))
       sys.exit()

   ts1 = datetime.strptime(sys.argv[3], '%m-%d %H:%M:%S.%f')
   ts2 = datetime.strptime(sys.argv[4], '%m-%d %H:%M:%S.%f')
   duration = float(sys.argv[5])*1000

   # 1: took to complete 1000ms
   # 2: took 33ms
   # 3: took 33 ms or took 0.3 seconds
   file1_events = [{}, {}, {}]
   file2_events = [{}, {}, {}]

   extract_events(filepath1, file1_events, ts1, duration)
   extract_events(filepath2, file2_events, ts2, duration)


   sum_events_timing(file1_events)
   sum_events_timing(file2_events)

   sum_all_events_timing_diff(file1_events, file2_events)

   sys.exit()


def process_one_log():
   filepath = sys.argv[1]
   print(filepath)
   if not os.path.isfile(filepath):
       print("File path {} does not exist. Exiting...".format(filepath))
       sys.exit()

   # 1: took to complete 1000ms
   # 2: took 33ms
   # 3: took 33 ms or took 0.3 seconds
   events = [{}, {}, {}]
   ts = datetime.strptime(sys.argv[2], '%m-%d %H:%M:%S.%f')
   duration = float(sys.argv[3])*1000
   extract_events(filepath, events, ts, duration)

   timing = float(sys.argv[3])
   print_sorted_all_events(events, timing)

   sys.exit()

def print_sorted_all_events(file_events, timing):
   for i in range(len(file_events)):
      print_sorted_events(file_events[i], timing)

def print_sorted_events(events, timing):
   for word in sorted(events, key=events.get, reverse=True):
      if (events[word]) > timing:
         print("event:{} \ttiming:{} ".format(word, events[word]))

def sum_events_timing(events):
   total_sum = 0;
   for i in range(len(events)):
      sum = 0
      print("start summary for type {}".format(i))
      for event in events[i]:
         sum += events[i][event]
         #print("event {} timing {} ".format(event, events[i][event]))
      print("sum events type {} {} : timing {}".format(i, len(events), sum))
      total_sum += sum
   print("sum all type events timing {}\n".format(total_sum))

def sum_events_timing_diff(type, file1_events, file2_events):
   sum_diff = 0
   max_diff = 0
   regression_events = {}
   print("start summary for type {}".format(type))
   for event in file1_events:
      val = file2_events.get(event)
      if val != None:
         diff = file1_events[event] - val
         if diff > 100 and val > 100:
            # print("regression event {} \t{}: {} \t{}: {} \tdiff: {}"
            #      .format(event, "case1", file1_events[event], "case2", val, diff))
            regression_events[event] = diff
            sum_diff += diff
            max_diff = max(max_diff, diff)
   print("\nsummary for timing type {} sum_diff {} max_diff {}".format(type, sum_diff, max_diff))
   print_events(regression_events, file1_events, file2_events)

def sum_all_events_timing_diff(file1_events, file2_events):
   for i in range(len(file1_events)):
      sum_events_timing_diff(i, file1_events[i], file2_events[i])

def print_events(events, file1_events, file2_events):
   for word in sorted(events, key=events.get, reverse=True):
      if (events[word]) > 10:
          print("{} \tdiff {} \t{} \t{}".format(word, events[word],file1_events[word], file2_events[word]))

def find_took(words):
   for i in range(len(words)):
      if words[i] == 'took' or words[i] == "took:":
         return i

def extract_time(line, events):
   if not "took" in line:
      return

   # 1: took to complete 1000ms
   # 2: took 33ms
   # 3: took 33 ms or took 0.3 seconds
   words = line.strip().split(' ')
   i = find_took(words)
   index = 0;
   str1 = " "
   key = str1.join(words[8:i])

   if words[i+1] == 'to' and words[i+2] == 'complete:':
      index = 0;
      val = float(words[i+3][:-2]);
   elif words[i+1][-2:] == 'ms':
      index = 1
      val = float(words[i+1][:-2]);
   elif len(words) > i+2:
      index = 2
      if words[i+2] == 'seconds':
         val = float(words[i+1])*1000;
      elif words[i+2] == 'ms':
         val = float(words[i+1])
      else:
         return True

   # print("index: {}  key: {} val: {}".format(index, key, val));

   if events[index].get(key) == None:
      events[index][key] = val
      return True
   else:
      # print("duplicate key: " + key + " line: " + line)
      return True

def check_time_range(line, ts, duration):
   index = line.find(" ", 6)
   if index <= 0:
      return False

   try:
      current_time = datetime.strptime(line[:index], '%m-%d %H:%M:%S.%f')
   except ValueError:
      return False

   deltatime = current_time - ts
   if deltatime.total_seconds()*1000 < 0 or deltatime.total_seconds() > duration:
      return False
   return True

def extract_events(filepath, events, ts, duration):
   with open(filepath, errors='ignore') as fp:
      for line in fp:
         if check_time_range(line, ts, duration) == False:
            continue
         if extract_time(line, events) == False:
            return


if __name__ == '__main__':
    main()