Add pythran option -ftime-report to print out the time spent on optim…

…izations

docs/CLI.rst

@@ -76,7 +76,7 @@ To know more options about Pythran, you can check::
   $> pythran --help
   usage: pythran [-h] [-o OUTPUT_FILE] [-P] [-E] [-e] [-v] [-w] [-V] [-p pass]
                  [-I include_dir] [-L ldflags] [-D macro_definition]
-                 [-U macro_definition] [--config config]
+                 [-U macro_definition] [--config config] [-ftime-report]
                  input_file
   
   pythran: a python to C++ compiler
@@ -102,5 +102,6 @@ To know more options about Pythran, you can check::
                          compiler
     -U macro_definition  any macro undef relevant to the underlying C++ compiler
     --config config      config additional params
+    -ftime-report        report time spent in each optimization/transformation
   
   It's a megablast!

pythran/middlend.py

@@ -14,52 +14,59 @@
                                      NormalizeIfElse,
                                      NormalizeStaticIf, SplitStaticExpression,
                                      RemoveFStrings)
+import re
 
 
-def refine(pm, node, optimizations):
+def refine(pm, node, optimizations, report_times=False):
     """ Refine node in place until it matches pythran's expectations. """
+    run_times = {}
     # Sanitize input
-    pm.apply(RemoveDeadFunctions, node)
-    pm.apply(ExpandGlobals, node)
-    pm.apply(ExpandImportAll, node)
-    pm.apply(NormalizeTuples, node)
-    pm.apply(RemoveFStrings, node)
-    pm.apply(ExpandBuiltins, node)
-    pm.apply(ExpandImports, node)
-    pm.apply(NormalizeMethodCalls, node)
-    pm.apply(NormalizeIfElse, node)
-    pm.apply(NormalizeIsNone, node)
-    pm.apply(SplitStaticExpression, node)
-    pm.apply(NormalizeStaticIf, node)
-    pm.apply(NormalizeTuples, node)
-    pm.apply(NormalizeException, node)
-    pm.apply(NormalizeMethodCalls, node)
+    pm.apply(RemoveDeadFunctions, node, run_times)
+    pm.apply(ExpandGlobals, node, run_times)
+    pm.apply(ExpandImportAll, node, run_times)
+    pm.apply(NormalizeTuples, node, run_times)
+    pm.apply(RemoveFStrings, node, run_times)
+    pm.apply(ExpandBuiltins, node, run_times)
+    pm.apply(ExpandImports, node, run_times)
+    pm.apply(NormalizeMethodCalls, node, run_times)
+    pm.apply(NormalizeIfElse, node, run_times)
+    pm.apply(NormalizeIsNone, node, run_times)
+    pm.apply(SplitStaticExpression, node, run_times)
+    pm.apply(NormalizeStaticIf, node, run_times)
+    pm.apply(NormalizeTuples, node, run_times)
+    pm.apply(NormalizeException, node, run_times)
+    pm.apply(NormalizeMethodCalls, node, run_times)
 
     # Some early optimizations
-    pm.apply(ComprehensionPatterns, node)
+    pm.apply(ComprehensionPatterns, node, run_times)
 
-    pm.apply(RemoveLambdas, node)
-    pm.apply(RemoveNestedFunctions, node)
-    pm.apply(NormalizeCompare, node)
+    pm.apply(RemoveLambdas, node, run_times)
+    pm.apply(RemoveNestedFunctions, node, run_times)
+    pm.apply(NormalizeCompare, node, run_times)
 
-    pm.gather(ExtendedSyntaxCheck, node)
+    pm.gather(ExtendedSyntaxCheck, node, run_times)
 
-    pm.apply(ListCompToGenexp, node)
-    pm.apply(RemoveComprehension, node)
-    pm.apply(RemoveNamedArguments, node)
+    pm.apply(ListCompToGenexp, node, run_times)
+    pm.apply(RemoveComprehension, node, run_times)
+    pm.apply(RemoveNamedArguments, node, run_times)
 
     # sanitize input
-    pm.apply(NormalizeReturn, node)
-    pm.apply(UnshadowParameters, node)
-    pm.apply(FalsePolymorphism, node)
+    pm.apply(NormalizeReturn, node, run_times)
+    pm.apply(UnshadowParameters, node, run_times)
+    pm.apply(FalsePolymorphism, node, run_times)
 
     # some extra optimizations
     apply_optimisation = True
     while apply_optimisation:
         apply_optimisation = False
         for optimization in optimizations:
-            apply_optimisation |= pm.apply(optimization, node)[0]
-
+            apply_optimisation |= pm.apply(optimization, node, run_times)[0]
+
+    if report_times and len(run_times):
+        print("Optimization run times:")
+        for key,val in run_times.items():
+            k = re.findall("'(.*)'",str(key))
+            print(f"{k[0]:<70s} : {val:>5.1f} s")
 
 def mark_unexported_functions(ir, exported_functions):
     from pythran.metadata import add as MDadd, Local as MDLocal

pythran/passmanager.py

@@ -14,6 +14,7 @@
 import gast as ast
 import os
 import re
+from time import time
 
 
 def uncamel(name):
@@ -210,12 +211,16 @@ def __init__(self, module_name, module_dir=None):
         self.module_dir = module_dir or os.getcwd()
         self._cache = {}
 
-    def gather(self, analysis, node):
+    def gather(self, analysis, node, run_times = None):
         "High-level function to call an `analysis' on a `node'"
+        t0 = time()
         assert issubclass(analysis, Analysis)
         a = analysis()
         a.attach(self)
-        return a.run(node)
+        ret = a.run(node)
+        if run_times is not None: run_times[analysis] = run_times.get(analysis,0) + time()-t0
+
+        return ret
 
     def dump(self, backend, node):
         '''High-level function to call a `backend' on a `node' to generate
@@ -225,13 +230,16 @@ def dump(self, backend, node):
         b.attach(self)
         return b.run(node)
 
-    def apply(self, transformation, node):
+    def apply(self, transformation, node, run_times = None):
         '''
         High-level function to call a `transformation' on a `node'.
         If the transformation is an analysis, the result of the analysis
         is displayed.
         '''
+        t0 = time()
         assert issubclass(transformation, (Transformation, Analysis))
         a = transformation()
         a.attach(self)
-        return a.apply(node)
+        ret=a.apply(node)
+        if run_times is not None: run_times[transformation] = run_times.get(transformation,0) + time()-t0
+        return ret

pythran/run.py

@@ -122,6 +122,10 @@ def run():
                         help='config additional params',
                         default=list())
 
+    parser.add_argument('-ftime-report', dest='report_times',
+                        action='store_true',
+                        help='report time spent in each optimization/transformation')
+
     parser.convert_arg_line_to_args = convert_arg_line_to_args
 
     args, extra = parser.parse_known_args(sys.argv[1:])
@@ -177,6 +181,7 @@ def run():
                                         output_file=args.output_file,
                                         cpponly=args.translate_only,
                                         pyonly=args.optimize_only,
+                                        report_times=args.report_times,
                                         **compile_flags(args))
 
     except IOError as e:

pythran/toolchain.py

@@ -87,7 +87,7 @@ def has_argument(module, fname):
 
 
 def front_middle_end(module_name, code, optimizations=None, module_dir=None,
-                     entry_points=None):
+                     entry_points=None, report_times = False):
     """Front-end and middle-end compilation steps"""
 
     pm = PassManager(module_name, module_dir)
@@ -102,27 +102,27 @@ def front_middle_end(module_name, code, optimizations=None, module_dir=None,
     if optimizations is None:
         optimizations = cfg.get('pythran', 'optimizations').split()
     optimizations = [_parse_optimization(opt) for opt in optimizations]
-    refine(pm, ir, optimizations)
+    refine(pm, ir, optimizations, report_times)
 
     return pm, ir, docstrings
 
 
 # PUBLIC INTERFACE STARTS HERE
 
 
-def generate_py(module_name, code, optimizations=None, module_dir=None):
+def generate_py(module_name, code, optimizations=None, module_dir=None, report_times=False):
     '''python + pythran spec -> py code
 
     Prints and returns the optimized python code.
 
     '''
 
-    pm, ir, _ = front_middle_end(module_name, code, optimizations, module_dir)
+    pm, ir, _ = front_middle_end(module_name, code, optimizations, module_dir, report_times=report_times)
     return pm.dump(Python, ir)
 
 
 def generate_cxx(module_name, code, specs=None, optimizations=None,
-                 module_dir=None):
+                 module_dir=None, report_times=False):
     '''python + pythran spec -> c++ code
     returns a PythonModule object and an error checker
 
@@ -137,6 +137,7 @@ def generate_cxx(module_name, code, specs=None, optimizations=None,
 
     pm, ir, docstrings = front_middle_end(module_name, code, optimizations,
                                           module_dir,
+                                          report_times=report_times,
                                           entry_points=entry_points)
 
     # back-end
@@ -364,7 +365,7 @@ def compile_cxxcode(module_name, cxxcode, output_binary=None, keep_temp=False,
 
 def compile_pythrancode(module_name, pythrancode, specs=None,
                         opts=None, cpponly=False, pyonly=False,
-                        output_file=None, module_dir=None, **kwargs):
+                        output_file=None, module_dir=None, report_times=False, **kwargs):
     '''Pythran code (string) -> c++ code -> native module
 
     if `cpponly` is set to true, return the generated C++ filename
@@ -375,7 +376,7 @@ def compile_pythrancode(module_name, pythrancode, specs=None,
 
     if pyonly:
         # Only generate the optimized python code
-        content = generate_py(module_name, pythrancode, opts, module_dir)
+        content = generate_py(module_name, pythrancode, opts, module_dir, report_times)
         if output_file is None:
             print(content)
             return None
@@ -392,7 +393,7 @@ def compile_pythrancode(module_name, pythrancode, specs=None,
 
     # Generate C++, get a PythonModule object
     module, error_checker = generate_cxx(module_name, pythrancode, specs, opts,
-                                         module_dir)
+                                         module_dir, report_times)
 
     if 'ENABLE_PYTHON_MODULE' in kwargs.get('undef_macros', []):
         module.preamble.insert(0, Line('#undef ENABLE_PYTHON_MODULE'))
@@ -426,7 +427,7 @@ def compile_pythrancode(module_name, pythrancode, specs=None,
 
 
 def compile_pythranfile(file_path, output_file=None, module_name=None,
-                        cpponly=False, pyonly=False, **kwargs):
+                        cpponly=False, pyonly=False, report_times=False, **kwargs):
     """
     Pythran file -> c++ file -> native module.
 
@@ -474,6 +475,7 @@ def compile_pythranfile(file_path, output_file=None, module_name=None,
                                               output_file=output_file,
                                               cpponly=cpponly, pyonly=pyonly,
                                               module_dir=module_dir,
+                                              report_times=report_times,
                                               **kwargs)
     except PythranSyntaxError as e:
         if e.filename is None: