#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 django-updates+unsubscr...@googlegroups.com.
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.
