From 65e0b7c7d0631fa1999cfb269532d2aa82377b48 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 5 Feb 2019 19:57:24 +0100 Subject: [PATCH 1/4] Add some metric instrumentation to the notifer service code. --- st2actions/st2actions/notifier/notifier.py | 33 +++++++++++++++------- 1 file changed, 23 insertions(+), 10 deletions(-) diff --git a/st2actions/st2actions/notifier/notifier.py b/st2actions/st2actions/notifier/notifier.py index b41fb96d08..1743be3178 100644 --- a/st2actions/st2actions/notifier/notifier.py +++ b/st2actions/st2actions/notifier/notifier.py @@ -14,6 +14,7 @@ # limitations under the License. from __future__ import absolute_import + from datetime import datetime import json @@ -45,6 +46,7 @@ from st2common.constants.keyvalue import FULL_SYSTEM_SCOPE, SYSTEM_SCOPE, DATASTORE_PARENT_SCOPE from st2common.services.keyvalues import KeyValueLookup from st2common.transport.queues import NOTIFIER_ACTIONUPDATE_WORK_QUEUE +from st2common.metrics.base import CounterWithTimer __all__ = [ 'Notifier', @@ -73,6 +75,7 @@ def __init__(self, connection, queues, trigger_dispatcher=None): pack=ACTION_TRIGGER_TYPE['pack'], name=ACTION_TRIGGER_TYPE['name']) + @CounterWithTimer(key='notifier.action.executions') def process(self, execution_db): execution_id = str(execution_db.id) extra = {'execution': execution_db} @@ -86,12 +89,16 @@ def process(self, execution_db): # action execution will be applied by the workflow engine. A policy may affect the # final state of the action execution thereby impacting the state of the workflow. if not workflow_service.is_action_execution_under_workflow_context(execution_db): - policy_service.apply_post_run_policies(liveaction_db) + with CounterWithTimer(key='notifier.apply_post_run_policies'): + policy_service.apply_post_run_policies(liveaction_db) if liveaction_db.notify is not None: - self._post_notify_triggers(liveaction_db=liveaction_db, execution_db=execution_db) + with CounterWithTimer(key='notifier.notify_trigger.post'): + self._post_notify_triggers(liveaction_db=liveaction_db, + execution_db=execution_db) - self._post_generic_trigger(liveaction_db=liveaction_db, execution_db=execution_db) + with CounterWithTimer(key='notifier.generic_trigger.post'): + self._post_generic_trigger(liveaction_db=liveaction_db, execution_db=execution_db) def _get_execution_for_liveaction(self, liveaction): execution = ActionExecution.get(liveaction__id=str(liveaction.id)) @@ -142,13 +149,15 @@ def _post_notify_subsection_triggers(self, liveaction_db=None, execution_db=None ) try: - message = self._transform_message(message=message, - context=jinja_context) + with CounterWithTimer(key='notifier.transform_message'): + message = self._transform_message(message=message, + context=jinja_context) except: LOG.exception('Failed (Jinja) transforming `message`.') try: - data = self._transform_data(data=data, context=jinja_context) + with CounterWithTimer(key='notifier.transform_data'): + data = self._transform_data(data=data, context=jinja_context) except: LOG.exception('Failed (Jinja) transforming `data`.') @@ -187,8 +196,10 @@ def _post_notify_subsection_triggers(self, liveaction_db=None, execution_db=None payload['channel'] = route LOG.debug('POSTing %s for %s. Payload - %s.', NOTIFY_TRIGGER_TYPE['name'], liveaction_db.id, payload) - self._trigger_dispatcher.dispatch(self._notify_trigger, payload=payload, - trace_context=trace_context) + + with CounterWithTimer(key='notifier.notify_trigger.dispatch'): + self._trigger_dispatcher.dispatch(self._notify_trigger, payload=payload, + trace_context=trace_context) except: failed_routes.append(route) @@ -254,8 +265,10 @@ def _post_generic_trigger(self, liveaction_db=None, execution_db=None): trace_context = self._get_trace_context(execution_id=execution_id) LOG.debug('POSTing %s for %s. Payload - %s. TraceContext - %s', ACTION_TRIGGER_TYPE['name'], liveaction_db.id, payload, trace_context) - self._trigger_dispatcher.dispatch(self._action_trigger, payload=payload, - trace_context=trace_context) + + with CounterWithTimer(key='notifier.generic_trigger.dispatch'): + self._trigger_dispatcher.dispatch(self._action_trigger, payload=payload, + trace_context=trace_context) def _get_runner_ref(self, action_ref): """ From b04847257dd72262303c9bec6ac1f930d487923f Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 5 Feb 2019 20:03:30 +0100 Subject: [PATCH 2/4] Don't submit metric if we don't post generic notify trigger so we don't have useless / confusing data (aka those functions will complete immediately). --- st2actions/st2actions/notifier/notifier.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/st2actions/st2actions/notifier/notifier.py b/st2actions/st2actions/notifier/notifier.py index 1743be3178..c626a67d13 100644 --- a/st2actions/st2actions/notifier/notifier.py +++ b/st2actions/st2actions/notifier/notifier.py @@ -92,13 +92,15 @@ def process(self, execution_db): with CounterWithTimer(key='notifier.apply_post_run_policies'): policy_service.apply_post_run_policies(liveaction_db) - if liveaction_db.notify is not None: + if liveaction_db.notify: with CounterWithTimer(key='notifier.notify_trigger.post'): self._post_notify_triggers(liveaction_db=liveaction_db, execution_db=execution_db) - with CounterWithTimer(key='notifier.generic_trigger.post'): - self._post_generic_trigger(liveaction_db=liveaction_db, execution_db=execution_db) + if cfg.CONF.action_sensor.enable: + with CounterWithTimer(key='notifier.generic_trigger.post'): + self._post_generic_trigger(liveaction_db=liveaction_db, + execution_db=execution_db) def _get_execution_for_liveaction(self, liveaction): execution = ActionExecution.get(liveaction__id=str(liveaction.id)) From a1be3c985ecc6824a90d8c0db7ab1d6dd0ec5c65 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Wed, 6 Feb 2019 09:40:25 +0100 Subject: [PATCH 3/4] Add changelog entry. --- CHANGELOG.rst | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 9d2aee0cd8..240fb55d86 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -17,6 +17,8 @@ Added For backward compatibility reasons, if pack metadata file doesn't contain that attribute, it's assumed it only works with Python 2. (new feature) #4474 +* Add metrics instrumentation to the ``st2notifier`` service. For the available / exposed metrics, + please refer to https://docs.stackstorm.com/reference/metrics.html. (improvement) #4536 Changed ~~~~~~~ From 89238c3300370b3fb38ef2084187b558f2b76586 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Wed, 6 Feb 2019 10:01:25 +0100 Subject: [PATCH 4/4] In those cases we are only interested in timing information. --- st2actions/st2actions/notifier/notifier.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/st2actions/st2actions/notifier/notifier.py b/st2actions/st2actions/notifier/notifier.py index c626a67d13..16128622ee 100644 --- a/st2actions/st2actions/notifier/notifier.py +++ b/st2actions/st2actions/notifier/notifier.py @@ -47,6 +47,7 @@ from st2common.services.keyvalues import KeyValueLookup from st2common.transport.queues import NOTIFIER_ACTIONUPDATE_WORK_QUEUE from st2common.metrics.base import CounterWithTimer +from st2common.metrics.base import Timer __all__ = [ 'Notifier', @@ -136,7 +137,7 @@ def _post_notify_subsection_triggers(self, liveaction_db=None, execution_db=None notify_subsection=None, default_message_suffix=None): routes = (getattr(notify_subsection, 'routes') or - getattr(notify_subsection, 'channels', None)) + getattr(notify_subsection, 'channels', [])) or [] execution_id = str(execution_db.id) @@ -151,14 +152,14 @@ def _post_notify_subsection_triggers(self, liveaction_db=None, execution_db=None ) try: - with CounterWithTimer(key='notifier.transform_message'): + with Timer(key='notifier.transform_message'): message = self._transform_message(message=message, context=jinja_context) except: LOG.exception('Failed (Jinja) transforming `message`.') try: - with CounterWithTimer(key='notifier.transform_data'): + with Timer(key='notifier.transform_data'): data = self._transform_data(data=data, context=jinja_context) except: LOG.exception('Failed (Jinja) transforming `data`.')