[#3196] Add request timer for Flask requests

Times between before_request and after_request and outputs to log level
info

ckan/config/middleware/flask_app.py

@@ -1,6 +1,7 @@
 # encoding: utf-8
 
 import os
+import time
 import importlib
 import inspect
 import itertools
@@ -18,7 +19,7 @@
 
 from ckan.lib import helpers
 from ckan.lib import jinja_extensions
-from ckan.common import config, g
+from ckan.common import config, g, request
 import ckan.lib.app_globals as app_globals
 from ckan.plugins import PluginImplementations
 from ckan.plugins.interfaces import IBlueprint
@@ -89,6 +90,9 @@ def make_flask_stack(conf, **app_conf):
     # Common handlers for all requests
     @app.before_request
     def ckan_before_request():
+        # Start the request timer
+        g._request_timer = time.time()
+
         # Identify the user from the repoze cookie or the API header
         # Sets g.user and g.userobj
         identify_user()
@@ -97,6 +101,15 @@ def ckan_before_request():
     def ckan_after_request(response):
         # Set CORS headers if necessary
         set_cors_headers_for_response(response)
+
+        # Log time between before and after view
+        request_time = time.time() - g._request_timer
+        url = request.environ.get('CKAN_CURRENT_URL')
+        if url:
+            url = url.split('?')[0]
+            log.info('{url} render time {request_time:.3f} seconds'.format(
+                url=url, request_time=request_time))
+
         return response
 
     # Template context processors