hybrid_server/classes/mvkcontroller.xml

@@ -20,6 +20,12 @@
             for parameter in params:
                 if parameter.startswith('--kernel='):
                     kernel_opts = parameter[len('--kernel='):].split(',')
+                elif parameter.startswith('--jit-timing-log='):
+                    output_file = open(parameter[len('--jit-timing-log='):], 'w')
+                    def log_line(line):
+                        output_file.write(line + '\n')
+                        output_file.flush()
+                    self.mvk.jit.set_jit_timing_log(log_line)
 
             for opt in kernel_opts:
                 if opt == 'legacy-interpreter':

kernel/modelverse_jit/bytecode_interpreter.py

@@ -22,7 +22,7 @@ class ContinueException(Exception):
 
 class InterpreterState(object):
     """The state of the bytecode interpreter."""
-    def __init__(self, gc_root_node, keyword_arg_dict, nop_period=20):
+    def __init__(self, gc_root_node, keyword_arg_dict, nop_period=10):
         self.gc_root_node = gc_root_node
         self.nop_period = nop_period
         self.keyword_arg_dict = keyword_arg_dict
@@ -108,7 +108,7 @@ class InterpreterState(object):
         def __handle_continue(exception):
             if exception.loop == instruction:
                 # Restart the loop.
-                yield [("TAIL_CALL_ARGS", [self.interpret, (instruction,)])]
+                yield [("TAIL_CALL_ARGS", [self.interpret_while, (instruction,)])]
             else:
                 # Propagate the exception to the next 'while' loop.
                 raise exception
@@ -194,12 +194,10 @@ class InterpreterState(object):
         """Interprets a 'declare' (local) instruction."""
         node_id = instruction.variable.node_id
         if node_id in self.local_vars:
-            self.update_result(self.local_vars[node_id])
             raise primitive_functions.PrimitiveFinished(None)
         else:
             local_node, = yield [("CN", [])]
             yield [("CE", [self.gc_root_node, local_node])]
-            self.update_result(local_node)
             self.local_vars[node_id] = local_node
             raise primitive_functions.PrimitiveFinished(None)
 
@@ -214,8 +212,6 @@ class InterpreterState(object):
             global_var, = yield [("CN", [])]
             yield [("CD", [_globals, var_name, global_var])]
 
-        self.update_result(global_var)
-        yield [("CE", [self.gc_root_node, global_var])]
         raise primitive_functions.PrimitiveFinished(None)
 
     def interpret_resolve(self, instruction):

kernel/modelverse_jit/jit.py

@@ -1,5 +1,6 @@
 import math
 import keyword
+import time
 from collections import defaultdict
 import modelverse_kernel.primitives as primitive_functions
 import modelverse_jit.bytecode_parser as bytecode_parser
@@ -155,6 +156,7 @@ class ModelverseJit(object):
         self.thunks_enabled = True
         self.jit_success_log_function = None
         self.jit_code_log_function = None
+        self.jit_timing_log = None
         self.compile_function_body = compile_function_body_baseline
 
     def set_jit_enabled(self, is_enabled=True):
@@ -210,6 +212,11 @@ class ModelverseJit(object):
         """Sets the function that the JIT uses to compile function bodies."""
         self.compile_function_body = compile_function_body
 
+    def set_jit_timing_log(self, log_function=print_value):
+        """Configures this JIT instance with a function that prints output to a log.
+           The time it takes to compile functions is then sent to this log."""
+        self.jit_timing_log = log_function
+
     def mark_entry_point(self, body_id):
         """Marks the node with the given identifier as a function entry point."""
         if body_id not in self.no_jit_entry_points and body_id not in self.jitted_entry_points:
@@ -481,6 +488,9 @@ class ModelverseJit(object):
     def jit_recompile(self, task_root, body_id, function_name, compile_function_body=None):
         """Replaces the function with the given name by compiling the bytecode at the given
            body id."""
+        if self.jit_timing_log is not None:
+            start_time = time.time()
+
         if compile_function_body is None:
             compile_function_body = self.compile_function_body
 
@@ -530,6 +540,11 @@ class ModelverseJit(object):
             self.jit_success_log_function(
                 "JIT compilation successful: (function '%s' at %d)" % (function_name, body_id))
 
+        if self.jit_timing_log is not None:
+            end_time = time.time()
+            compile_time = end_time - start_time
+            self.jit_timing_log('Compile time for %s:%f' % (function_name, compile_time))
+
         raise primitive_functions.PrimitiveFinished(compiled_function)
 
     def get_source_map_name(self, function_name):

kernel/modelverse_kernel/main.py

@@ -79,6 +79,15 @@ class ModelverseKernel(object):
         #
         #     self.jit.set_jit_success_log(logging_function)
         #
+        # To make the JIT print compile times to the command-line,
+        # uncomment the line below:
+        #
+        #     self.jit.set_jit_timing_log()
+        #
+        # If you want, you can use a custom logging function:
+        #
+        #     self.jit.set_jit_timing_log(logging_function)
+        #
         # To make the JIT print jitted code to the command-line, uncomment the
         # line below:
         #

performance/utils.py

@@ -1,6 +1,7 @@
 import unittest
 import sys
 import os
+import tempfile
 
 import sys
 import time
@@ -184,7 +185,7 @@ def compile_files(address, process, files, mode):
         if val != 0:
             raise Exception("Linking error")
 
-def run_file(files, parameters, mode, handle_output, optimization_level=None):
+def run_file(files, parameters, mode, handle_output, optimization_level=None, jit_timing_log=None):
     """Compiles the given sequence of files, feeds them the given input in the given mode,
        and handles their output."""
     # Resolve file
@@ -198,6 +199,9 @@ def run_file(files, parameters, mode, handle_output, optimization_level=None):
         modelverse_args = [str(port)]
         if optimization_level is not None:
             modelverse_args.append('--kernel=%s' % optimization_level)
+        if jit_timing_log is not None:
+            modelverse_args.append('--jit-timing-log=%s' % jit_timing_log)
+
         proc = execute("run_local_modelverse", modelverse_args, wait=False)
 
         # Compile, push and link the source code files.
@@ -246,7 +250,8 @@ def run_file_to_completion(files, parameters, mode):
     except ModelverseTerminated:
         return results
 
-def run_file_fixed_output_count(files, parameters, mode, output_count, optimization_level=None):
+def run_file_fixed_output_count(
+        files, parameters, mode, output_count, optimization_level=None, jit_timing_log=None):
     """Compiles the given sequence of files, feeds them the given input in the given mode,
        and then collects and returns a fixed number of outputs."""
     results = []
@@ -258,34 +263,57 @@ def run_file_fixed_output_count(files, parameters, mode, output_count, optimizat
         else:
             return False
 
-    run_file(files, parameters, mode, handle_output, optimization_level)
+    run_file(files, parameters, mode, handle_output, optimization_level, jit_timing_log)
     return results
 
-def run_file_single_output(files, parameters, mode, optimization_level=None):
+def run_file_single_output(files, parameters, mode, optimization_level=None, jit_timing_log=None):
     """Compiles the given sequence of files, feeds them the given input in the given mode,
        and then collects and returns a single output."""
-    return run_file_fixed_output_count(files, parameters, mode, 1, optimization_level)[0]
+    return run_file_fixed_output_count(
+        files, parameters, mode, 1, optimization_level, jit_timing_log)[0]
 
 def mean(values):
     """Computes the arithmetic mean of the given values."""
     return float(sum(values)) / max(len(values), 1)
 
+def parse_jit_timing_log(log_file):
+    """Parses the JIT timing log entries from the given file."""
+    results = []
+    for line in log_file.readlines():
+        first, _, data = line.strip().rpartition(':')
+        _, _, name = first.strip().rpartition(' ')
+        results.append((name, float(data)))
+    return results
+
 def run_perf_test(files, parameters, optimization_level, n_iterations=1):
     """Compiles the given sequence of files, feeds them the given input in the given mode,
        and then collects their output. This process is repeated n_iterations times. The
        return value is the average of all outputs, along with the mean total run-time."""
     test_runtimes = []
     total_runtimes = []
+    compile_times = []
     for _ in xrange(n_iterations):
-        start_time = time.time()
-        test_time = run_file_single_output(
-            files, parameters, 'CO',
-            optimization_level)
-        end_time = time.time()
-        total_time = end_time - start_time
-        test_runtimes.append(test_time)
-        total_runtimes.append(total_time)
-    return mean(test_runtimes), mean(total_runtimes)
+        try:
+            timing_log = tempfile.mktemp()
+            start_time = time.time()
+            test_time = run_file_single_output(
+                files, parameters, 'CO',
+                optimization_level, timing_log)
+            end_time = time.time()
+            total_time = end_time - start_time
+            test_runtimes.append(test_time)
+            total_runtimes.append(total_time)
+            with open(timing_log, 'r') as log_file:
+                parsed_times = parse_jit_timing_log(log_file)
+
+            compile_times.append(sum([data for _, data in parsed_times]))
+        finally:
+            os.remove(timing_log)
+    return {
+        TEST_TIME_QUANTITY: mean(test_runtimes),
+        TOTAL_TIME_QUANTITY: mean(total_runtimes),
+        COMPILE_TIME_QUANTITY: mean(compile_times)
+    }
 
 def get_expectation_checks(expected_values):
     """Converts the given sequence of expected values to a sequence of functions which tell
@@ -373,6 +401,7 @@ DEFAULT_PERF_FILE_NAME = 'perf_data.txt'
 
 TOTAL_TIME_QUANTITY = 'total-runtime'
 TEST_TIME_QUANTITY = 'test-runtime'
+COMPILE_TIME_QUANTITY = 'compile-time'
 
 def write_perf_entry_to_stream(
         test_name, optimization_level, quantity,
@@ -383,12 +412,10 @@ def write_perf_entry_to_stream(
 def write_perf_to_file(
         test_name, optimization_level, runtimes, file_name=DEFAULT_PERF_FILE_NAME):
     """Writes performance data to a file."""
-    test_runtime, total_runtime = runtimes
     with open(file_name, "a") as perf_file:
-        write_perf_entry_to_stream(
-            test_name, optimization_level, TEST_TIME_QUANTITY, test_runtime, perf_file)
-        write_perf_entry_to_stream(
-            test_name, optimization_level, TOTAL_TIME_QUANTITY, total_runtime, perf_file)
+        for quantity, data_point in runtimes.items():
+            write_perf_entry_to_stream(
+                test_name, optimization_level, quantity, data_point, perf_file)
 
 def write_total_runtime_to_file(
         test_name, optimization_level, total_runtime, file_name=DEFAULT_PERF_FILE_NAME):