Extract timing information in two logs and report the differences and regression.

Test: manually.
Change-Id: I25f3bbb00ba5258e935ebea42fc231168532a2b8

Change-Id: I36adea1a5078000afa81f4875b9fd84e295139e3

1 files changed, 197 insertions, 0 deletions

diff --git a/perf_tools/parse_timing.py b/perf_tools/parse_timing.py
new file mode 100644
index 00000000..1ba23142
--- /dev/null
+++ b/perf_tools/parse_timing.py
@@ -0,0 +1,197 @@
+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()