Add logging to related descriptors

[Flavio Curella]

Hi y'all,

One of the most common performance issues we found with our clients is the 
"n+1 queries" problem: some code will access some related objects of an 
instance that's been fetched without `select_related` or `prefetch_related`.

There are many way this can be improved[1] from the user side. But I think 
a useful way Django could easily doing more to help debug applications is 
to simply add some DEBUG-level logging whenever a related instance gets 
fetched.

The idea would be add logging calls in the `__get__` methods of related 
descriptors:

* 
https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L166
* 
https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L395

And in the `get_queryset` methods of the related managers:

* 
https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L609
* 
https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L890


Adding some logging seems pretty trivial, but I have a couple of questions 
I would appreciate your feedback oon:

1. Maybe issuing a warning would be more effective and also prevent those 
issues from happening. One additional benefit is that users could turn 
those warnings into exceptions, if they wish.
2. Should this kind of logging also be also applied to fields deferred by 
`defer()` and `only()`?


[1] Various solutions I've found around:

* add an argument to the fields / add subclasses of the fields: 
https://code.djangoproject.com/ticket/26481, 
https://gist.github.com/kyle-eshares/5eaed8a5c299e5282d066a1fbc03152c
* a `sealable` decorator for the model: 
https://github.com/charettes/django-seal

Thank you,
–Flavio.

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/a4155ace-7fcb-4463-8b89-069fc36778ce%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Re: Add logging to related descriptors

[James Bennett]

Have you looked at the assertNumQueries assertion?

https://docs.djangoproject.com/en/2.2/topics/testing/tools/#django.test.TransactionTestCase.assertNumQueries

This can let you assert the expected queries and break your tests if
someone accidentally introduces an N+1.

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/CAL13Cg88D8DQovyY559GBMrEV6M7dXrT1Bnd70Ws8_tf-PgJ%2Bw%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

Re: Add logging to related descriptors

[Flavio Curella]

`assertNumQueries` is useful in *preventing* accidental N+1 in your views, 
and I sure which people would use a lot more.

But there are many situations where a N+1 can get created and people 
usually have don't write tests for (even if they should have). For example, 
assume this model:

```
# models.py

class Author(models.Model):
name = models.CharField(max_length=100)


class Book(models.Model):
   title = models.CharField(max_length=100)
   author = models.ForeignKey(Author)


   class __str__(self):
  return f"{self.title}, by {self.author.name}"


# admin.py

admin.site.register(Book)
```

You shouldn't write a `__str__` that way in the first place, but in my 
experience I've seen way more `__str__` methods accessing related fields 
than tests checking `assertNumQueries` against admin views. Some additional 
logging would help me spot this issues before writing the tests.

The additional logging is not a solution, just a debugging tool to help fix 
the codebase by telling me where to add `select_related` _and_ prioritize 
what to write tests against.


On Tuesday, May 28, 2019 at 11:13:59 AM UTC-5, James Bennett wrote:
>
> Have you looked at the assertNumQueries assertion?
>
>
> https://docs.djangoproject.com/en/2.2/topics/testing/tools/#django.test.TransactionTestCase.assertNumQueries
>
> This can let you assert the expected queries and break your tests if 
> someone accidentally introduces an N+1.
>

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/147e8487-958c-4220-9114-d253ec653e20%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Re: Add logging to related descriptors

[James Bennett]

On Tue, May 28, 2019 at 9:30 AM Flavio Curella 
wrote:

> But there are many situations where a N+1 can get created and people
> usually have don't write tests for (even if they should have). For example,
> assume this model:
>

I guess my question is: if your devs won't check this in tests, why do you
expect they'll check it through another mechanism? :)

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/CAL13Cg-K6YXg3UkGbnKktd7x7TSE7CncT_p8ZGHyt_kGTAbXpg%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

Re: ERROR: The included URLConf 'website.urls' does not appear to have patterns in it. If u see valid patterns in the file then there is issue of Circular import.

[Madhur Kabra]

Thanks for your answer, but this isn't working. Could you help me with 
another solution

On Monday, May 27, 2019 at 10:06:37 PM UTC+5:30, rajan khadka wrote:
>
> in this
>
> from django.urls import URLPattern, url
> from . import views
>
> urlpatterns = [
> url('', views.index, name=index),
> ]
>
> can u replace with this
>
> from django.urls import path
> from . import views
>
> urlpatterns = [
> path('', views.index, name=index),
> ]
>
>
>
> On Mon, May 27, 2019 at 8:32 PM Madhur Kabra  > wrote:
>
>> I am getting the url conf error, I  have attached the relevant files.
>> Thanks for the assistance
>>
>> -- 
>> You received this message because you are subscribed to the Google Groups 
>> "Django developers (Contributions to Django itself)" group.
>> To unsubscribe from this group and stop receiving emails from it, send an 
>> email to django-d...@googlegroups.com .
>> To post to this group, send email to django-d...@googlegroups.com 
>> .
>> Visit this group at https://groups.google.com/group/django-developers.
>> To view this discussion on the web visit 
>> https://groups.google.com/d/msgid/django-developers/452a42ef-70be-4f8f-b963-223909507a48%40googlegroups.com
>>  
>> 
>> .
>> For more options, visit https://groups.google.com/d/optout.
>>
>

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/933ad758-2c1d-452b-bfd9-f8549ddfb847%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Re: ERROR: The included URLConf 'website.urls' does not appear to have patterns in it. If u see valid patterns in the file then there is issue of Circular import.

[Tom Forbes]

As Adam states before, in the first reply to your original message, this 
mailing list is for the internal development of Django and not for getting help 
with your Django projects.

There are numerous other places to ask, check his email for a few, and a lot of 
people (myself included) willing to help you there. 

Tom

> On 28 May 2019, at 17:44, Madhur Kabra  wrote:
> 
> Thanks for your answer, but this isn't working. Could you help me with 
> another solution
> 
>> On Monday, May 27, 2019 at 10:06:37 PM UTC+5:30, rajan khadka wrote:
>> in this
>> from django.urls import URLPattern, url
>> from . import views
>> 
>> urlpatterns = [
>> url('', views.index, name=index),
>> ]
>> can u replace with this
>> from django.urls import path
>> from . import views
>> 
>> urlpatterns = [
>> path('', views.index, name=index),
>> ]
>> 
>> 
>>> On Mon, May 27, 2019 at 8:32 PM Madhur Kabra  wrote:
>>> I am getting the url conf error, I  have attached the relevant files.
>>> Thanks for the assistance
>>> -- 
>>> You received this message because you are subscribed to the Google Groups 
>>> "Django developers (Contributions to Django itself)" group.
>>> To unsubscribe from this group and stop receiving emails from it, send an 
>>> email to django-d...@googlegroups.com.
>>> To post to this group, send email to django-d...@googlegroups.com.
>>> Visit this group at https://groups.google.com/group/django-developers.
>>> To view this discussion on the web visit 
>>> https://groups.google.com/d/msgid/django-developers/452a42ef-70be-4f8f-b963-223909507a48%40googlegroups.com.
>>> For more options, visit https://groups.google.com/d/optout.
> 
> -- 
> You received this message because you are subscribed to the Google Groups 
> "Django developers (Contributions to Django itself)" group.
> To unsubscribe from this group and stop receiving emails from it, send an 
> email to django-developers+unsubscr...@googlegroups.com.
> To post to this group, send email to django-developers@googlegroups.com.
> Visit this group at https://groups.google.com/group/django-developers.
> To view this discussion on the web visit 
> https://groups.google.com/d/msgid/django-developers/933ad758-2c1d-452b-bfd9-f8549ddfb847%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/DEF03CF8-1B44-4F11-B972-04F12527C3FA%40tomforb.es.
For more options, visit https://groups.google.com/d/optout.

Re: Add logging to related descriptors

[Flavio Curella]

On Tuesday, May 28, 2019 at 11:48:11 AM UTC-5, James Bennett wrote:
>
>
> I guess my question is: if your devs won't check this in tests, why do you 
> expect they'll check it through another mechanism? :) 
>

I don't expect them to. The logging is for me, the consultant hired to find 
why their code is slow :P 

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/4cbd0052-7f2f-48de-b58a-242784d43767%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Fellow Reports -- May 2019

[Carlton Gibson]

Hi all. 


Calendar Week 19 -- ending 12 May.


Triaged:

https://code.djangoproject.com/ticket/30472 -- Argon2id should be supported 
and become the default variety for Argon2PasswordHasher (Accepted)
https://code.djangoproject.com/ticket/30469 -- Boolean False becomes NULL 
with recent mysql-connector-python (Invalid)
https://code.djangoproject.com/ticket/30470 -- Complete assertHTMLEqual() 
support for all self closing tags (Accepted)
https://code.djangoproject.com/ticket/30468 -- assertHTMLEqual doesn't 
account for all ASCII whitespace in a class attribute. (Accepted)
https://code.djangoproject.com/ticket/30467 -- `makemigrations app_label` 
sometimes tries to create migrations for unrequested app_label (invalid)
https://code.djangoproject.com/ticket/30449 -- Ordering problem in 
admin.RelatedFieldListFilter and admin.RelatedOnlyFieldListFilter (Accepted)
https://code.djangoproject.com/ticket/30453 -- Django's template 
library tags cant use already decorated things like lru_cache because of 
getfullargspec (needsinfo)
https://code.djangoproject.com/ticket/30466 -- FieldFile.save documentation 
is misleading (wontfix)
https://code.djangoproject.com/ticket/30459 -- If a StackedInline has 
fieldsets with the "collapsed" class, the "Show" link 
doesn't work on inline forms added with the "Add another [inline 
object]" link (Accepted)
https://code.djangoproject.com/ticket/30463 -- Deprecation message crashes 
when using a query expression in Model.ordering. (Accepted)
https://code.djangoproject.com/ticket/30457 -- on_commit should be 
triggered in a TestCase (Accepted)



Reviewed:

https://github.com/django/django/pull/11353 -- Fixed #30459 - Delegated 
hide/show JS toggle to parent div
https://github.com/django/django/pull/11348 -- Fixed #30470 -- Added 
assertHTMLEqual() support for all self closing tags.
https://github.com/django/django/pull/11346 -- Fixed trivial source comment 
typo.
https://github.com/django/django/pull/11344 -- Refs #27804 -- Used 
subTest() in HTMLEqualTests.test_self_closing_tags.
https://github.com/django/django/pull/11345 -- Fixed #30468 -- Fixed 
assertHTMLEqual() to handle all ASCII whitespace in a class attribute.
https://github.com/django/django/pull/11165 -- Fixed #30310 -- Added 
support for looking up HttpHeaders.headers using underscores.
https://github.com/django/django/pull/11343 -- Refs #30399 -- Made 
assertHTMLEqual normalize character and entity references.
https://code.djangoproject.com/ticket/27086 -- running servers.tests may 
hang in parallel mode on Mac OS X
https://github.com/django/django/pull/11209 -- Fixed #30451 -- Implemented 
ASGI handler and coroutine-safety.
https://github.com/django/django/pull/9884 -- Fixed 29336 -- Added docs for 
circular template inheritance.



Authored:

https://github.com/django/django/pull/11336 -- Removed redundant check from 
StaticFilesHandler.





Calendar Week 20 -- ending 19 May.


Triaged:

https://code.djangoproject.com/ticket/30475 -- Use of i18n_patterns and a 
buggy 404 template trigger internal server error without a backtrace 
(needsinfo)
https://code.djangoproject.com/ticket/30481 -- Document that force_text() 
allows lone surrogates. (Accepted)
https://code.djangoproject.com/ticket/30478 -- Do not require npm installed 
for JavaScript tests (tox -e javascript) (wontfix)



Reviewed:

https://github.com/django/django/pull/11374 -- Fixed #30485: Fixed 
django.utils.http.urlencode in the doseq=False case.
https://code.djangoproject.com/ticket/25633 -- GeoDjango KyngChaos 
installation instructions are outdated
https://code.djangoproject.com/ticket/30196 -- Make FileResponse always set 
Content-Disposition header.
https://code.djangoproject.com/ticket/30199 -- get_or_create documentation 
encourages unsafe usage
https://github.com/django/django/pull/11370 -- Make it very clear where 
LOGGING setting goes - be consistent.
https://code.djangoproject.com/ticket/30486 -- Custom aggregate function 
example needs updating for Django 2.2's `allow_distinct`
https://github.com/django/django/pull/11373 -- Fixed typo and added 
allow_distinct in docs/ref/models/expressions.txt
https://github.com/django/django/pull/11371 -- Fixed #30483 -- Switched 
test requirement to psycopg2 package.
https://code.djangoproject.com/ticket/30220 -- Use headless browsers for 
selenium tests.
https://github.com/django/django/pull/11362 -- Changed tuple choices to 
list in docs.
https://github.com/django/django/pull/11363 -- Changed docs to link to 
Python's description of iterable.
https://github.com/django/django/pull/11366 -- Fixed mis-capitalisation in 
comment.



Authored:

https://github.com/django/django/pull/11353 -- Fixed #30459 - Delegated 
hide/show JS toggle to parent div.




Calendar Week 21 -- ending 26 May.


Triaged:

https://code.djangoproject.com/ticket/30505 -- rdering of Field.choices is 
significant for makemigrations (Accepted)
https://code.djangoproject.com/ticket/30504 -- Order of arguments on 
redirect incorrect on 

Re: Add logging to related descriptors

[Adam Johnson]

My library https://github.com/adamchainz/django-perf-rec also has some
popularity, it's like assertNumQueries on steroids

I'd still like to revisit and one day merge auto prefetch_related that
would turn every N+1 queries into 2 bigger queries (
https://groups.google.com/d/msg/django-developers/EplZGj-ejvg/nYb0jxSTBgAJ
).

On Tue, 28 May 2019 at 17:50, Flavio Curella 
wrote:

> On Tuesday, May 28, 2019 at 11:48:11 AM UTC-5, James Bennett wrote:
>>
>>
>> I guess my question is: if your devs won't check this in tests, why do
>> you expect they'll check it through another mechanism? :)
>>
>
> I don't expect them to. The logging is for me, the consultant hired to
> find why their code is slow :P
>
> --
> You received this message because you are subscribed to the Google Groups
> "Django developers (Contributions to Django itself)" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to django-developers+unsubscr...@googlegroups.com.
> To post to this group, send email to django-developers@googlegroups.com.
> Visit this group at https://groups.google.com/group/django-developers.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/django-developers/4cbd0052-7f2f-48de-b58a-242784d43767%40googlegroups.com
> 
> .
> For more options, visit https://groups.google.com/d/optout.
>


-- 
Adam

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/CAMyDDM35ww2EDbbnS6F46Gp5FMSD4ASyKxKYwYoMajnXb4MoMg%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

Re: Add logging to related descriptors

[charettes]

Hello Flavio,

We've implemented a solution[0] similar to what you are suggesting that 
produces warnings[1]
that can either be turned into logs[2] or elevated to exceptions[3]. We 
chose to elevate the warnings
to exceptions during our test suite to make sure covered code enforces the 
usage of
select_related and prefetch_related.

One thing to note is that the package is still opt-in in the sense that it 
requires sealing querysets
but we're thinking of adding a setting that enables it by default for all 
models.

Cheers,
Simon

[0] https://github.com/charettes/django-seal
[1] https://docs.python.org/3/library/warnings.html
[2] https://docs.python.org/3/library/logging.html#logging.captureWarnings
[3] https://docs.python.org/3/library/warnings.html#warnings.filterwarnings

Le mardi 28 mai 2019 12:10:26 UTC-4, Flavio Curella a écrit :
>
> Hi y'all,
>
> One of the most common performance issues we found with our clients is the 
> "n+1 queries" problem: some code will access some related objects of an 
> instance that's been fetched without `select_related` or `prefetch_related`.
>
> There are many way this can be improved[1] from the user side. But I think 
> a useful way Django could easily doing more to help debug applications is 
> to simply add some DEBUG-level logging whenever a related instance gets 
> fetched.
>
> The idea would be add logging calls in the `__get__` methods of related 
> descriptors:
>
> * 
> https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L166
> * 
> https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L395
>
> And in the `get_queryset` methods of the related managers:
>
> * 
> https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L609
> * 
> https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L890
>
>
> Adding some logging seems pretty trivial, but I have a couple of questions 
> I would appreciate your feedback oon:
>
> 1. Maybe issuing a warning would be more effective and also prevent those 
> issues from happening. One additional benefit is that users could turn 
> those warnings into exceptions, if they wish.
> 2. Should this kind of logging also be also applied to fields deferred by 
> `defer()` and `only()`?
>
>
> [1] Various solutions I've found around:
>
> * add an argument to the fields / add subclasses of the fields: 
> https://code.djangoproject.com/ticket/26481, 
> https://gist.github.com/kyle-eshares/5eaed8a5c299e5282d066a1fbc03152c
> * a `sealable` decorator for the model: 
> https://github.com/charettes/django-seal
>
> Thank you,
> –Flavio.
>

-- 
You received this message because you are subscribed to the Google Groups 
"Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to django-developers+unsubscr...@googlegroups.com.
To post to this group, send email to django-developers@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/97744bb4-143e-4970-be9e-198a3c49b6d6%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.