1#!/usr/bin/python
2
3import copy
4import datetime
5import logging
6import os
7import pprint
8import sys
9import time
10
11THIS_YEAR = datetime.datetime.now().year
12
13
14def 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
45def 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[7]
76            if len(tokens) == 9 and tokens[8] in ["PASS", "FAIL", "SKIP", "ERROR"]:
77                return True, test_module_name, test_case_name, "end", timestamp
78            elif len(tokens) == 8:
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.
86java_exec_stats = {}
87# Python runner's execution stats.
88python_exec_stats = {}
89flag_show_samples = False
90
91
92def 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
117def 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
128def 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
208def 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
215if __name__ == "__main__":
216    if len(sys.argv) != 2:
217        usage()
218    main(sys.argv[1])
219