Add profiling of the import time

theano/compile/function_module.py

@@ -1410,6 +1410,7 @@ class FunctionMaker(object):
 
         # Get a function instance
         start_linker = time.time()
+        start_import_time = theano.gof.cmodule.import_time
         add_stack_trace_on_call_orig = gof.Op.add_stack_trace_on_call
         limit_orig = theano.config.traceback.limit
         try:
@@ -1428,6 +1429,8 @@ class FunctionMaker(object):
         if self.profile:
             self.profile.linker_time += linker_time
             _fn.time_thunks = self.profile.flag_time_thunks
+            import_time = theano.gof.cmodule.import_time - start_import_time
+            self.profile.import_time += import_time
 
         fn = self.function_builder(_fn, _i, _o, self.indices, self.outputs,
                 defaults, self.unpack_single, self.return_none, self)

theano/compile/profiling.py

@@ -104,7 +104,7 @@ def _atexit_print_fn():
         for ps in to_sum[1:]:
             for attr in ["compile_time", "fct_call_time", "fct_callcount",
                          "vm_call_time", "optimizer_time", "linker_time",
-                         "validate_time"]:
+                         "validate_time", "import_time"]:
                 setattr(cum, attr, getattr(cum, attr) + getattr(ps, attr))
 
             # merge dictonary
@@ -194,6 +194,9 @@ class ProfileStats(object):
     linker_time = 0.0
     # time spent linking graph (FunctionMaker.create)
 
+    import_time = 0.0
+    # time spent in importing compiled python module.
+
     line_width = config.profiling.output_line_width
 
     optimizer_profile = None
@@ -640,6 +643,7 @@ class ProfileStats(object):
         print >> file, ('    Theano Linker time (includes C,'
                         ' CUDA code generation/compiling): %es' %
                         self.linker_time)
+        print >> file, '       Import time %es' % self.import_time
         print >> file, ''
 
         # The validation time is a subset of optimizer_time

theano/gof/cmodule.py

@@ -71,6 +71,8 @@ _logger = logging.getLogger("theano.gof.cmodule")
 
 METH_VARARGS = "METH_VARARGS"
 METH_NOARGS = "METH_NOARGS"
+# global variable that represent the total time spent in importing module.
+import_time = 0
 
 
 class MissingGXX(Exception):
@@ -282,11 +284,15 @@ def dlimport(fullpath, suffix=None):
     _logger.debug("module_name %s", module_name)
 
     sys.path[0:0] = [workdir]  # insert workdir at beginning (temporarily)
+    global import_time
     try:
         if importlib is not None:
             if hasattr(importlib, "invalidate_caches"):
                 importlib.invalidate_caches()
+        t0 = time.time()
         rval = __import__(module_name, {}, {}, [module_name])
+        t1 = time.time()
+        import_time += t1 - t0
         if not rval:
             raise Exception('__import__ failed', fullpath)
     finally: