In ProfileMode, print the time spend in the optimizer and in the linker phase.

theano/compile/function_module.py

@@ -868,9 +868,11 @@ class FunctionMaker(object):
         optimizer, linker = mode.optimizer, copy.copy(mode.linker)
 
         # optimize the env
-        t0 = time.time()
+        start_optimizer = time.time()
         optimizer(env)
-        _logger.debug('Optimizing took %f seconds' % (time.time() - t0))
+        end_optimizer = time.time()
+        mode.optimizer_time += end_optimizer - start_optimizer
+        _logger.debug('Optimizing took %f seconds' % (end_optimizer - start_optimizer))
 
         # This loop was inserted to remove aliasing between outputs when they all
         # evaluete to the same value. Originally it was OK for outputs to be aliased,
@@ -978,9 +980,11 @@ class FunctionMaker(object):
 
 
         # Get a function instance
-        t0 = time.time()
+        start_linker = time.time()
         _fn, _i, _o = self.linker.make_thunk(input_storage = input_storage_lists)
-        _logger.debug('Linking took %f seconds' % (time.time() - t0))
+        end_linker = time.time()
+        _logger.debug('Linker took %f seconds' % (end_linker - start_linker))
+        self.mode.linker_time += end_linker - start_linker
         fn = self.function_builder(_fn, _i, _o, self.indices, self.outputs, defaults, self.unpack_single, self.return_none, self)
         return fn
 

theano/compile/mode.py

@@ -222,6 +222,8 @@ class Mode(object):
         self._optimizer = optimizer
         self.call_time = 0
         self.fn_time = 0
+        self.optimizer_time = 0
+        self.linker_time = 0
 
     def __str__(self):
         return "Mode(linker = %s, optimizer = %s)" % (self.provided_linker, self.provided_optimizer)

theano/compile/profilemode.py

@@ -69,6 +69,8 @@ class ProfileMode(Mode):
         self.fct_call = fct_call
         self.call_time = 0
         self.fn_time = 0
+        self.optimizer_time = 0
+        self.linker_time = 0
         self.message = ""
         self.outputs_size = outputs_size
 
@@ -168,9 +170,12 @@ class ProfileMode(Mode):
         op_cimpl = self.op_cimpl
         message = self.message
         outputs_size = self.outputs_size
+        other_time = {'linker_time':self.linker_time,
+                      'optimizer_time':self.optimizer_time}
 
         self.print_summary_("print_summary", compile_time, fct_call_time, fct_call,
-                            apply_time, op_cimpl, message, outputs_size, **kwargs)
+                            apply_time, op_cimpl, message, outputs_size, other_time,
+                            **kwargs)
 
 
     def print_diff_summary(self, other, **kwargs):
@@ -205,15 +210,17 @@ class ProfileMode(Mode):
         op_cimpl = self.op_cimpl and other.op_cimpl
         message = self.message
         outputs_size = diff_dict(self.outputs_size,other.outputs_size)
-
+        other_time = {'linker_time':self.linker_time-other.linker_time,
+                      'optimizer_time':self.optimizer_time-other.optimizer_time}
         self.print_summary_("print_diff_summary", compile_time, fct_call_time, fct_call,
                             apply_time, op_cimpl, message, outputs_size,
-                            print_apply=False,
+                            print_apply=False, other_time=other_time,
                             **kwargs)
 
     @staticmethod
     def print_summary_(fct_name, compile_time, fct_call_time, fct_call,
                        apply_time, op_cimpl, message, outputs_size,
+                       other_time,
                        n_apply_to_print=config.ProfileMode.n_apply_to_print,
                        n_ops_to_print=config.ProfileMode.n_ops_to_print,
                        print_apply=True,
@@ -367,7 +374,9 @@ class ProfileMode(Mode):
 
         print
         print 'Time since import %.3fs'%(total_time)
-        print 'Compile time: %.3fs %.1f%%'%(compile_time, compile_time/total_time*100)
+        print 'Theano compile time: %.3fs %.1f%%'%(compile_time, compile_time/total_time*100)
+        print '    Optimization time: %.3fs'%(other_time['optimizer_time'])
+        print '    Linker time: %.3fs'%(other_time['linker_time'])
         print 'Theano fct call %.3fs %.1f%%'%(total_fct_time,total_fct_time/total_time*100)
         print '   Theano Op time (included in fct call, Time spent running thunks) %.3fs %.1f%%(of total) %.1f%%(of fct call)'% (local_time,local_time/total_time*100, time_pr_in_fct)
         print 'Unknow time since import %.3fs %.1f%%'%(unknow_time,unknow_time/total_time*100)