Merge pull request #306 from AlanCoding/new_perf_logging

[3.2.2] new method of performance logging

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):

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):

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):

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