1 #!/usr/bin/python 2 3 import copy 4 import datetime 5 import logging 6 import os 7 import pprint 8 import sys 9 import time 10 11 THIS_YEAR = datetime.datetime.now().year 12 13 14 def AnalyzeJavaLog(line): 15 """Analyzes a log line printed by VTS Java harness. 16 17 Args: 18 line: string for a log line. 19 20 Returns: 21 boolean (True if it's a Java log line, False otherwise) 22 string (module type) 23 string (phase name) 24 float (timestamp) 25 """ 26 tokens = line.split() 27 timestamp = 0 28 if len(tokens) < 4: 29 return False, None, None, 0 30 # Example 31 # 05-12 07:51:45 I/VtsMultiDeviceTest: 32 date_time_str = "%s-%s %s" % (THIS_YEAR, tokens[0], tokens[1]) 33 try: 34 timestamp = time.mktime(datetime.datetime.strptime( 35 date_time_str, "%Y-%m-%d %H:%M:%S").timetuple()) 36 except ValueError as e: 37 timestamp = -1 38 39 if (len(tokens[2]) > 2 and tokens[2] == "D/ModuleDef:" and 40 tokens[3][-1] == ":"): 41 return True, tokens[3][:-1], tokens[4], timestamp 42 return False, None, None, timestamp 43 44 45 def AnalyzePythonLog(line): 46 """Analyzes a log line printed by VTS Python runner. 47 48 Args: 49 line: string for a log line. 50 51 Returns: 52 boolean (True if it's a Python log line, False otherwise) 53 string (test module name) 54 string (test case name) 55 string ('begin' or 'end') 56 float (timestamp) 57 """ 58 tokens = line.split() 59 timestamp = 0 60 test_module_name = None 61 if len(tokens) < 7: 62 return False, test_module_name, None, None, timestamp 63 # Example 64 # [VtsKernelSelinuxFileApi] 05-12 07:51:32.916 INFO ... 65 if len(tokens[0]) > 2 and tokens[0][0] == "[" and tokens[0][-1] == "]": 66 test_module_name = tokens[0][1:-1] 67 68 date_time_str = "%s-%s %s" % (THIS_YEAR, tokens[1], tokens[2]) 69 try: 70 timestamp = time.mktime(datetime.datetime.strptime( 71 date_time_str, "%Y-%m-%d %H:%M:%S.%f").timetuple()) 72 except ValueError as e: 73 timestamp = -1 74 if tokens[4] == "[Test" and tokens[5] == "Case]": 75 test_case_name = tokens[6] 76 if len(tokens) == 8 and tokens[7] in ["PASS", "FAIL", "SKIP", "ERROR"]: 77 return True, test_module_name, test_case_name, "end", timestamp 78 elif len(tokens) == 7: 79 return True, test_module_name, test_case_name, "begin", timestamp 80 else: 81 assert False, "Error at '%s'" % line 82 return True, test_module_name, None, None, timestamp 83 return False, test_module_name, None, None, timestamp 84 85 # Java harness's execution stats. 86 java_exec_stats = {} 87 # Python runner's execution stats. 88 python_exec_stats = {} 89 flag_show_samples = False 90 91 92 def ProcessEvent(module_type, module_name, timestamp): 93 """Processes a given Java log event.""" 94 if module_type in java_exec_stats: 95 java_exec_stats[module_type]["sum"] += timestamp 96 java_exec_stats[module_type]["count"] += 1 97 if module_name in java_exec_stats[module_type]: 98 java_exec_stats[module_type][module_name]["sum"] += timestamp 99 java_exec_stats[module_type][module_name]["count"] += 1 100 if flag_show_samples: 101 java_exec_stats[module_type][module_name]["samples"].append( 102 timestamp) 103 else: 104 java_exec_stats[module_type][module_name] = {} 105 java_exec_stats[module_type][module_name]["sum"] = timestamp 106 java_exec_stats[module_type][module_name]["count"] = 1 107 if flag_show_samples: 108 java_exec_stats[module_type][module_name]["samples"] = [ 109 timestamp 110 ] 111 else: 112 java_exec_stats[module_type] = {} 113 java_exec_stats[module_type]["sum"] = timestamp 114 java_exec_stats[module_type]["count"] = 1 115 116 117 def FilterDict(input_dict, threashold): 118 """Filters items in input_dict whose values are greater than threshold.""" 119 result_dict = {} 120 org_dict = copy.copy(input_dict) 121 for key, value in input_dict.iteritems(): 122 if value["value"] > threashold and value["state"] == "end": 123 result_dict[key] = value["value"] 124 del org_dict[key] 125 return org_dict, result_dict 126 127 128 def main(log_file_path): 129 """Analyzes the phases of an execution caught in the log. 130 131 Args: 132 log_file_path: string, log file path. 133 """ 134 print "Log File:", log_file_path 135 136 prev_java_module_type = None 137 prev_java_module_name = None 138 prev_timestamp = 0 139 last_timestamp = 0 140 python_exec_stats = {} 141 142 with open(log_file_path, "r") as log_file: 143 for line in log_file: 144 (is_java_log, java_module_type, java_module_name, 145 timestamp) = AnalyzeJavaLog(line) 146 if is_java_log: 147 last_timestamp = timestamp 148 if prev_java_module_type: 149 ProcessEvent(prev_java_module_type, prev_java_module_name, 150 timestamp - prev_timestamp) 151 prev_java_module_type = java_module_type 152 prev_java_module_name = java_module_name 153 prev_timestamp = timestamp 154 else: 155 (is_python_log, test_module_name, test_case_name, event_type, 156 timestamp) = AnalyzePythonLog(line) 157 if is_python_log: 158 last_timestamp = timestamp 159 if test_case_name: 160 if event_type == "begin": 161 if test_case_name not in python_exec_stats: 162 python_exec_stats[test_case_name] = {} 163 python_exec_stats[test_case_name][ 164 "value"] = timestamp 165 python_exec_stats[test_case_name][ 166 "state"] = "begin" 167 else: 168 for count in range(1, 1000): 169 new_test_case_name = "%s_%s" % ( 170 test_case_name, str(count)) 171 if new_test_case_name not in python_exec_stats: 172 python_exec_stats[ 173 new_test_case_name] = {} 174 python_exec_stats[new_test_case_name][ 175 "value"] = timestamp 176 python_exec_stats[new_test_case_name][ 177 "state"] = "begin" 178 break 179 python_exec_stats[test_case_name] = {} 180 python_exec_stats[test_case_name][ 181 "value"] = timestamp 182 python_exec_stats[test_case_name][ 183 "state"] = "begin" 184 elif event_type == "end": 185 assert python_exec_stats[test_case_name][ 186 "state"] == "begin" 187 python_exec_stats[test_case_name]["state"] = "end" 188 python_exec_stats[test_case_name]["value"] = ( 189 timestamp - 190 python_exec_stats[test_case_name]["value"]) 191 assert python_exec_stats[test_case_name] >= 0, ( 192 "%s >= 0 ?" % 193 python_exec_stats[test_case_name]) 194 195 if prev_java_module_type: 196 ProcessEvent(prev_java_module_type, prev_java_module_name, 197 last_timestamp - prev_timestamp) 198 199 for threshold in [600, 300, 180, 120, 60, 30]: 200 python_exec_stats, filtered_dict = FilterDict(python_exec_stats, 201 threshold) 202 print "Python test cases took >%s seconds:" % threshold 203 print filtered_dict.keys() 204 print "Total Execution Time Breakdown:" 205 pprint.pprint(java_exec_stats, width=1) 206 207 208 def usage(): 209 """Prints usage and exits.""" 210 print "Script to analyze the total execution of a VTS run." 211 print "Usage: <this script> <VTS host log file path>" 212 exit(-1) 213 214 215 if __name__ == "__main__": 216 if len(sys.argv) != 2: 217 usage() 218 main(sys.argv[1]) 219
