Improve profiler logging

* The custom profiler notifier defined by Mistral now also prints
  the total elapsed time of a profiler trace into the log file .
  This makes it much easier to search for bottlenecks.

Change-Id: I1db7e66e1b3756cccfde73feee83baef9edf283f

mistral/utils/profiler.py

@@ -21,6 +21,8 @@ from oslo_log import log as logging
 import osprofiler.profiler
 import osprofiler.web
 
+from mistral import utils
+
 
 PROFILER_LOG = logging.getLogger(cfg.CONF.profiler.profiler_log_name)
 
@@ -34,6 +36,30 @@ def log_to_file(info, context=None):
         info['name']
     ]
 
+    th_local_name = '_profiler_trace_%s_start_time_' % info['trace_id']
+
+    if info['name'].endswith('-start'):
+        utils.set_thread_local(
+            th_local_name,
+            datetime.datetime.utcnow()
+        )
+
+        # Insert a blank sequence for a trace start.
+        attrs.insert(1, ' ' * 8)
+
+    if info['name'].endswith('-stop'):
+        delta = (
+            datetime.datetime.utcnow() - utils.get_thread_local(th_local_name)
+        ).total_seconds()
+
+        utils.set_thread_local(th_local_name, None)
+
+        # Insert a blank sequence for a trace start.
+        attrs.insert(1, str(delta))
+
+        if delta > 0.5:
+            attrs.append(' <- !!!')
+
     if 'info' in info and 'db' in info['info']:
         db_info = copy.deepcopy(info['info']['db'])