Added per node runtime logging

Author: ccraddock

nipype/pipeline/plugins/callback_log.py

@@ -5,9 +5,10 @@ def log_nodes_cb(node, status, result=None):
     logger = logging.getLogger('callback')
     try:
         real_mem1 = result['real_memory']
-        real_mem2 = result['result'].runtime.get('real_memory2')
+        real_mem2 = result['real_memory2']
+        run_seconds = result['run_seconds']
     except Exception as exc:
-        real_mem1 = real_mem2 = 'N/A'
+        real_mem1 = real_mem2 = run_seconds = 'N/A'
     if status == 'start':
         message  = '{"name":' + '"' + node.name + '"' + ',"id":' + '"' +\
         node._id + '"' + ',"start":' + '"' +str(datetime.datetime.now()) +\
@@ -20,7 +21,7 @@ def log_nodes_cb(node, status, result=None):
         message  = '{"name":' + '"' + node.name + '"' + ',"id":' + '"' + \
         node._id + '"' + ',"finish":' + '"' + str(datetime.datetime.now()) +\
         '"' + ',"memory":' + str(node._interface.estimated_memory) + ',"num_threads":' \
-        + str(node._interface.num_threads) + ',"real memory1":' + str(real_mem1) + ',"real memory2":' + str(real_mem2) + '}'
+        + str(node._interface.num_threads) + ',"real_memory1":' + str(real_mem1) + ',"real_memory2":' + str(real_mem2) + ',"run_seconds":' + str(run_seconds) + '}'
 
         logger.debug(message)
 

nipype/pipeline/plugins/multiproc.py

@@ -21,11 +21,15 @@ def run_node(node, updatehash, plugin_args=None):
         run_memory = False
     if run_memory:
         import memory_profiler
+        import datetime
         proc = (node.run, (), {'updatehash' : updatehash})
+        start = datetime.datetime.now()
         mem_mb, retval = memory_profiler.memory_usage(proc=proc, retval=True, include_children=True, max_usage=True)
+        runtime = (datetime.datetime.now() - start).total_seconds()
         result['result'] = retval
         result['real_memory'] = mem_mb[0]/1024.0
         result['real_memory2'] = retval.runtime.get('real_memory2')
+        result['run_seconds'] = runtime
     else:
         try:
             result['result'] = node.run(updatehash=updatehash)