SQL is formatted for logging regardless of whether it will be logged

[Jacob Walls]

I have an endpoint that generates several large SQL strings. It performs 10x worse (300ms -> 3000ms) on the main branch. Traced it to eager formatting of SQL.

To reproduce, print or throw inside format_debug_sql(), and run a project without logging queries (i.e. without a django.db entry in LOGGING configured at the DEBUG level).

django/db/backends/base/operations.py

@@ -791 +791 @@
 
     def format_debug_sql(self, sql):
         # Hook for backends (e.g. NoSQL) to customize formatting.
+        print('eager formatting...')
         return sqlparse.format(sql, reindent=True, keyword_case="upper")

Regression in d8f093908c504ae0dbc39d3f5231f7d7920dde37 (#35448).

We might want a benchmark in django-asv for views with long SQL strings?

This fix works for me; I can submit a patch with tests in the next few days:

django/db/backends/utils.py

@@ -10 +10 @@
 from django.apps import apps
 from django.db import NotSupportedError
 from django.utils.dateparse import parse_time
+from django.utils.functional import lazy
 
 logger = logging.getLogger("django.db.backends")
 
@@ -151 +152 @@
             logger.debug(
                 "(%.3f) %s; args=%s; alias=%s",
                 duration,
-                self.db.ops.format_debug_sql(sql),
+                lazy(self.db.ops.format_debug_sql)(sql),
                 params,
                 self.db.alias,
                 extra={

[Simon Charette]

Have we considered moving the formatting logic ​to an actual logging formater instead? I believe these only kick in when the log is actually handled?

[Tim Graham]

I had some reservations that moving the formatting from the test runner to the CursorDebugWrapper might cause some problem.