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.

[Jacob Walls]

Have we considered moving the formatting logic ​to an actual logging formater instead?

I looked into this. Unless I'm missing something, it's not a good fit for our needs, because we don't want to actually change the DEFAULT_LOGGING.

To get a logging.Formatter working, I have this in Django:

django/db/backends/utils.py

@@ -151 +151 @@
             logger.debug(
                 "(%.3f) %s; args=%s; alias=%s",
                 duration,
-                self.db.ops.format_debug_sql(sql),
+                sql,
                 params,
                 self.db.alias,
                 extra={
@@ -159 +159 @@
                     "sql": sql,
                     "params": params,
                     "alias": self.db.alias,
+                    "sql_format_function": self.db.ops.format_debug_sql,
                 },
             )
 

django/utils/log.py

@@ -255 +255 @@
         exc_info=exception,
     )
     response._has_been_logged = True
+
+
+class DebugSQLFormatter(logging.Formatter):
+    def format(self, record):
+        record.sql = record.sql_format_function(record.sql)
+        return super().format(record)

And this in my project settings. I've started with a working example of query logging and commented out the changes I'd have to make on upgrade to keep the current behavior. (As far as I can tell, there is no way to "inherit" these definitions from Django.)

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    # "formatters": {  # had to be added
    #     "django.db.backends": {
    #         "()": "django.utils.log.DebugSQLFormatter",
    #         "format": "({duration:.3f}) {sql}; args={args}; alias={alias}",
    #         "style": "{",
    #     },
    # },
    "handlers": {
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': 'general.log',
        },
        # "django.db.backends": {  # had to be added
        #     "class": "logging.FileHandler",
        #     "filename": "general.log",
        #     "formatter": "django.db.backends",
        # },
    },
    "loggers": {
        "django.db.backends": {
            "handlers": ["file"],
            # "handlers": ["django.db.backends"],  # had to be adjusted
            "level": "DEBUG",
        },
    },
}

---

Wouldn't the suggestion to use lazy() be preferable to maintain the prior behavior without any impact on projects?

[Jacob Walls]

​PR for adding the degree of laziness, but open to other ideas if I didn't evaluate the logging.Formatter approach sufficiently.

[Natalia Bidart]

As I just commented in the PR, I think I slightly prefer using ​logging.Logger.isEnabledFor to conditionally format the sql.

[Tim Graham]

So the idea is:

if logger.isEnabledFor(logging.DEBUG):
    logger.debug(...)

It seems like it would work, but I guess I'm still concerned that SQL formatting shouldn't be part of CursorDebugWrapper if it has the potential to slow down request processing by 10x in any situation. For me, 3283120cca5d5eba5c3619612d0de5ad49dcf054 was too much of a hack and the formatting of --debug-sql output could simply be removed (i.e. revert d8f093908c504ae0dbc39d3f5231f7d7920dde37 too) unless an elegant solution is proposed.

[Natalia Bidart]

Replying to Tim Graham:

[...] I'm still concerned that SQL formatting shouldn't be part of CursorDebugWrapper if it has the potential to slow down request processing by 10x in any situation.

I agree.

For me, 3283120cca5d5eba5c3619612d0de5ad49dcf054 was too much of a hack and the formatting of --debug-sql output could simply be removed (i.e. revert d8f093908c504ae0dbc39d3f5231f7d7920dde37 too) unless an elegant solution is proposed.

I think this is worth considering. Reading on the tickets and evaluating "lack of SQL formatting" vs. the complications that this change has brought up, I'm inclined to go this route. Would be interesting to evaluate if we could have a dedicated log formatter (following the suggestion from Simon) to be automatically configured and plugged in when running the tests with --debug-sql. We could do this analysis in the context of #34111 (which would be reopened if reverted, unless we decide to wontfix it).

I'll ponder on this, and open to read other's people thoughts.

[Natalia Bidart]

It's also worth noting that #36112 is a side effect of the revisions mentioned in comment:6, so that one would also be solved by the proposed reverts.

[Natalia Bidart]

Tim, I'm now convinced that reverting the revnos you mentioned (plus ec8cbea91ed6362d43298caa43f3d868452f7efa) is a good path forward. I have investigated and proposed an approach for the path of isolating the log formatting in the log utils, always considering customizations (but not per backend, more like per project since it would require customizations in the logging dictConfig).

See alternate PR at ​https://github.com/django/django/pull/19508 (4 commits, 3 reverts but the alternate fix for #34111).

[Tim Graham]

Requiring customizing logging per project doesn't seem ideal (users don't want to deal with it). Also, a project may use a mix and of SQL and Non-SQL backends. Could self.db.ops.format_debug_sql be passed in extra and used in QueryFormatter?

There is still the behavior change (introduced in d8f093908c504ae0dbc39d3f5231f7d7920dde37) that SQL is formatted outside of running tests (with the proposal it's only if the user has configured debug logging), correct? I'm unsure if this is worth the risk of affecting users in some development environments. It would be interesting to know from Jacob exactly how large the SQL statements were that resulted in the 3 second response time.

[Jacob Walls]

I'm dynamically generating annotations that introspect EAV data from JSON fields. In the worst case, I found up to 400 alias clauses. (Yes, it's on my list to look into pruning unnecessary annotations, but--perhaps unbelievably--it hasn't been costing me enough performance in ordinary cases to move up my priority list). Here's a ​gist with the string. sqlparse takes about 13s to format this on an apple silicon chip. (It also produces some strange indentation; I suppose I could raise this with the maintainers.)

[Jacob Walls]

Requiring customizing logging per project doesn't seem ideal (users don't want to deal with it).

What I like about Natalia's proposal is that since we would no longer format SQL by default outside tests, no customization is necessary to keep a working query logger configuration. Users with existing (custom or default) logging configs will just get the status quo behavior of unformatted SQL in their logs (good from a performance standpoint). Users that want formatted SQL in their logs have an upgrade path via the example formatters Natalia's PR provides: copy the new default config, and change the django.db.backends logger from ERROR to DEBUG, and preserve any other custom handling). This way the "risk" is opt-in.

[Natalia Bidart]

Spin off PR based on Tim's comments is at ​https://github.com/django/django/pull/19509/ (needs tests and docs if we settle on the core solution).

[Natalia Bidart]

Final attempt at ​https://github.com/django/django/pull/19512 (I think this is a winner).

[Sage Abdullah]

Thanks for reporting this, Tim Jacob (and Tim for triaging the ticket)! I did notice this when I made ​my repro for #36143.

You can see that with Django's main branch, my assertNumQueries test ​took more than 5 mins. On Natalia's PR branch for this ticket, ​it only took less than a second.

Here's a minimal diff to demonstrate the issue on Django's main branch:

tests/bulk_create/tests.py

@@ -295 +295 @@
 
     @skipUnlessDBFeature("has_bulk_insert")
     def test_max_batch_size(self):
-        objs = [Country(name=f"Country {i}") for i in range(1000)]
+        objs = [Country(name=f"Country {i}") for i in range(2**12)]
         fields = ["name", "iso_two_letter", "description"]
         max_batch_size = connection.ops.bulk_batch_size(fields, objs)
         with self.assertNumQueries(ceil(len(objs) / max_batch_size)):

Using SQLite, the test took more than 18s on my machine, and less than 0.1s with Natalia's PR branch.

[Jacob Walls]

(Just in case others were planning to: I've reported the various issues with performance and indentation of the large SQL strings at play here to the maintainer of sqlparse.)

[Natalia Bidart]

​PR ready for final review.

[nessita <124304+nessita@…>]

In 1a03a984:

Fixed #36380 -- Deferred SQL formatting when running tests with --debug-sql.

Thanks to Jacob Walls for the report and previous iterations of this
fix, to Simon Charette for the logging formatter idea, and to Tim Graham
for testing and ensuring that 3rd party backends remain compatible.

This partially reverts d8f093908c504ae0dbc39d3f5231f7d7920dde37.

Refs #36112, #35448.

Co-authored-by: Jacob Walls <jacobtylerwalls@…>

[nessita <124304+nessita@…>]

In d6e0c710:

Refs #36380 -- Replaced mocked logging assertions in tests/backends/tests.py.