From 45ac6d03b1298d150a26b9a774fd8e9093229393 Mon Sep 17 00:00:00 2001 From: Winson Chan Date: Fri, 10 Jun 2016 01:49:38 +0000 Subject: [PATCH] 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 | 21 ++++- etc/wf_trace_logging.conf.sample.rotating | 21 ++++- mistral/api/app.py | 12 ++- mistral/cmd/launch.py | 7 +- mistral/config.py | 16 +++- mistral/context.py | 21 ++++- mistral/db/sqlalchemy/base.py | 12 ++- mistral/engine/action_handler.py | 3 + mistral/engine/actions.py | 8 ++ mistral/engine/default_engine.py | 4 + mistral/engine/default_executor.py | 5 +- mistral/engine/dispatcher.py | 3 + mistral/engine/task_handler.py | 4 + mistral/engine/tasks.py | 8 ++ mistral/engine/workflow_handler.py | 6 ++ mistral/engine/workflows.py | 6 ++ mistral/services/scheduler.py | 18 +++- mistral/tests/unit/engine/test_profiler.py | 99 ++++++++++++++++++++++ mistral/utils/profiler.py | 54 ++++++++++++ mistral/workflow/base.py | 3 + requirements.txt | 1 + 21 files changed, 311 insertions(+), 21 deletions(-) create mode 100644 mistral/tests/unit/engine/test_profiler.py create mode 100644 mistral/utils/profiler.py diff --git a/etc/wf_trace_logging.conf.sample b/etc/wf_trace_logging.conf.sample index 9b02596d5..8ce8c9fd1 100644 --- a/etc/wf_trace_logging.conf.sample +++ b/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= diff --git a/etc/wf_trace_logging.conf.sample.rotating b/etc/wf_trace_logging.conf.sample.rotating index 6f4e38030..8c2730606 100644 --- a/etc/wf_trace_logging.conf.sample.rotating +++ b/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= diff --git a/mistral/api/app.py b/mistral/api/app.py index 16592ab91..0511599aa 100644 --- a/mistral/api/app.py +++ b/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) diff --git a/mistral/cmd/launch.py b/mistral/cmd/launch.py index 571c2cc74..a041b2a3f 100644 --- a/mistral/cmd/launch.py +++ b/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 diff --git a/mistral/config.py b/mistral/config.py index 6c61305ec..1e4909c3b 100644 --- a/mistral/config.py +++ b/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, [ diff --git a/mistral/context.py b/mistral/context.py index c404fb9b4..80d23641b 100644 --- a/mistral/context.py +++ b/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) diff --git a/mistral/db/sqlalchemy/base.py b/mistral/db/sqlalchemy/base.py index 16743a6ad..50b1ed7cc 100644 --- a/mistral/db/sqlalchemy/base.py +++ b/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 diff --git a/mistral/engine/action_handler.py b/mistral/engine/action_handler.py index 118722fad..94bdc0e8d 100644 --- a/mistral/engine/action_handler.py +++ b/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 diff --git a/mistral/engine/actions.py b/mistral/engine/actions.py index a0ac9f91d..21fe1bbd1 100644 --- a/mistral/engine/actions.py +++ b/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.') diff --git a/mistral/engine/default_engine.py b/mistral/engine/default_engine.py index 3a9cc0f90..053489b86 100644 --- a/mistral/engine/default_engine.py +++ b/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) diff --git a/mistral/engine/default_executor.py b/mistral/engine/default_executor.py index 6ec244573..3fe1039de 100644 --- a/mistral/engine/default_executor.py +++ b/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. diff --git a/mistral/engine/dispatcher.py b/mistral/engine/dispatcher.py index 778cb64e9..d5bed6521 100644 --- a/mistral/engine/dispatcher.py +++ b/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. diff --git a/mistral/engine/task_handler.py b/mistral/engine/task_handler.py index b61ef0a22..246f4206b 100644 --- a/mistral/engine/task_handler.py +++ b/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. diff --git a/mistral/engine/tasks.py b/mistral/engine/tasks.py index 9db70d5aa..bcd54a48d 100644 --- a/mistral/engine/tasks.py +++ b/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 diff --git a/mistral/engine/workflow_handler.py b/mistral/engine/workflow_handler.py index 06c8e2c70..9d3e05e85 100644 --- a/mistral/engine/workflow_handler.py +++ b/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 diff --git a/mistral/engine/workflows.py b/mistral/engine/workflows.py index 76e866a9c..65f4f2c04 100644 --- a/mistral/engine/workflows.py +++ b/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 diff --git a/mistral/services/scheduler.py b/mistral/services/scheduler.py index e2be7ce68..6bc56021f 100644 --- a/mistral/services/scheduler.py +++ b/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) diff --git a/mistral/tests/unit/engine/test_profiler.py b/mistral/tests/unit/engine/test_profiler.py new file mode 100644 index 000000000..eb79be622 --- /dev/null +++ b/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) diff --git a/mistral/utils/profiler.py b/mistral/utils/profiler.py new file mode 100644 index 000000000..6b9360e51 --- /dev/null +++ b/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) diff --git a/mistral/workflow/base.py b/mistral/workflow/base.py index 46a770d0c..66f53fdba 100644 --- a/mistral/workflow/base.py +++ b/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. diff --git a/requirements.txt b/requirements.txt index 65d94c8fe..394214f2a 100644 --- a/requirements.txt +++ b/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