Add middleware to report response time (and number of queries)

InvenTree/InvenTree/middleware.py

@@ -2,6 +2,7 @@ from django.shortcuts import HttpResponseRedirect
 from django.urls import reverse_lazy
 from django.db import connection
 import logging
+import time
 
 logger = logging.getLogger(__name__)
 
@@ -45,7 +46,9 @@ class QueryCountMiddleware(object):
 
     def __call__(self, request):
 
+        t_start = time.time()
         response = self.get_response(request)
+        t_stop = time.time()
 
         if response.status_code == 200:
             total_time = 0
@@ -54,14 +57,20 @@ class QueryCountMiddleware(object):
 
                 for query in connection.queries:
                     query_time = query.get('time')
+
                     if query_time is None:
                         # django-debug-toolbar monkeypatches the connection
                         # cursor wrapper and adds extra information in each
                         # item in connection.queries. The query time is stored
                         # under the key "duration" rather than "time" and is
                         # in milliseconds, not seconds.
-                        query_time = query.get('duration', 0) / 1000
+                        query_time = float(query.get('duration', 0))
+
                     total_time += float(query_time)
 
-                logger.debug('%s queries run, total %s seconds' % (len(connection.queries), total_time))
+                logger.debug('{n} queries run, {a:.3f}s / {b:.3f}s'.format(
+                    n=len(connection.queries),
+                    a=total_time,
+                    b=(t_stop - t_start)))
+                    
         return response

InvenTree/InvenTree/settings.py

@@ -67,13 +67,38 @@ INSTALLED_APPS = [
     'django_filters',       # Extended filter functionality
     'dbbackup',             # Database backup / restore
     'rest_framework',       # DRF (Django Rest Framework)
-    'corsheaders',         # Cross-origin Resource Sharing for DRF
+    'corsheaders',          # Cross-origin Resource Sharing for DRF
     'crispy_forms',         # Improved form rendering
     'import_export',        # Import / export tables to file
     'django_cleanup',       # Automatically delete orphaned MEDIA files
     'qr_code',              # Generate QR codes
 ]
 
+LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'handlers': {
+        'console': {
+            'level': 'DEBUG',
+            'class': 'logging.StreamHandler',
+        },
+        'file': {
+            'level': 'DEBUG',
+            'class': 'logging.FileHandler',
+            'filename': './debug.log',
+        },
+    },
+
+    'loggers': {
+        'ddjango.db.backends': {
+            'level': 'DEBUG',
+            'handlers': ['file'],
+            'propagate': True
+        },
+    },
+}
+
+
 MIDDLEWARE = [
     'django.middleware.security.SecurityMiddleware',
     'django.contrib.sessions.middleware.SessionMiddleware',
@@ -83,7 +108,8 @@ MIDDLEWARE = [
     'django.contrib.auth.middleware.AuthenticationMiddleware',
     'django.contrib.messages.middleware.MessageMiddleware',
     'django.middleware.clickjacking.XFrameOptionsMiddleware',
-    'InvenTree.middleware.AuthRequiredMiddleware'
+    'InvenTree.middleware.AuthRequiredMiddleware',
+    'InvenTree.middleware.QueryCountMiddleware',
 ]
 
 if DEBUG: