Enable osprofiler to measure performance

Add option to enable osprofiler to measure performance of workflow execution.

Change-Id: I98e66e3f721c134370848dc2b65fb37c49b0e8ee
Implements: blueprint mistral-osprofiler

etc/wf_trace_logging.conf.sample

@@ -1,17 +1,22 @@
 [loggers]
-keys=workflow_trace,root
+keys=workflow_trace,profiler_trace,root
 
 [handlers]
-keys=consoleHandler, wfTraceFileHandler, fileHandler
+keys=consoleHandler, wfTraceFileHandler, profilerFileHandler, fileHandler
 
 [formatters]
-keys=wfFormatter, simpleFormatter, verboseFormatter
+keys=wfFormatter, profilerFormatter, simpleFormatter, verboseFormatter
 
 [logger_workflow_trace]
 level=INFO
 handlers=consoleHandler, wfTraceFileHandler
 qualname=workflow_trace
 
+[logger_profiler_trace]
+level=INFO
+handlers=profilerFileHandler
+qualname=profiler_trace
+
 [logger_root]
 level=INFO
 handlers=fileHandler
@@ -34,6 +39,12 @@ level=INFO
 formatter=wfFormatter
 args=("/var/log/mistral_wf_trace.log",)
 
+[handler_profilerFileHandler]
+class=FileHandler
+level=INFO
+formatter=profilerFormatter
+args=("/var/log/mistral_osprofile.log",)
+
 [formatter_verboseFormatter]
 format=%(asctime)s %(thread)s %(levelname)s %(module)s [-] %(message)s
 datefmt=
@@ -45,3 +56,7 @@ datefmt=
 [formatter_wfFormatter]
 format=%(asctime)s WF [-] %(message)s
 datefmt=
+
+[formatter_profilerFormatter]
+format=%(message)s
+datefmt=

etc/wf_trace_logging.conf.sample.rotating

@@ -1,17 +1,22 @@
 [loggers]
-keys=workflow_trace,root
+keys=workflow_trace,profiler_trace,root
 
 [handlers]
-keys=consoleHandler, wfTraceFileHandler, fileHandler
+keys=consoleHandler, wfTraceFileHandler, profilerFileHandler, fileHandler
 
 [formatters]
-keys=wfFormatter, simpleFormatter, verboseFormatter
+keys=wfFormatter, profilerFormatter, simpleFormatter, verboseFormatter
 
 [logger_workflow_trace]
 level=INFO
 handlers=consoleHandler, wfTraceFileHandler
 qualname=workflow_trace
 
+[logger_profiler_trace]
+level=INFO
+handlers=profilerFileHandler
+qualname=profiler_trace
+
 [logger_root]
 level=INFO
 handlers=fileHandler
@@ -34,6 +39,12 @@ level=INFO
 formatter=wfFormatter
 args=("/var/log/mistral_wf_trace.log", "a", 10485760, 5)
 
+[handler_profilerFileHandler]
+class=logging.handlers.RotatingFileHandler
+level=INFO
+formatter=profilerFormatter
+args=("/var/log/mistral_osprofile.log", "a", 10485760, 5)
+
 [formatter_verboseFormatter]
 format=%(asctime)s %(thread)s %(levelname)s %(module)s [-] %(message)s
 datefmt=
@@ -45,3 +56,7 @@ datefmt=
 [formatter_wfFormatter]
 format=%(asctime)s WF [-] %(message)s
 datefmt=
+
+[formatter_profilerFormatter]
+format=%(message)s
+datefmt=

mistral/api/app.py

@@ -1,6 +1,5 @@
-# -*- coding: utf-8 -*-
-#
 # Copyright 2013 - Mirantis, Inc.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -16,6 +15,7 @@
 
 from oslo_config import cfg
 import oslo_middleware.cors as cors_middleware
+import osprofiler.web
 import pecan
 
 from mistral.api import access_control
@@ -67,6 +67,14 @@ def setup_app(config=None):
     # Set up access control.
     app = access_control.setup(app)
 
+    # Set up profiler.
+    if cfg.CONF.profiler.enabled:
+        app = osprofiler.web.WsgiMiddleware(
+            app,
+            hmac_keys=cfg.CONF.profiler.hmac_keys,
+            enabled=cfg.CONF.profiler.enabled
+        )
+
     # Create a CORS wrapper, and attach mistral-specific defaults that must be
     # included in all CORS responses.
     return cors_middleware.CORS(app, cfg.CONF)

mistral/cmd/launch.py

@@ -1,5 +1,5 @@
 #!/usr/bin/env python
-# -*- coding: utf-8 -*-
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -57,6 +57,7 @@ from mistral.engine import default_executor as def_executor
 from mistral.engine import rpc
 from mistral.services import expiration_policy
 from mistral.services import scheduler
+from mistral.utils import profiler
 from mistral import version
 
 
@@ -66,6 +67,8 @@ LOG = logging.getLogger(__name__)
 
 
 def launch_executor(transport):
+    profiler.setup('mistral-executor', cfg.CONF.executor.host)
+
     target = messaging.Target(
         topic=cfg.CONF.executor.topic,
         server=cfg.CONF.executor.host
@@ -100,6 +103,8 @@ def launch_executor(transport):
 
 
 def launch_engine(transport):
+    profiler.setup('mistral-engine', cfg.CONF.engine.host)
+
     target = messaging.Target(
         topic=cfg.CONF.engine.topic,
         server=cfg.CONF.engine.host

mistral/config.py

@@ -1,6 +1,5 @@
-# -*- coding: utf-8 -*-
-#
 # Copyright 2013 - Mirantis, Inc.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -23,6 +22,7 @@ import itertools
 from oslo_config import cfg
 from oslo_log import log
 from oslo_middleware import cors
+from osprofiler import opts as profiler
 
 from mistral import version
 
@@ -131,6 +131,15 @@ coordination_opts = [
                  help='Number of seconds between heartbeats for coordination.')
 ]
 
+profiler_opts = profiler.list_opts()[0][1]
+profiler_opts.append(
+    cfg.StrOpt(
+        'profiler_log_name',
+        default='profiler_trace',
+        help='Logger name for the osprofiler trace output.'
+    )
+)
+
 CONF = cfg.CONF
 
 API_GROUP = 'api'
@@ -139,6 +148,7 @@ EXECUTOR_GROUP = 'executor'
 PECAN_GROUP = 'pecan'
 COORDINATION_GROUP = 'coordination'
 EXECUTION_EXPIRATION_POLICY_GROUP = 'execution_expiration_policy'
+PROFILER_GROUP = profiler.list_opts()[0][0]
 
 CONF.register_opts(api_opts, group=API_GROUP)
 CONF.register_opts(engine_opts, group=ENGINE_GROUP)
@@ -149,6 +159,7 @@ CONF.register_opts(execution_expiration_policy_opts,
 CONF.register_opt(wf_trace_log_name_opt)
 CONF.register_opt(rpc_option)
 CONF.register_opts(coordination_opts, group=COORDINATION_GROUP)
+CONF.register_opts(profiler_opts, group=PROFILER_GROUP)
 
 CLI_OPTS = [
     use_debugger,
@@ -179,6 +190,7 @@ def list_opts():
         (PECAN_GROUP, pecan_opts),
         (COORDINATION_GROUP, coordination_opts),
         (EXECUTION_EXPIRATION_POLICY_GROUP, execution_expiration_policy_opts),
+        (PROFILER_GROUP, profiler_opts),
         (None, itertools.chain(
             CLI_OPTS,
             [

mistral/context.py

@@ -1,5 +1,5 @@
-#
 # Copyright 2013 - Mirantis, Inc.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -18,6 +18,7 @@ from keystoneclient.v3 import client as keystone_client
 from oslo_config import cfg
 import oslo_messaging as messaging
 from oslo_serialization import jsonutils
+from osprofiler import profiler
 import pecan
 from pecan import hooks
 
@@ -174,9 +175,25 @@ class RpcContextSerializer(messaging.Serializer):
         return self._base.deserialize_entity(context, entity)
 
     def serialize_context(self, context):
-        return context.to_dict()
+        ctx = context.to_dict()
+
+        pfr = profiler.get()
+
+        if pfr:
+            ctx['trace_info'] = {
+                "hmac_key": pfr.hmac_key,
+                "base_id": pfr.get_base_id(),
+                "parent_id": pfr.get_id()
+            }
+
+        return ctx
 
     def deserialize_context(self, context):
+        trace_info = context.pop('trace_info', None)
+
+        if trace_info:
+            profiler.init(**trace_info)
+
         ctx = MistralContext(**context)
         set_ctx(ctx)
 

mistral/db/sqlalchemy/base.py

@@ -1,6 +1,5 @@
-# -*- coding: utf-8 -*-
-#
 # Copyright 2013 - Mirantis, Inc.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -19,6 +18,7 @@ import six
 from oslo_config import cfg
 from oslo_db import options
 from oslo_db.sqlalchemy import session as db_session
+import osprofiler.sqlalchemy
 import sqlalchemy as sa
 
 from mistral.db.sqlalchemy import sqlite_lock
@@ -46,6 +46,14 @@ def _get_facade():
             **dict(six.iteritems(cfg.CONF.database))
         )
 
+        if cfg.CONF.profiler.enabled:
+            if cfg.CONF.profiler.trace_sqlalchemy:
+                osprofiler.sqlalchemy.add_tracing(
+                    sa,
+                    _facade.get_engine(),
+                    'db'
+                )
+
     return _facade
 
 

mistral/engine/action_handler.py

@@ -1,4 +1,5 @@
 # Copyright 2015 - Mirantis, Inc.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -13,6 +14,7 @@
 #    limitations under the License.
 
 from oslo_log import log as logging
+from osprofiler import profiler
 import traceback as tb
 
 from mistral.db.v2.sqlalchemy import models
@@ -25,6 +27,7 @@ from mistral.workbook import parser as spec_parser
 LOG = logging.getLogger(__name__)
 
 
+@profiler.trace('action-handler-on-action-complete')
 def on_action_complete(action_ex, result):
     task_ex = action_ex.task_execution
 

mistral/engine/actions.py

@@ -1,4 +1,5 @@
 # Copyright 2016 - Nokia Networks.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -15,6 +16,7 @@
 import abc
 from oslo_config import cfg
 from oslo_log import log as logging
+from osprofiler import profiler
 import six
 
 from mistral.db.v2 import api as db_api
@@ -190,6 +192,7 @@ class Action(object):
 class PythonAction(Action):
     """Regular Python action."""
 
+    @profiler.trace('action-complete')
     def complete(self, result):
         assert self.action_ex
 
@@ -205,6 +208,7 @@ class PythonAction(Action):
 
         self._log_result(prev_state, result)
 
+    @profiler.trace('action-schedule')
     def schedule(self, input_dict, target, index=0, desc=''):
         assert not self.action_ex
 
@@ -222,6 +226,7 @@ class PythonAction(Action):
             target=target
         )
 
+    @profiler.trace('action-run')
     def run(self, input_dict, target, index=0, desc='', save=True):
         assert not self.action_ex
 
@@ -355,10 +360,12 @@ class AdHocAction(PythonAction):
 class WorkflowAction(Action):
     """Workflow action."""
 
+    @profiler.trace('action-complete')
     def complete(self, result):
         # No-op because in case of workflow result is already processed.
         pass
 
+    @profiler.trace('action-schedule')
     def schedule(self, input_dict, target, index=0, desc=''):
         assert not self.action_ex
 
@@ -397,6 +404,7 @@ class WorkflowAction(Action):
             wf_params
         )
 
+    @profiler.trace('action-run')
     def run(self, input_dict, target, index=0, desc='', save=True):
         raise NotImplemented('Does not apply to this WorkflowAction.')
 

mistral/engine/default_engine.py

@@ -1,5 +1,6 @@
 # Copyright 2013 - Mirantis, Inc.
 # Copyright 2015 - StackStorm, Inc.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -14,6 +15,7 @@
 #    limitations under the License.
 
 from oslo_log import log as logging
+from osprofiler import profiler
 
 from mistral import coordination
 from mistral.db.v2 import api as db_api
@@ -38,6 +40,7 @@ class DefaultEngine(base.Engine, coordination.Service):
         coordination.Service.__init__(self, 'engine_group')
 
     @u.log_exec(LOG)
+    @profiler.trace('engine-start-workflow')
     def start_workflow(self, wf_identifier, wf_input, description='',
                        **params):
         with db_api.transaction():
@@ -78,6 +81,7 @@ class DefaultEngine(base.Engine, coordination.Service):
             )
 
     @u.log_exec(LOG)
+    @profiler.trace('engine-on-action-complete')
     def on_action_complete(self, action_ex_id, result):
         with db_api.transaction():
             action_ex = db_api.get_action_execution(action_ex_id)

mistral/engine/default_executor.py

@@ -1,6 +1,5 @@
-# -*- coding: utf-8 -*-
-#
 # Copyright 2013 - Mirantis, Inc.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -15,6 +14,7 @@
 #    limitations under the License.
 
 from oslo_log import log as logging
+from osprofiler import profiler
 
 from mistral.actions import action_factory as a_f
 from mistral import coordination
@@ -32,6 +32,7 @@ class DefaultExecutor(base.Executor, coordination.Service):
 
         coordination.Service.__init__(self, 'executor_group')
 
+    @profiler.trace('executor-run-action')
     def run_action(self, action_ex_id, action_class_str, attributes,
                    action_params):
         """Runs action.

mistral/engine/dispatcher.py

@@ -1,4 +1,5 @@
 # Copyright 2016 - Nokia Networks
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -12,12 +13,14 @@
 #    See the License for the specific language governing permissions and
 #    limitations under the License.
 
+from osprofiler import profiler
 
 from mistral import exceptions as exc
 from mistral.workflow import commands
 from mistral.workflow import states
 
 
+@profiler.trace('dispatcher-dispatch-commands')
 def dispatch_workflow_commands(wf_ex, wf_cmds):
     # TODO(rakhmerov): I don't like these imports but otherwise we have
     # import cycles.

mistral/engine/task_handler.py

@@ -1,6 +1,7 @@
 # Copyright 2015 - Mirantis, Inc.
 # Copyright 2015 - StackStorm, Inc.
 # Copyright 2016 - Nokia Networks.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -15,6 +16,7 @@
 #    limitations under the License.
 
 from oslo_log import log as logging
+from osprofiler import profiler
 import traceback as tb
 
 from mistral.engine import tasks
@@ -30,6 +32,7 @@ from mistral.workflow import states
 LOG = logging.getLogger(__name__)
 
 
+@profiler.trace('task-handler-run-task')
 def run_task(wf_cmd):
     """Runs workflow task.
 
@@ -61,6 +64,7 @@ def run_task(wf_cmd):
         wf_handler.on_task_complete(task.task_ex)
 
 
+@profiler.trace('task-handler-on-task-complete')
 def on_action_complete(action_ex):
     """Handles action completion event.
 

mistral/engine/tasks.py

@@ -1,4 +1,5 @@
 # Copyright 2016 - Nokia Networks.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -16,6 +17,7 @@ import abc
 import copy
 import operator
 from oslo_log import log as logging
+from osprofiler import profiler
 import six
 
 from mistral.db.v2 import api as db_api
@@ -67,6 +69,7 @@ class Task(object):
         """Runs task."""
         raise NotImplementedError
 
+    @profiler.trace('task-defer')
     def defer(self):
         """Defers task.
 
@@ -92,6 +95,7 @@ class Task(object):
     def reset(self):
         self.reset_flag = True
 
+    @profiler.trace('task-set-state')
     def set_state(self, state, state_info, processed=None):
         """Sets task state without executing post completion logic.
 
@@ -114,6 +118,7 @@ class Task(object):
         if processed is not None:
             self.task_ex.processed = processed
 
+    @profiler.trace('task-complete')
     def complete(self, state, state_info=None):
         """Complete task and set specified state.
 
@@ -210,6 +215,7 @@ class RegularTask(Task):
     Takes care of processing regular tasks with one action.
     """
 
+    @profiler.trace('task-on-action-complete')
     def on_action_complete(self, action_ex):
         state = action_ex.state
         # TODO(rakhmerov): Here we can define more informative messages
@@ -223,6 +229,7 @@ class RegularTask(Task):
     def is_completed(self):
         return self.task_ex and states.is_completed(self.task_ex.state)
 
+    @profiler.trace('task-run')
     def run(self):
         if not self.task_ex:
             self._run_new()
@@ -354,6 +361,7 @@ class WithItemsTask(RegularTask):
     Takes care of processing "with-items" tasks.
     """
 
+    @profiler.trace('task-on-action-complete')
     def on_action_complete(self, action_ex):
         assert self.task_ex
 

mistral/engine/workflow_handler.py

@@ -1,4 +1,5 @@
 # Copyright 2016 - Nokia Networks.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -13,6 +14,7 @@
 #    limitations under the License.
 
 from oslo_log import log as logging
+from osprofiler import profiler
 import traceback as tb
 
 from mistral.db.v2 import api as db_api
@@ -25,6 +27,7 @@ from mistral.workflow import states
 LOG = logging.getLogger(__name__)
 
 
+@profiler.trace('workflow-handler-start-workflow')
 def start_workflow(wf_identifier, wf_input, desc, params):
     wf = workflows.Workflow(
         db_api.get_workflow_definition(wf_identifier)
@@ -52,6 +55,7 @@ def fail_workflow(wf_ex, msg=None):
     stop_workflow(wf_ex, states.ERROR, msg)
 
 
+@profiler.trace('workflow-handler-on-task-complete')
 def on_task_complete(task_ex):
     wf_ex = task_ex.workflow_execution
 
@@ -106,6 +110,7 @@ def resume_workflow(wf_ex, env=None):
     wf.resume(env=env)
 
 
+@profiler.trace('workflow-handler-set-state')
 def set_workflow_state(wf_ex, state, msg=None):
     if states.is_completed(state):
         stop_workflow(wf_ex, state, msg)
@@ -117,6 +122,7 @@ def set_workflow_state(wf_ex, state, msg=None):
         )
 
 
+@profiler.trace('workflow-handler-lock-execution')
 def lock_workflow_execution(wf_ex_id):
     # Locks a workflow execution using the db_api.acquire_lock function.
     # The method expires all session objects and returns the up-to-date

mistral/engine/workflows.py

@@ -1,4 +1,5 @@
 # Copyright 2016 - Nokia Networks.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -16,6 +17,7 @@ import abc
 import copy
 from oslo_config import cfg
 from oslo_log import log as logging
+from osprofiler import profiler
 import six
 
 from mistral.db.v2 import api as db_api
@@ -56,6 +58,7 @@ class Workflow(object):
         self.wf_ex = wf_ex
         self.wf_spec = spec_parser.get_workflow_spec(wf_def.spec)
 
+    @profiler.trace('workflow-start')
     def start(self, input_dict, desc='', params=None):
         """Start workflow.
 
@@ -107,6 +110,7 @@ class Workflow(object):
         elif state == states.ERROR:
             return self._fail_workflow(msg)
 
+    @profiler.trace('workflow-on-task-complete')
     def on_task_complete(self, task_ex):
         """Handle task completion event.
 
@@ -148,6 +152,7 @@ class Workflow(object):
 
         self._continue_workflow(task_ex, reset, env=env)
 
+    @profiler.trace('workflow-lock')
     def lock(self):
         assert self.wf_ex
 
@@ -183,6 +188,7 @@ class Workflow(object):
         data_flow.add_environment_to_context(self.wf_ex)
         data_flow.add_workflow_variables_to_context(self.wf_ex, self.wf_spec)
 
+    @profiler.trace('workflow-set-state')
     def set_state(self, state, state_info=None, recursive=False):
         assert self.wf_ex
 

mistral/services/scheduler.py

@@ -1,5 +1,6 @@
 # Copyright 2014 - Mirantis, Inc.
 # Copyright 2015 - StackStorm, Inc.
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -55,7 +56,14 @@ def schedule_call(factory_method_path, target_method_name,
        in mistral/utils/serializer.py
     :param method_args: Target method keyword arguments.
     """
-    ctx = context.ctx().to_dict() if context.has_ctx() else {}
+    ctx_serializer = context.RpcContextSerializer(
+        context.JsonPayloadSerializer()
+    )
+
+    ctx = (
+        ctx_serializer.serialize_context(context.ctx())
+        if context.has_ctx() else {}
+    )
 
     execution_time = (datetime.datetime.now() +
                       datetime.timedelta(seconds=run_after))
@@ -161,12 +169,14 @@ class CallScheduler(periodic_task.PeriodicTasks):
                 (target_auth_context, target_method, method_args)
             )
 
+        ctx_serializer = context.RpcContextSerializer(
+            context.JsonPayloadSerializer()
+        )
+
         for (target_auth_context, target_method, method_args) in delayed_calls:
             try:
                 # Set the correct context for the method.
-                context.set_ctx(
-                    context.MistralContext(target_auth_context)
-                )
+                ctx_serializer.deserialize_context(target_auth_context)
 
                 # Call the method.
                 target_method(**method_args)

mistral/tests/unit/engine/test_profiler.py

@@ -0,0 +1,99 @@
+# Copyright 2016 - Brocade Communications Systems, Inc.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License");
+#    you may not use this file except in compliance with the License.
+#    You may obtain a copy of the License at
+#
+#        http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS,
+#    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#    See the License for the specific language governing permissions and
+#    limitations under the License.
+
+import mock
+import uuid
+
+from oslo_config import cfg
+import osprofiler
+
+from mistral import context
+from mistral.services import workflows as wf_service
+from mistral.tests.unit.engine import base
+from mistral.workflow import states
+
+
+# Use the set_default method to set value otherwise in certain test cases
+# the change in value is not permanent.
+cfg.CONF.set_default('auth_enable', False, group='pecan')
+cfg.CONF.set_default('enabled', True, group='profiler')
+cfg.CONF.set_default('hmac_keys', 'foobar', group='profiler')
+cfg.CONF.set_default('profiler_log_name', 'profile_trace', group='profiler')
+
+
+class EngineProfilerTest(base.EngineTestCase):
+    def setUp(self):
+        super(EngineProfilerTest, self).setUp()
+
+        # Configure the osprofiler.
+        self.mock_profiler_log_func = mock.Mock(return_value=None)
+        osprofiler.notifier.set(self.mock_profiler_log_func)
+
+        self.ctx_serializer = context.RpcContextSerializer(
+            context.JsonPayloadSerializer()
+        )
+
+    def test_profile_trace(self):
+        wf_def = """
+        version: '2.0'
+        wf:
+          type: direct
+          tasks:
+            task1:
+              action: std.echo output="Peace!"
+        """
+
+        wf_service.create_workflows(wf_def)
+
+        ctx = {
+            'trace_info': {
+                'hmac_key': cfg.CONF.profiler.hmac_keys,
+                'base_id': str(uuid.uuid4()),
+                'parent_id': str(uuid.uuid4())
+            }
+        }
+
+        self.ctx_serializer.deserialize_context(ctx)
+
+        wf_ex = self.engine_client.start_workflow('wf', {})
+
+        self.assertIsNotNone(wf_ex)
+        self.assertEqual(states.RUNNING, wf_ex['state'])
+
+        self.await_execution_success(wf_ex['id'])
+
+        self.assertGreater(self.mock_profiler_log_func.call_count, 0)
+
+    def test_no_profile_trace(self):
+        wf_def = """
+        version: '2.0'
+        wf:
+          type: direct
+          tasks:
+            task1:
+              action: std.echo output="Peace!"
+        """
+
+        wf_service.create_workflows(wf_def)
+
+        self.ctx_serializer.deserialize_context({})
+
+        wf_ex = self.engine_client.start_workflow('wf', {})
+
+        self.assertIsNotNone(wf_ex)
+        self.assertEqual(states.RUNNING, wf_ex['state'])
+
+        self.await_execution_success(wf_ex['id'])
+
+        self.assertEqual(self.mock_profiler_log_func.call_count, 0)

mistral/utils/profiler.py

@@ -0,0 +1,54 @@
+# Copyright 2016 - Brocade Communications Systems, Inc.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License");
+#    you may not use this file except in compliance with the License.
+#    You may obtain a copy of the License at
+#
+#        http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS,
+#    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#    See the License for the specific language governing permissions and
+#    limitations under the License.
+
+import copy
+import datetime
+import json
+import six
+
+from oslo_config import cfg
+from oslo_log import log as logging
+import osprofiler.profiler
+import osprofiler.web
+
+
+PROFILER_LOG = logging.getLogger(cfg.CONF.profiler.profiler_log_name)
+
+
+def log_to_file(info, context=None):
+    attrs = [
+        str(info['timestamp']),
+        info['base_id'],
+        info['parent_id'],
+        info['trace_id'],
+        info['name']
+    ]
+
+    if 'info' in info and 'db' in info['info']:
+        db_info = copy.deepcopy(info['info']['db'])
+
+        db_info['params'] = {
+            k: str(v) if isinstance(v, datetime.datetime) else v
+            for k, v in six.iteritems(db_info.get('params', {}))
+        }
+
+        attrs.append(json.dumps(db_info))
+
+    PROFILER_LOG.info(' '.join(attrs))
+
+
+def setup(binary, host):
+    if cfg.CONF.profiler.enabled:
+        osprofiler.notifier.set(log_to_file)
+        osprofiler.web.enable(cfg.CONF.profiler.hmac_keys)

mistral/workflow/base.py

@@ -1,6 +1,7 @@
 # Copyright 2014 - Mirantis, Inc.
 # Copyright 2015 - StackStorm, Inc.
 # Copyright 2015 - Huawei Technologies Co. Ltd
+# Copyright 2016 - Brocade Communications Systems, Inc.
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -18,6 +19,7 @@ import abc
 import copy
 
 from oslo_log import log as logging
+from osprofiler import profiler
 
 from mistral import exceptions as exc
 from mistral import utils as u
@@ -95,6 +97,7 @@ class WorkflowController(object):
 
         return task_ex
 
+    @profiler.trace('workflow-controller-continue-workflow')
     def continue_workflow(self, task_ex=None, reset=True, env=None):
         """Calculates a list of commands to continue the workflow.
 

requirements.txt

@@ -19,6 +19,7 @@ oslo.utils>=3.11.0 # Apache-2.0
 oslo.log>=1.14.0 # Apache-2.0
 oslo.serialization>=1.10.0 # Apache-2.0
 oslo.service>=1.10.0 # Apache-2.0
+osprofiler>=1.3.0 # Apache-2.0
 paramiko>=2.0 # LGPL
 pbr>=1.6 # Apache-2.0
 pecan>=1.0.0 # BSD