#!/usr/bin/python
import copy
import datetime
import logging
import os
import pprint
import sys
import time
THIS_YEAR = datetime.datetime.now().year
def AnalyzeJavaLog(line):
"""Analyzes a log line printed by VTS Java harness.
Args:
line: string for a log line.
Returns:
boolean (True if it's a Java log line, False otherwise)
string (module type)
string (phase name)
float (timestamp)
"""
tokens = line.split()
timestamp = 0
if len(tokens) < 4:
return False, None, None, 0
# Example
# 05-12 07:51:45 I/VtsMultiDeviceTest:
date_time_str = "%s-%s %s" % (THIS_YEAR, tokens[0], tokens[1])
try:
timestamp = time.mktime(datetime.datetime.strptime(
date_time_str, "%Y-%m-%d %H:%M:%S").timetuple())
except ValueError as e:
timestamp = -1
if (len(tokens[2]) > 2 and tokens[2] == "D/ModuleDef:" and
tokens[3][-1] == ":"):
return True, tokens[3][:-1], tokens[4], timestamp
return False, None, None, timestamp
def AnalyzePythonLog(line):
"""Analyzes a log line printed by VTS Python runner.
Args:
line: string for a log line.
Returns:
boolean (True if it's a Python log line, False otherwise)
string (test module name)
string (test case name)
string ('begin' or 'end')
float (timestamp)
"""
tokens = line.split()
timestamp = 0
test_module_name = None
if len(tokens) < 7:
return False, test_module_name, None, None, timestamp
# Example
# [VtsKernelSelinuxFileApi] 05-12 07:51:32.916 INFO ...
if len(tokens[0]) > 2 and tokens[0][0] == "[" and tokens[0][-1] == "]":
test_module_name = tokens[0][1:-1]
date_time_str = "%s-%s %s" % (THIS_YEAR, tokens[1], tokens[2])
try:
timestamp = time.mktime(datetime.datetime.strptime(
date_time_str, "%Y-%m-%d %H:%M:%S.%f").timetuple())
except ValueError as e:
timestamp = -1
if tokens[4] == "[Test" and tokens[5] == "Case]":
test_case_name = tokens[7]
if len(tokens) == 9 and tokens[8] in ["PASS", "FAIL", "SKIP", "ERROR"]:
return True, test_module_name, test_case_name, "end", timestamp
elif len(tokens) == 8:
return True, test_module_name, test_case_name, "begin", timestamp
else:
assert False, "Error at '%s'" % line
return True, test_module_name, None, None, timestamp
return False, test_module_name, None, None, timestamp
# Java harness's execution stats.
java_exec_stats = {}
# Python runner's execution stats.
python_exec_stats = {}
flag_show_samples = False
def ProcessEvent(module_type, module_name, timestamp):
"""Processes a given Java log event."""
if module_type in java_exec_stats:
java_exec_stats[module_type]["sum"] += timestamp
java_exec_stats[module_type]["count"] += 1
if module_name in java_exec_stats[module_type]:
java_exec_stats[module_type][module_name]["sum"] += timestamp
java_exec_stats[module_type][module_name]["count"] += 1
if flag_show_samples:
java_exec_stats[module_type][module_name]["samples"].append(
timestamp)
else:
java_exec_stats[module_type][module_name] = {}
java_exec_stats[module_type][module_name]["sum"] = timestamp
java_exec_stats[module_type][module_name]["count"] = 1
if flag_show_samples:
java_exec_stats[module_type][module_name]["samples"] = [
timestamp
]
else:
java_exec_stats[module_type] = {}
java_exec_stats[module_type]["sum"] = timestamp
java_exec_stats[module_type]["count"] = 1
def FilterDict(input_dict, threashold):
"""Filters items in input_dict whose values are greater than threshold."""
result_dict = {}
org_dict = copy.copy(input_dict)
for key, value in input_dict.iteritems():
if value["value"] > threashold and value["state"] == "end":
result_dict[key] = value["value"]
del org_dict[key]
return org_dict, result_dict
def main(log_file_path):
"""Analyzes the phases of an execution caught in the log.
Args:
log_file_path: string, log file path.
"""
print "Log File:", log_file_path
prev_java_module_type = None
prev_java_module_name = None
prev_timestamp = 0
last_timestamp = 0
python_exec_stats = {}
with open(log_file_path, "r") as log_file:
for line in log_file:
(is_java_log, java_module_type, java_module_name,
timestamp) = AnalyzeJavaLog(line)
if is_java_log:
last_timestamp = timestamp
if prev_java_module_type:
ProcessEvent(prev_java_module_type, prev_java_module_name,
timestamp - prev_timestamp)
prev_java_module_type = java_module_type
prev_java_module_name = java_module_name
prev_timestamp = timestamp
else:
(is_python_log, test_module_name, test_case_name, event_type,
timestamp) = AnalyzePythonLog(line)
if is_python_log:
last_timestamp = timestamp
if test_case_name:
if event_type == "begin":
if test_case_name not in python_exec_stats:
python_exec_stats[test_case_name] = {}
python_exec_stats[test_case_name][
"value"] = timestamp
python_exec_stats[test_case_name][
"state"] = "begin"
else:
for count in range(1, 1000):
new_test_case_name = "%s_%s" % (
test_case_name, str(count))
if new_test_case_name not in python_exec_stats:
python_exec_stats[
new_test_case_name] = {}
python_exec_stats[new_test_case_name][
"value"] = timestamp
python_exec_stats[new_test_case_name][
"state"] = "begin"
break
python_exec_stats[test_case_name] = {}
python_exec_stats[test_case_name][
"value"] = timestamp
python_exec_stats[test_case_name][
"state"] = "begin"
elif event_type == "end":
assert python_exec_stats[test_case_name][
"state"] == "begin"
python_exec_stats[test_case_name]["state"] = "end"
python_exec_stats[test_case_name]["value"] = (
timestamp -
python_exec_stats[test_case_name]["value"])
assert python_exec_stats[test_case_name] >= 0, (
"%s >= 0 ?" %
python_exec_stats[test_case_name])
if prev_java_module_type:
ProcessEvent(prev_java_module_type, prev_java_module_name,
last_timestamp - prev_timestamp)
for threshold in [600, 300, 180, 120, 60, 30]:
python_exec_stats, filtered_dict = FilterDict(python_exec_stats,
threshold)
print "Python test cases took >%s seconds:" % threshold
print filtered_dict.keys()
print "Total Execution Time Breakdown:"
pprint.pprint(java_exec_stats, width=1)
def usage():
"""Prints usage and exits."""
print "Script to analyze the total execution of a VTS run."
print "Usage: <this script> <VTS host log file path>"
exit(-1)
if __name__ == "__main__":
if len(sys.argv) != 2:
usage()
main(sys.argv[1])