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.

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

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

[James Bennett]

On Tue, May 28, 2019 at 9:30 AM Flavio Curella <flavio....@gmail.com> 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? :) 

[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 

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

--
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-develop...@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/4cbd0052-7f2f-48de-b58a-242784d43767%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Adam

[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