Add logging to related descriptors

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

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:


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



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:

* 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 [hidden email].
To post to this group, send email to [hidden email].
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.
Reply | Threaded
Open this post in threaded view
|

Re: Add logging to related descriptors

James Bennett
Have you looked at the assertNumQueries assertion?


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 [hidden email].
To post to this group, send email to [hidden email].
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.
Reply | Threaded
Open this post in threaded view
|

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?

<a href="https://docs.djangoproject.com/en/2.2/topics/testing/tools/#django.test.TransactionTestCase.assertNumQueries" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fdocs.djangoproject.com%2Fen%2F2.2%2Ftopics%2Ftesting%2Ftools%2F%23django.test.TransactionTestCase.assertNumQueries\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNGGR0tPXDPQJ9m8Np1PR0QOPIr7JA&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fdocs.djangoproject.com%2Fen%2F2.2%2Ftopics%2Ftesting%2Ftools%2F%23django.test.TransactionTestCase.assertNumQueries\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNGGR0tPXDPQJ9m8Np1PR0QOPIr7JA&#39;;return true;" data-external="true">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 [hidden email].
To post to this group, send email to [hidden email].
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.
Reply | Threaded
Open this post in threaded view
|

Re: Add logging to related descriptors

James Bennett
On Tue, May 28, 2019 at 9:30 AM Flavio Curella <[hidden email]> 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 [hidden email].
To post to this group, send email to [hidden email].
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.
Reply | Threaded
Open this post in threaded view
|

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 [hidden email].
To post to this group, send email to [hidden email].
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.
Reply | Threaded
Open this post in threaded view
|

Re: Add logging to related descriptors

Adam Johnson-2
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 <[hidden email]> 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 [hidden email].
To post to this group, send email to [hidden email].
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 [hidden email].
To post to this group, send email to [hidden email].
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.
Reply | Threaded
Open this post in threaded view
|

Re: Add logging to related descriptors

Simon Charette
In reply to this post by Flavio Curella
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:

* <a href="https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L166" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fdjango%2Fdjango%2Fblob%2Fa44a21a22f20c1a710670676fcca798dd6bb5ac0%2Fdjango%2Fdb%2Fmodels%2Ffields%2Frelated_descriptors.py%23L166\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNGvlRGuNHcxWVM6f2VK6isZN9n1_A&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fdjango%2Fdjango%2Fblob%2Fa44a21a22f20c1a710670676fcca798dd6bb5ac0%2Fdjango%2Fdb%2Fmodels%2Ffields%2Frelated_descriptors.py%23L166\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNGvlRGuNHcxWVM6f2VK6isZN9n1_A&#39;;return true;">https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L166
* <a href="https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L395" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fdjango%2Fdjango%2Fblob%2Fa44a21a22f20c1a710670676fcca798dd6bb5ac0%2Fdjango%2Fdb%2Fmodels%2Ffields%2Frelated_descriptors.py%23L395\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNEBtuf-XdPxO0r4lcrvJpBPci4QDw&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fdjango%2Fdjango%2Fblob%2Fa44a21a22f20c1a710670676fcca798dd6bb5ac0%2Fdjango%2Fdb%2Fmodels%2Ffields%2Frelated_descriptors.py%23L395\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNEBtuf-XdPxO0r4lcrvJpBPci4QDw&#39;;return true;">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:

* <a href="https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L609" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fdjango%2Fdjango%2Fblob%2Fa44a21a22f20c1a710670676fcca798dd6bb5ac0%2Fdjango%2Fdb%2Fmodels%2Ffields%2Frelated_descriptors.py%23L609\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNF447G8rcyvpLK-L19LOaslBsK8kg&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fdjango%2Fdjango%2Fblob%2Fa44a21a22f20c1a710670676fcca798dd6bb5ac0%2Fdjango%2Fdb%2Fmodels%2Ffields%2Frelated_descriptors.py%23L609\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNF447G8rcyvpLK-L19LOaslBsK8kg&#39;;return true;">https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L609
* <a href="https://github.com/django/django/blob/a44a21a22f20c1a710670676fcca798dd6bb5ac0/django/db/models/fields/related_descriptors.py#L890" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fdjango%2Fdjango%2Fblob%2Fa44a21a22f20c1a710670676fcca798dd6bb5ac0%2Fdjango%2Fdb%2Fmodels%2Ffields%2Frelated_descriptors.py%23L890\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNF-WzNUqzcc7HeUvclyDlCsJ71tMQ&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fdjango%2Fdjango%2Fblob%2Fa44a21a22f20c1a710670676fcca798dd6bb5ac0%2Fdjango%2Fdb%2Fmodels%2Ffields%2Frelated_descriptors.py%23L890\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNF-WzNUqzcc7HeUvclyDlCsJ71tMQ&#39;;return true;">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: <a href="https://code.djangoproject.com/ticket/26481" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fcode.djangoproject.com%2Fticket%2F26481\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNEfQ82AazDy8-slax3bHtioykel2Q&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fcode.djangoproject.com%2Fticket%2F26481\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNEfQ82AazDy8-slax3bHtioykel2Q&#39;;return true;">https://code.djangoproject.com/ticket/26481, <a href="https://gist.github.com/kyle-eshares/5eaed8a5c299e5282d066a1fbc03152c" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgist.github.com%2Fkyle-eshares%2F5eaed8a5c299e5282d066a1fbc03152c\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFZwS1RewOuBI9CSYOrpNKSuSOkJg&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgist.github.com%2Fkyle-eshares%2F5eaed8a5c299e5282d066a1fbc03152c\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFZwS1RewOuBI9CSYOrpNKSuSOkJg&#39;;return true;">https://gist.github.com/kyle-eshares/5eaed8a5c299e5282d066a1fbc03152c
* a `sealable` decorator for the model: <a href="https://github.com/charettes/django-seal" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fcharettes%2Fdjango-seal\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNGoaVlxtzh1qBnzqW9B4w0c9KWghA&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fcharettes%2Fdjango-seal\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNGoaVlxtzh1qBnzqW9B4w0c9KWghA&#39;;return true;">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 [hidden email].
To post to this group, send email to [hidden email].
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.