Add printing of the 5 slowest node make_thunk in the profile

theano/compile/profiling.py

@@ -19,6 +19,7 @@ __docformat__ = "restructuredtext en"
 
 import atexit
 import copy
+import operator
 import os
 import sys
 import time
@@ -78,7 +79,8 @@ def _atexit_print_fn():
 
             # merge dictonary
             for attr in ["apply_time", "apply_callcount",
-                         "apply_cimpl", "variable_shape", "variable_strides"]:
+                         "apply_cimpl", "variable_shape", "variable_strides",
+                         "linker_make_thunk_time"]:
                 cum_attr = getattr(cum, attr)
                 for key, val in iteritems(getattr(ps, attr)):
                     assert key not in cum_attr
@@ -193,6 +195,8 @@ class ProfileStats(object):
 
     linker_node_make_thunks = 0.0
 
+    linker_make_thunk_time = {}
+
     line_width = config.profiling.output_line_width
 
     nb_nodes = -1
@@ -670,6 +674,11 @@ class ProfileStats(object):
         print('       Import time %es' % self.import_time, file=file)
         print('       Node make_thunk time %es' % self.linker_node_make_thunks,
               file=file)
+
+        for node, t in sorted(self.linker_make_thunk_time.items(),
+                                 key=operator.itemgetter(1))[:5]:
+            print('           Node %s time %es' % (node, t),
+                  file=file)
         print('', file=file)
 
         # The validation time is a subset of optimizer_time

theano/gof/vm.py

@@ -1041,16 +1041,19 @@ class VM_Linker(link.LocalLinker):
         reallocated_info = calculate_reallocate_info(
             order, fgraph, storage_map, compute_map_re, dependencies)
         t0 = time.time()
+        linker_make_thunk_time = {}
+        impl = None
+        if self.c_thunks is False:
+            impl = 'py'
         for node in order:
             try:
-                impl = None
-                if self.c_thunks is False:
-                    impl = 'py'
+                thunk_start = time.time()
                 thunks.append(node.op.make_thunk(node,
                                                  storage_map,
                                                  compute_map,
                                                  no_recycling,
                                                  impl=impl))
+                linker_make_thunk_time[node] = time.time() - thunk_start
                 if not hasattr(thunks[-1], 'lazy'):
                     # We don't want all ops maker to think about lazy Ops.
                     # So if they didn't specify that its lazy or not, it isn't.
@@ -1064,6 +1067,7 @@ class VM_Linker(link.LocalLinker):
 
         if self.profile:
             self.profile.linker_node_make_thunks += t1 - t0
+            self.profile.linker_make_thunk_time = linker_make_thunk_time
 
         for node, thunk in zip(order, thunks):
             thunk.inputs = [storage_map[v] for v in node.inputs]