diff --git a/awx/main/dispatch/pool.py b/awx/main/dispatch/pool.py index 16366c3e0c6c..8830a69af813 100644 --- a/awx/main/dispatch/pool.py +++ b/awx/main/dispatch/pool.py @@ -21,9 +21,11 @@ from jinja2 import Template import psutil +from ansible_base.lib.logging.runtime import log_excess_runtime + from awx.main.models import UnifiedJob from awx.main.dispatch import reaper -from awx.main.utils.common import convert_mem_str_to_bytes, get_mem_effective_capacity, log_excess_runtime +from awx.main.utils.common import convert_mem_str_to_bytes, get_mem_effective_capacity if 'run_callback_receiver' in sys.argv: logger = logging.getLogger('awx.main.commands.run_callback_receiver') @@ -366,7 +368,7 @@ def full(self): def debug_meta(self): return 'min={} max={}'.format(self.min_workers, self.max_workers) - @log_excess_runtime(logger) + @log_excess_runtime(logger, debug_cutoff=0.05, cutoff=0.2) def cleanup(self): """ Perform some internal account and cleanup. This is run on diff --git a/awx/main/dispatch/worker/base.py b/awx/main/dispatch/worker/base.py index 264205a8ed6d..9547edf15fd2 100644 --- a/awx/main/dispatch/worker/base.py +++ b/awx/main/dispatch/worker/base.py @@ -16,10 +16,11 @@ from django import db from django.conf import settings +from ansible_base.lib.logging.runtime import log_excess_runtime + from awx.main.dispatch.pool import WorkerPool from awx.main.dispatch.periodic import Scheduler from awx.main.dispatch import pg_bus_conn -from awx.main.utils.common import log_excess_runtime from awx.main.utils.db import set_connection_name import awx.main.analytics.subsystem_metrics as s_metrics @@ -126,7 +127,7 @@ def process_task(self, body): return self.dispatch_task(body) - @log_excess_runtime(logger) + @log_excess_runtime(logger, debug_cutoff=0.05, cutoff=0.2) def record_statistics(self): if time.time() - self.last_stats > 1: # buffer stat recording to once per second try: @@ -183,6 +184,7 @@ def __init__(self, *args, schedule=None, **kwargs): schedule['metrics_gather'] = {'control': self.record_metrics, 'schedule': timedelta(seconds=20)} self.scheduler = Scheduler(schedule) + @log_excess_runtime(logger, debug_cutoff=0.05, cutoff=0.2) def record_metrics(self): current_time = time.time() self.pool.produce_subsystem_metrics(self.subsystem_metrics) diff --git a/awx/main/tasks/facts.py b/awx/main/tasks/facts.py index c72dc0d3a67d..0ddba205c683 100644 --- a/awx/main/tasks/facts.py +++ b/awx/main/tasks/facts.py @@ -11,8 +11,10 @@ from django.utils.timezone import now from django.db import OperationalError +# django-ansible-base +from ansible_base.lib.logging.runtime import log_excess_runtime + # AWX -from awx.main.utils.common import log_excess_runtime from awx.main.models.inventory import Host diff --git a/awx/main/utils/common.py b/awx/main/utils/common.py index 8b482f6ed057..2e517952e510 100644 --- a/awx/main/utils/common.py +++ b/awx/main/utils/common.py @@ -6,7 +6,6 @@ import json import yaml import logging -import time import psycopg import os import subprocess @@ -89,7 +88,6 @@ 'deepmerge', 'get_event_partition_epoch', 'cleanup_new_process', - 'log_excess_runtime', 'unified_job_class_to_event_table_name', ] @@ -1215,36 +1213,5 @@ def wrapper_cleanup_new_process(*args, **kwargs): return wrapper_cleanup_new_process -def log_excess_runtime(func_logger, cutoff=5.0, debug_cutoff=5.0, msg=None, add_log_data=False): - def log_excess_runtime_decorator(func): - @functools.wraps(func) - def _new_func(*args, **kwargs): - start_time = time.time() - log_data = {'name': repr(func.__name__)} - - if add_log_data: - return_value = func(*args, log_data=log_data, **kwargs) - else: - return_value = func(*args, **kwargs) - - log_data['delta'] = time.time() - start_time - if isinstance(return_value, dict): - log_data.update(return_value) - - if msg is None: - record_msg = 'Running {name} took {delta:.2f}s' - else: - record_msg = msg - if log_data['delta'] > cutoff: - func_logger.info(record_msg.format(**log_data)) - elif log_data['delta'] > debug_cutoff: - func_logger.debug(record_msg.format(**log_data)) - return return_value - - return _new_func - - return log_excess_runtime_decorator - - def unified_job_class_to_event_table_name(job_class): return f'main_{job_class().event_class.__name__.lower()}'