Add additional timer metrics to the action runner which will provide
better operational visibility into some steps of the action runner.
@@ -36,6 +36,7 @@ from st2common.util.action_db import update_liveaction_status, get_liveaction_by
from st2common.util import param as param_utils
from st2common.util.config_loader import ContentPackConfigLoader
from st2common.metrics.base import CounterWithTimer
+from st2common.metrics.base import Timer
from st2common.util import jsonify
from st2common.runners.base import get_runner
@@ -83,6 +84,8 @@ class RunnerContainer(object):
)
with CounterWithTimer(key="action.executions"):
+ status = liveaction_db.status
+ with CounterWithTimer(key="action.executions.process.%s" % (status)):
liveaction_db = funcs[liveaction_db.status](runner)
return liveaction_db.result
@@ -155,6 +158,7 @@ class RunnerContainer(object):
LOG.debug('Action "%s" completed.' % (runner.action.name), extra=extra)
# Update the final status of liveaction and corresponding action execution.
+ with Timer(key="action.executions.update_status"):
runner.liveaction = self._update_status(
runner.liveaction.id, status, result, context
)
@@ -322,6 +326,7 @@ class RunnerContainer(object):
else:
end_timestamp = None
+ with Timer(key="action.executions.update_liveaction_db"):
liveaction_db = update_liveaction_status(
status=status if state_changed else liveaction_db.status,
result=result,
@@ -333,6 +338,7 @@ class RunnerContainer(object):
return (liveaction_db, state_changed)
def _update_status(self, liveaction_id, status, result, context):
+ with Timer(key="action.executions.update_liveaction_db"):
try:
# NOTE: The next two operations take a very long time in master with large executions
# (long standing issue), but because start_timestamp and end_timestamp measure how long
@@ -354,19 +360,23 @@ class RunnerContainer(object):
# and users, we update "end_timestamp" on each object again after both of them have
# already been written. That atomic single field update is very fast and adds no
# additional overhead.
- LOG.debug("Setting status: %s for liveaction: %s", status, liveaction_id)
+ LOG.debug(
+ "Setting status: %s for liveaction: %s", status, liveaction_id
+ )
liveaction_db, state_changed = self._update_live_action_db(
liveaction_id, status, result, context
)
except Exception as e:
LOG.exception(
"Cannot update liveaction "
- "(id: %s, status: %s, result: %s)." % (liveaction_id, status, result)
+ "(id: %s, status: %s, result: %s)."
+ % (liveaction_id, status, result)
)
raise e
live_action_written_to_db_dt = date_utils.get_datetime_utc_now()
+ with Timer(key="action.executions.update_execution_db"):
try:
execution_db = executions.update_execution(
liveaction_db, publish=state_changed
@@ -376,7 +386,8 @@ class RunnerContainer(object):
except Exception as e:
LOG.exception(
"Cannot update action execution for liveaction "
- "(id: %s, status: %s, result: %s)." % (liveaction_id, status, result)
+ "(id: %s, status: %s, result: %s)."
+ % (liveaction_id, status, result)
)
raise e
