diff --git a/awx/api/generics.py b/awx/api/generics.py index d2d7f0ff40..36176016b0 100644 --- a/awx/api/generics.py +++ b/awx/api/generics.py @@ -139,7 +139,6 @@ class APIView(views.APIView): response['X-API-Query-Count'] = len(q_times) response['X-API-Query-Time'] = '%0.3fs' % sum(q_times) - analytics_logger.info("api response", extra=dict(python_objects=dict(request=request, response=response))) return response def get_authenticate_header(self, request): diff --git a/awx/main/middleware.py b/awx/main/middleware.py index dfb08b20fb..0c71eeed92 100644 --- a/awx/main/middleware.py +++ b/awx/main/middleware.py @@ -5,6 +5,10 @@ import logging import threading import uuid import six +import time +import cProfile +import pstats +import os from django.conf import settings from django.contrib.auth.models import User @@ -23,6 +27,38 @@ from awx.conf import fields, register logger = logging.getLogger('awx.main.middleware') analytics_logger = logging.getLogger('awx.analytics.activity_stream') +perf_logger = logging.getLogger('awx.analytics.performance') + + +class TimingMiddleware(threading.local): + + dest = '/var/lib/awx/profile' + + def process_request(self, request): + self.start_time = time.time() + if settings.AWX_REQUEST_PROFILE: + self.prof = cProfile.Profile() + self.prof.enable() + + def process_response(self, request, response): + total_time = time.time() - self.start_time + response['X-API-Total-Time'] = '%0.3fs' % total_time + if settings.AWX_REQUEST_PROFILE: + self.prof.disable() + cprofile_file = self.save_profile_file(request) + response['cprofile_file'] = cprofile_file + perf_logger.info('api response times', extra=dict(python_objects=dict(request=request, response=response))) + return response + + def save_profile_file(self, request): + if not os.path.isdir(self.dest): + os.makedirs(self.dest) + filename = '%.3fs-%s' % (pstats.Stats(self.prof).total_tt, uuid.uuid4()) + filepath = os.path.join(self.dest, filename) + with open(filepath, 'w') as f: + f.write('%s %s\n' % (request.method, request.get_full_path())) + pstats.Stats(self.prof, stream=f).sort_stats('cumulative').print_stats() + return filepath class ActivityStreamMiddleware(threading.local): diff --git a/awx/main/utils/formatters.py b/awx/main/utils/formatters.py index 12034dd5ea..380641fdf9 100644 --- a/awx/main/utils/formatters.py +++ b/awx/main/utils/formatters.py @@ -120,6 +120,7 @@ class LogstashFormatter(LogstashFormatterVersion1): # exist if SQL_DEBUG is turned on in settings. headers = [ (float, 'X-API-Time'), # may end with an 's' "0.33s" + (float, 'X-API-Total-Time'), (int, 'X-API-Query-Count'), (float, 'X-API-Query-Time'), # may also end with an 's' (str, 'X-API-Node'), @@ -131,9 +132,11 @@ class LogstashFormatter(LogstashFormatterVersion1): 'path': request.path, 'path_info': request.path_info, 'query_string': request.META['QUERY_STRING'], - 'data': request.data, } + if hasattr(request, 'data'): + data_for_log['request']['data'] = request.data + return data_for_log def get_extra_fields(self, record): diff --git a/awx/settings/defaults.py b/awx/settings/defaults.py index c1d6a053c9..9f25ddb525 100644 --- a/awx/settings/defaults.py +++ b/awx/settings/defaults.py @@ -211,6 +211,7 @@ TEMPLATE_CONTEXT_PROCESSORS = ( # NOQA ) MIDDLEWARE_CLASSES = ( # NOQA + 'awx.main.middleware.TimingMiddleware', 'django.contrib.sessions.middleware.SessionMiddleware', 'django.middleware.locale.LocaleMiddleware', 'django.middleware.common.CommonMiddleware', @@ -1134,4 +1135,8 @@ LOGGING = { }, } } +# Apply coloring to messages logged to the console COLOR_LOGS = False + +# Use middleware to get request statistics +AWX_REQUEST_PROFILE = False