[Django] #36380: SQL is formatted for logging regardless of whether it will be logged

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob | Owner: Jacob Walls
Walls |
Type: Bug | Status: assigned
Component: Database | Version: dev
layer (models, ORM) |
Severity: Release | Keywords: debug-sql
blocker |
Triage Stage: | Has patch: 0
Unreviewed |
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
-------------------------------------+-------------------------------------
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).

{{{#!diff
diff --git a/django/db/backends/base/operations.py
b/django/db/backends/base/operations.py
index fea73bc1e4..4c106f59e3 100644
--- a/django/db/backends/base/operations.py
+++ b/django/db/backends/base/operations.py
@@ -791,4 +791,5 @@ class BaseDatabaseOperations:

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.

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:

{{{#!diff
diff --git a/django/db/backends/utils.py b/django/db/backends/utils.py
index 568f510a67..ae810ffd12 100644
--- a/django/db/backends/utils.py
+++ b/django/db/backends/utils.py
@@ -10,6 +10,7 @@ from hashlib import md5
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,7 +152,7 @@ class CursorDebugWrapper(CursorWrapper):
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={
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/36380>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------

Reporter: Jacob Walls | Owner: Jacob

| Walls
Type: Bug | Status: assigned

Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage:
| Unreviewed
Has patch: 0 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by Simon Charette):

Have we considered moving the formatting logic
[https://docs.python.org/3/library/logging.html#logging.Formatter to an
actual logging formater] instead? I believe these only kick in when the
log is actually handled?
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:1>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:

Keywords: debug-sql | Triage Stage: Accepted

Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Tim Graham):

* stage: Unreviewed => Accepted


Old description:

New description:

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).

{{{#!diff
diff --git a/django/db/backends/base/operations.py
b/django/db/backends/base/operations.py
index fea73bc1e4..4c106f59e3 100644
--- a/django/db/backends/base/operations.py
+++ b/django/db/backends/base/operations.py
@@ -791,4 +791,5 @@ class BaseDatabaseOperations:

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:

{{{#!diff
diff --git a/django/db/backends/utils.py b/django/db/backends/utils.py
index 568f510a67..ae810ffd12 100644
--- a/django/db/backends/utils.py
+++ b/django/db/backends/utils.py
@@ -10,6 +10,7 @@ from hashlib import md5
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,7 +152,7 @@ class CursorDebugWrapper(CursorWrapper):
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={
}}}

--

Comment:

I had some reservations that moving the formatting from the test runner to
the `CursorDebugWrapper` might cause some problem.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:2>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by 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:

{{{#!diff
diff --git a/django/db/backends/utils.py b/django/db/backends/utils.py

index 568f510a67..fe5b9478ac 100644
--- a/django/db/backends/utils.py
+++ b/django/db/backends/utils.py
@@ -151,7 +151,7 @@ class CursorDebugWrapper(CursorWrapper):

logger.debug(
"(%.3f) %s; args=%s; alias=%s",
duration,
- self.db.ops.format_debug_sql(sql),

+ sql,
params,
self.db.alias,
extra={
@@ -159,6 +159,7 @@ class CursorDebugWrapper(CursorWrapper):
"sql": sql,
"params": params,
"alias": self.db.alias,
+ "sql_format_function": self.db.ops.format_debug_sql,
},
)

diff --git a/django/utils/log.py b/django/utils/log.py
index a25b97a7d5..09bb7ace50 100644
--- a/django/utils/log.py
+++ b/django/utils/log.py
@@ -255,3 +255,9 @@ def log_response(
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.)

{{{#!py

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?
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:3>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted

Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Jacob Walls):

* has_patch: 0 => 1

Comment:

[https://github.com/django/django/pull/19479 PR] for adding the degree of
laziness, but open to other ideas if I didn't evaluate the
`logging.Formatter` approach sufficiently.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:4>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted

format_debug_sq |

Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Natalia Bidart):

* keywords: debug-sql => debug-sql format_debug_sq
* needs_better_patch: 0 => 1

Comment:

As I just commented in the PR, I think I slightly prefer using
[https://docs.python.org/3/library/logging.html#logging.Logger.isEnabledFor
logging.Logger.isEnabledFor] to conditionally format the sql.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:5>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sq |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by Tim Graham):

So the idea is:
{{{#!python
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:6>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sq |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by Natalia Bidart):

Replying to [comment:6 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:7>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sq |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:8>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sq |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Natalia Bidart):

* cc: Simon Charette, Jacob Walls, Mariusz Felisiak (added)

Comment:

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).
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:9>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sq |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:10>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sq |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by 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
[https://gist.github.com/jacobtylerwalls/e993883367704c994c02d389c35ca85b
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.)
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:11>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Jacob
| Walls
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sq |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Comment (by 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 pre-4.2 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:12>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------

Reporter: Jacob Walls | Owner: Natalia
| Bidart

Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted

format_debug_sql |

Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Jacob Walls):

* keywords: debug-sql format_debug_sq => debug-sql format_debug_sql
* owner: Jacob Walls => Natalia Bidart

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:13>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by 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).
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:14>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |

Has patch: 1 | Needs documentation: 1
Needs tests: 1 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Natalia Bidart):

* needs_docs: 0 => 1
* needs_tests: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:15>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |

Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Changes (by Natalia Bidart):

* needs_better_patch: 1 => 0
* needs_docs: 1 => 0
* needs_tests: 1 => 0

Comment:

Final attempt at https://github.com/django/django/pull/19512 (I think this
is a winner).
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:16>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |
Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Changes (by Natalia Bidart):

* needs_better_patch: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:17>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by Sage Abdullah):

Thanks for reporting this, Tim! I did notice this when I made
[https://github.com/laymonage/django-sqlite-bulk-optimization my repro]
for #36143.

You can see that with Django's `main` branch, my `assertNumQueries` test
[https://github.com/laymonage/django-sqlite-bulk-
optimization/actions/runs/15422012460/job/43399341443 took more than 5
mins]. On Natalia's PR branch for this ticket,
[https://github.com/laymonage/django-sqlite-bulk-
optimization/actions/runs/15422012460/job/43399341468 it only took less
than a second].

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

{{{#!diff
diff --git a/tests/bulk_create/tests.py b/tests/bulk_create/tests.py
index d590a292de..0c9aa65aeb 100644
--- a/tests/bulk_create/tests.py
+++ b/tests/bulk_create/tests.py
@@ -295,7 +295,7 @@ class BulkCreateTests(TestCase):

@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.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:18>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by 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`.)
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:19>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |
Has patch: 1 | Needs documentation: 0

Needs tests: 1 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Natalia Bidart):

* needs_better_patch: 1 => 0
* needs_tests: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:20>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |
Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Changes (by Natalia Bidart):

* needs_tests: 1 => 0

Comment:

[https://github.com/django/django/pull/19512 PR] ready for final review.
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:21>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:

Keywords: debug-sql | Triage Stage: Ready for
format_debug_sql | checkin

Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Sarah Boyce):

* stage: Accepted => Ready for checkin

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:22>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:

Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |

Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Changes (by Sarah Boyce):

* needs_better_patch: 0 => 1
* stage: Ready for checkin => Accepted

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:23>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |
Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Natalia Bidart):

* needs_better_patch: 1 => 0

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:24>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:
Keywords: debug-sql | Triage Stage: Accepted
format_debug_sql |
Has patch: 1 | Needs documentation: 0

Needs tests: 1 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Jacob Walls):

* needs_better_patch: 0 => 1

* needs_tests: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:25>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: assigned
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution:

Keywords: debug-sql | Triage Stage: Ready for
format_debug_sql | checkin

Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Changes (by Jacob Walls):

* needs_better_patch: 1 => 0

* needs_tests: 1 => 0

* stage: Accepted => Ready for checkin

--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:26>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart

Type: Bug | Status: closed

Component: Database layer | Version: dev
(models, ORM) |

Severity: Release blocker | Resolution: fixed

Keywords: debug-sql | Triage Stage: Ready for
format_debug_sql | checkin
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by nessita <124304+nessita@…>):

In [changeset:"d6e0c710173531645bd3689bc03e9b809aa3d220" d6e0c710]:
{{{#!CommitTicketReference repository=""
revision="d6e0c710173531645bd3689bc03e9b809aa3d220"
Refs #36380 -- Replaced mocked logging assertions in
tests/backends/tests.py.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:28>

[Django]

#36380: SQL is formatted for logging regardless of whether it will be logged
-------------------------------------+-------------------------------------
Reporter: Jacob Walls | Owner: Natalia
| Bidart
Type: Bug | Status: closed
Component: Database layer | Version: dev
(models, ORM) |
Severity: Release blocker | Resolution: fixed
Keywords: debug-sql | Triage Stage: Ready for
format_debug_sql | checkin
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by nessita <124304+nessita@…>):

* resolution: => fixed
* status: assigned => closed

Comment:

In [changeset:"1a03a984ab3728253f964ba16cd8d806f76bddf9" 1a03a984]:
{{{#!CommitTicketReference repository=""
revision="1a03a984ab3728253f964ba16cd8d806f76bddf9"
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 <jacobty...@gmail.com>
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/36380#comment:27>