[IMP] http,server: add query count and request times in logs

When there is a performance issue, it's sometimes difficult to discover
which request increased the query count or its duration.

With this commit, the query count, the query time and "python and io" time are displayed
in the logs at the end of each werkzeug request line.

Co-authored-by: Christophe Monniez <moc@odoo.com>

3 files changed, 52 insertions, 6 deletions

diff --git a/odoo/http.py b/odoo/http.py
index 5ecb6a0c211..3ae800cc71b 100644
--- a/odoo/http.py
+++ b/odoo/http.py
@@ -1438,6 +1438,9 @@ class Root(object):
             httprequest.app = self
             httprequest.parameter_storage_class = werkzeug.datastructures.ImmutableOrderedMultiDict
             threading.current_thread().url = httprequest.url
+            threading.current_thread().query_count = 0
+            threading.current_thread().query_time = 0
+            threading.current_thread().perf_t0 = time.time()
 
             explicit_session = self.setup_session(httprequest)
             self.setup_db(httprequest)
diff --git a/odoo/netsvc.py b/odoo/netsvc.py
index c8d9dbb6441..f344ec28048 100644
--- a/odoo/netsvc.py
+++ b/odoo/netsvc.py
@@ -9,6 +9,7 @@ import pprint
 from . import release
 import sys
 import threading
+import time
 
 import psycopg2
 
@@ -69,10 +70,40 @@ LEVEL_COLOR_MAPPING = {
     logging.CRITICAL: (WHITE, RED),
 }
 
+class PerfFilter(logging.Filter):
+    def format_perf(self, query_count, query_time, remaining_time):
+        return ("%d" % query_count, "%.3f" % query_time, "%.3f" % remaining_time)
+
+    def filter(self, record):
+        if hasattr(threading.current_thread(), "query_count"):
+            query_count = threading.current_thread().query_count
+            query_time = threading.current_thread().query_time
+            perf_t0 = threading.current_thread().perf_t0
+            remaining_time = time.time() - perf_t0 - query_time
+            record.perf_info = '%s %s %s' % self.format_perf(query_count, query_time, remaining_time)
+            delattr(threading.current_thread(), "query_count")
+        else:
+            record.perf_info = "- - -"
+        return True
+
+class ColoredPerfFilter(PerfFilter):
+    def format_perf(self, query_count, query_time, remaining_time):
+        def colorize_time(time, format, low=1, high=5):
+            if time > high:
+                return COLOR_PATTERN % (30 + RED, 40 + DEFAULT, format % time)
+            if time > low:
+                return COLOR_PATTERN % (30 + YELLOW, 40 + DEFAULT, format % time)
+            return format % time
+        return (
+            colorize_time(query_time, "%.3f", 100, 1000),
+            colorize_time(query_time, "%.3f", 0.1, 3),
+            colorize_time(remaining_time, "%.3f", 1, 5)
+            )
+
 class DBFormatter(logging.Formatter):
     def format(self, record):
         record.pid = os.getpid()
-        record.dbname = getattr(threading.currentThread(), 'dbname', '?')
+        record.dbname = getattr(threading.current_thread(), 'dbname', '?')
         return logging.Formatter.format(self, record)
 
 class ColoredFormatter(DBFormatter):
@@ -88,6 +119,13 @@ def init_logger():
         return
     _logger_init = True
 
+    old_factory = logging.getLogRecordFactory()
+    def record_factory(*args, **kwargs):
+        record = old_factory(*args, **kwargs)
+        record.perf_info = ""
+        return record
+    logging.setLogRecordFactory(record_factory)
+
     logging.addLevelName(25, "INFO")
     logging.captureWarnings(True)
 
@@ -95,7 +133,7 @@ def init_logger():
     resetlocale()
 
     # create a format for log messages and dates
-    format = '%(asctime)s %(pid)s %(levelname)s %(dbname)s %(name)s: %(message)s'
+    format = '%(asctime)s %(pid)s %(levelname)s %(dbname)s %(name)s: %(message)s %(perf_info)s'
     # Normal Handler on stderr
     handler = logging.StreamHandler()
 
@@ -143,11 +181,13 @@ def init_logger():
 
     if os.name == 'posix' and isinstance(handler, logging.StreamHandler) and is_a_tty(handler.stream):
         formatter = ColoredFormatter(format)
+        perf_filter = ColoredPerfFilter()
     else:
         formatter = DBFormatter(format)
+        perf_filter = PerfFilter()
     handler.setFormatter(formatter)
-
     logging.getLogger().addHandler(handler)
+    logging.getLogger('werkzeug').addFilter(perf_filter)
 
     if tools.config['log_db']:
         db_levels = {
diff --git a/odoo/sql_db.py b/odoo/sql_db.py
index ae1db0d6436..afa396148f0 100644
--- a/odoo/sql_db.py
+++ b/odoo/sql_db.py
@@ -217,10 +217,9 @@ class Cursor(object):
             raise ValueError("SQL query parameters should be a tuple, list or dict; got %r" % (params,))
 
         if self.sql_log:
-            now = time.time()
             encoding = psycopg2.extensions.encodings[self.connection.encoding]
             _logger.debug("query: %s", self._obj.mogrify(query, params).decode(encoding, 'replace'))
-
+        now = time.time()
         try:
             params = params or None
             res = self._obj.execute(query, params)
@@ -231,10 +230,14 @@ class Cursor(object):
 
         # simple query count is always computed
         self.sql_log_count += 1
+        delay = (time.time() - now)
+        if hasattr(threading.current_thread(), 'query_count'):
+            threading.current_thread().query_count += 1
+            threading.current_thread().query_time += delay
 
         # advanced stats only if sql_log is enabled
         if self.sql_log:
-            delay = (time.time() - now) * 1E6
+            delay *= 1E6
 
             res_from = re_from.match(query.lower())
             if res_from: