Merge pull request #539 from ahoppen/pr/analyze-code-completion-timings

[Stress Tester] Use new duration measurement capability of stress tester to analyse code completion durations

Author: shahmishal

analyze_request_durations.py

@@ -0,0 +1,140 @@
+#!/usr/bin/env python
+
+from __future__ import print_function
+
+import argparse
+import json
+import os
+
+# This value was emirically determined on an iMac Pro with a fairly small sample size.
+# All measurements in seconds should be taken with extreme care
+INSTRUCTIONS_PER_SECOND = 6693088549.09358
+
+# The length of the bars in the histograms
+HISTOGRAM_BAR_LENGTH = 40
+
+
+def parse_args():
+    parser = argparse.ArgumentParser()
+    parser.add_argument('request_durations_file')
+    return parser.parse_args()
+
+
+def print_stats(entries):
+    """
+    entries is a list of dictionaries from the JSON file under the
+    files.<file-name>.<request-name> path containing the following keys
+    - totalInstructions
+    - logHistogram
+    - requestsExecuted
+    """
+
+    # Create a log histogram for all entries
+    aggregated_completion_log_histogram = {}
+    # Adds totalInstruction for each entry
+    total_instructions = 0
+    # Adds requestsExecuted for each entry
+    total_requests_executed = 0
+    for entry in entries:
+        total_instructions += int(entry['totalInstructions'])
+        total_requests_executed += int(entry['requestsExecuted'])
+        for (bucket, count) in entry['logHistogram'].iteritems():
+            bucket = int(bucket)
+            count = int(count)
+            if bucket not in aggregated_completion_log_histogram:
+                aggregated_completion_log_histogram[bucket] = 0
+            aggregated_completion_log_histogram[bucket] += count
+
+    if total_requests_executed == 0:
+        print('No requests executed')
+        return
+
+    print('Requests: {}'.format(total_requests_executed))
+
+    average_instructions_per_request = total_instructions / total_requests_executed
+    seconds_estimate = average_instructions_per_request / INSTRUCTIONS_PER_SECOND
+    print('Average: {:.0e} instr (ca. {:.3f}s)'
+          .format(average_instructions_per_request, seconds_estimate))
+
+    print('\nHistogram:')
+
+    min_bucket = min(aggregated_completion_log_histogram)
+    max_bucket = max(aggregated_completion_log_histogram)
+    max_count = max([x[1] for x in aggregated_completion_log_histogram.iteritems()])
+
+    # Sums up the percentages for each entry to make it easier to spot the
+    # n-th percentile in the histogram
+    running_percentage_sum = 0
+    for bucket in range(min_bucket, max_bucket + 1):
+        count = aggregated_completion_log_histogram.get(bucket, 0)
+        executed_instructions = pow(2, bucket)
+        estimated_seconds = executed_instructions / INSTRUCTIONS_PER_SECOND
+        bar_fill = (count * HISTOGRAM_BAR_LENGTH / max_count)
+        bar = '*' * bar_fill + ' ' * (HISTOGRAM_BAR_LENGTH - bar_fill)
+        percentage = float(count) / total_requests_executed * 100
+        running_percentage_sum += percentage
+        print('< {:5.0e} instr (ca. {:6.3f}s): {} {:4.1f}% (< {:5.1f}%)'
+              .format(executed_instructions, estimated_seconds, bar, percentage,
+                      running_percentage_sum))
+
+
+def print_stats_for_all_files(request_durations, request_name):
+    print('\n---------- All {} requests ----------\n'.format(request_name))
+    all_request_entries = []
+    for (file_name, file_stats) in request_durations['files'].iteritems():
+        all_request_entries.append(file_stats[request_name])
+    print_stats(all_request_entries)
+
+
+def print_slowest_files(request_durations, request_name, num_files):
+    print('\n---------- {} slowest files for {} requests ----------\n'
+          .format(num_files, request_name))
+
+    file_and_average = []
+    for (file_name, file_stats) in request_durations['files'].iteritems():
+        instr_executed_in_file = int(file_stats[request_name]['totalInstructions'])
+        requests_in_file = int(file_stats[request_name]['requestsExecuted'])
+        if requests_in_file > 0:
+            average = instr_executed_in_file / requests_in_file
+            file_and_average.append((file_name, average))
+    file_and_average = sorted(file_and_average, key=lambda x: x[1], reverse=True)
+
+    for (file_name, average_request_duration) in file_and_average[0:num_files]:
+        print('-- {} --\n'.format(file_name))
+        print_stats([request_durations['files'][file_name][request_name]])
+        print('\n')
+
+
+def print_seconds_disclaimer():
+    print('''IMPORTANT:
+All measurements printed by this script were done in number of number of
+instructions. Measurements in seconds are computed assuming that all machines
+execute the same number of instructions per second at all times, which is not
+correct. Thus all measurements in seconds should be taken with extreme care.
+As they scale linearly with the number of instructions, it is safe to compare
+values in seconds output by this script.
+''')
+
+
+def analyze_request_durations(file):
+    if not os.path.exists(file):
+        print('{} does not exist. No request durations to analyze.'.format(file))
+        return
+    print_seconds_disclaimer()
+    print('\n---------- Raw durations for further analysis ----------\n')
+    with open(file, 'r') as json_file:
+        print(json_file.read())
+
+    with open(file, 'r') as json_file:
+        request_durations = json.load(json_file, encoding='utf-8')
+    print_stats_for_all_files(request_durations, 'CodeComplete')
+    print_slowest_files(request_durations, 'CodeComplete', 10)
+
+
+def main():
+    args = parse_args()
+    analyze_request_durations(args.request_durations_file)
+
+
+if __name__ == '__main__':
+    main()

run_sk_stress_test

@@ -22,6 +22,7 @@ import subprocess
 import argparse
 import platform
 import codecs
+from analyze_request_durations import analyze_request_durations
 
 import common
 
@@ -230,9 +231,10 @@ class StressTesterRunner(object):
         # temporary file paths
         filtered_projects = os.path.join(script_dir, 'stress-tester-projects.json')
         results = os.path.join(script_dir, 'stress-tester-results.json')
+        request_durations = os.path.join(script_dir, 'stress-tester-request-durations.json')
 
         # remove temporary files if they already exist
-        self._cleanup([filtered_projects, results])
+        self._cleanup([filtered_projects, results, request_durations])
 
         run_env = {
             'SK_STRESS_TEST': self.stress_tester,
@@ -243,7 +245,9 @@ class StressTesterRunner(object):
             'SK_XFAILS_PATH': self.xfails_path,
             'SK_STRESS_ACTIVE_CONFIG': self.swift_branch,
             'SK_STRESS_SUPPRESS_OUTPUT': 'true',
-            'SK_STRESS_REWRITE_MODES': 'none concurrent insideout'}
+            'SK_STRESS_REWRITE_MODES': 'none concurrent insideout',
+            'SK_STRESS_REQUEST_DURATIONS_FILE': request_durations,
+        }
         run_env.update(os.environ)
         run_cmd = ['./runner.py',
           '--projects', filtered_projects,
@@ -264,6 +268,8 @@ class StressTesterRunner(object):
         except common.ExecuteCommandFailure:
             self.compat_runner_failed = True
 
+        analyze_request_durations(request_durations)
+
         success = self._process_output(results, self.xfails_path)
 
         return success