#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:
> 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={
> }}}
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 <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
--
You received this message because you are subscribed to the Google Groups
"Django updates" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion visit
https://groups.google.com/d/msgid/django-updates/01070196b6caf397-7a2b30cf-614f-4ec1-8b34-b1af37823033-000000%40eu-central-1.amazonses.com.
