[enh] Add Server-Timing header (#1637)

Server Timing specification: https://www.w3.org/TR/server-timing/

In the browser Dev Tools, focus on the main request, there are the responses per engine in the Timing tab.

Author: dalf

searx/results.py

@@ -136,6 +136,7 @@ def __init__(self):
         self._ordered = False
         self.paging = False
         self.unresponsive_engines = set()
+        self.timings = []
 
     def extend(self, engine_name, results):
         for result in list(results):
@@ -319,3 +320,13 @@ def results_number(self):
 
     def add_unresponsive_engine(self, engine_error):
         self.unresponsive_engines.add(engine_error)
+
+    def add_timing(self, engine_name, engine_time, page_load_time):
+        self.timings.append({
+            'engine': engines[engine_name].shortcut,
+            'total': engine_time,
+            'load': page_load_time
+        })
+
+    def get_timings(self):
+        return self.timings

searx/search.py

@@ -74,10 +74,10 @@ def search_one_request(engine, query, request_params):
 
     # ignoring empty urls
     if request_params['url'] is None:
-        return []
+        return None
 
     if not request_params['url']:
-        return []
+        return None
 
     # send request
     response = send_http_request(engine, request_params)
@@ -103,20 +103,29 @@ def search_one_request_safe(engine_name, query, request_params, result_container
         # send requests and parse the results
         search_results = search_one_request(engine, query, request_params)
 
-        # add results
-        result_container.extend(engine_name, search_results)
-
-        # update engine time when there is no exception
-        with threading.RLock():
-            engine.stats['engine_time'] += time() - start_time
-            engine.stats['engine_time_count'] += 1
-            # update stats with the total HTTP time
-            engine.stats['page_load_time'] += requests_lib.get_time_for_thread()
-            engine.stats['page_load_count'] += 1
+        # check if the engine accepted the request
+        if search_results is not None:
+            # yes, so add results
+            result_container.extend(engine_name, search_results)
+
+            # update engine time when there is no exception
+            engine_time = time() - start_time
+            page_load_time = requests_lib.get_time_for_thread()
+            result_container.add_timing(engine_name, engine_time, page_load_time)
+            with threading.RLock():
+                engine.stats['engine_time'] += engine_time
+                engine.stats['engine_time_count'] += 1
+                # update stats with the total HTTP time
+                engine.stats['page_load_time'] += page_load_time
+                engine.stats['page_load_count'] += 1
 
     except Exception as e:
-        search_duration = time() - start_time
+        # Timing
+        engine_time = time() - start_time
+        page_load_time = requests_lib.get_time_for_thread()
+        result_container.add_timing(engine_name, engine_time, page_load_time)
 
+        # Record the errors
         with threading.RLock():
             engine.stats['errors'] += 1
 
@@ -125,14 +134,14 @@ def search_one_request_safe(engine_name, query, request_params, result_container
             # requests timeout (connect or read)
             logger.error("engine {0} : HTTP requests timeout"
                          "(search duration : {1} s, timeout: {2} s) : {3}"
-                         .format(engine_name, search_duration, timeout_limit, e.__class__.__name__))
+                         .format(engine_name, engine_time, timeout_limit, e.__class__.__name__))
             requests_exception = True
         elif (issubclass(e.__class__, requests.exceptions.RequestException)):
             result_container.add_unresponsive_engine((engine_name, gettext('request exception')))
             # other requests exception
             logger.exception("engine {0} : requests exception"
                              "(search duration : {1} s, timeout: {2} s) : {3}"
-                             .format(engine_name, search_duration, timeout_limit, e))
+                             .format(engine_name, engine_time, timeout_limit, e))
             requests_exception = True
         else:
             result_container.add_unresponsive_engine((

searx/webapp.py

@@ -43,6 +43,7 @@
     exit(1)
 from cgi import escape
 from datetime import datetime, timedelta
+from time import time
 from werkzeug.contrib.fixers import ProxyFix
 from flask import (
     Flask, request, render_template, url_for, Response, make_response,
@@ -402,6 +403,8 @@ def render(template_name, override_theme=None, **kwargs):
 
 @app.before_request
 def pre_request():
+    request.start_time = time()
+    request.timings = []
     request.errors = []
 
     preferences = Preferences(themes, list(categories.keys()), engines, plugins)
@@ -437,6 +440,21 @@ def pre_request():
             request.user_plugins.append(plugin)
 
 
+@app.after_request
+def post_request(response):
+    total_time = time() - request.start_time
+    timings_all = ['total;dur=' + str(round(total_time * 1000, 3))]
+    if len(request.timings) > 0:
+        timings = sorted(request.timings, key=lambda v: v['total'])
+        timings_total = ['total_' + str(i) + '_' + v['engine'] +
+                         ';dur=' + str(round(v['total'] * 1000, 3)) for i, v in enumerate(timings)]
+        timings_load = ['load_' + str(i) + '_' + v['engine'] +
+                        ';dur=' + str(round(v['load'] * 1000, 3)) for i, v in enumerate(timings)]
+        timings_all = timings_all + timings_total + timings_load
+    response.headers.add('Server-Timing', ', '.join(timings_all))
+    return response
+
+
 def index_error(output_format, error_message):
     if output_format == 'json':
         return Response(json.dumps({'error': error_message}),
@@ -515,6 +533,9 @@ def index():
     # UI
     advanced_search = request.form.get('advanced_search', None)
 
+    # Server-Timing header
+    request.timings = result_container.get_timings()
+
     # output
     for result in results:
         if output_format == 'html':

tests/unit/test_webapp.py

@@ -33,6 +33,19 @@ def setUp(self):
             },
         ]
 
+        timings = [
+            {
+                'engine': 'startpage',
+                'total': 0.8,
+                'load': 0.7
+            },
+            {
+                'engine': 'youtube',
+                'total': 0.9,
+                'load': 0.6
+            }
+        ]
+
         def search_mock(search_self, *args):
             search_self.result_container = Mock(get_ordered_results=lambda: self.test_results,
                                                 answers=set(),
@@ -42,7 +55,8 @@ def search_mock(search_self, *args):
                                                 unresponsive_engines=set(),
                                                 results=self.test_results,
                                                 results_number=lambda: 3,
-                                                results_length=lambda: len(self.test_results))
+                                                results_length=lambda: len(self.test_results),
+                                                get_timings=lambda: timings)
 
         Search.search = search_mock