jazzband / django-silk

Silky smooth profiling for Django
MIT License
4.35k stars 333 forks source link

SILKY_ANALYZE_QUERIES=True causes unexpected data updates #629

Open hstanev opened 1 year ago

hstanev commented 1 year ago

Hi! First of all thanks for creating this library!

I have a case where I increment an integer like this: MyModel.objects.filter(pk=101).update(counter=F('counter')+1)

When using silk with SILKY_ANALYZE_QUERIES=True - my counter is incremented twice for every sql statement I make. This is probably not a bug, but I suggest to put a big warning in the docs, so that people use this setting with caution.

SebCorbin commented 1 year ago

Could you give us more information about where your query is placed in your code? In middleware, in a view? Also if you can give us a stacktrace of both calls so we can track down why the query would be executed twice.

Dufran commented 1 year ago

Hi, I encountered same behavior. I just have a custom method that increment counter that get called via endpoint And having SILKY_ANALYZE_QUERIES=True messed up some behavior inside tests, like incrementing 2 times. I think it's related to https://docs.djangoproject.com/en/4.1/ref/models/expressions/#avoiding-race-conditions-using-f race conditions, that gets triggered with silk middleware

SebCorbin commented 1 year ago

OK so it seems the EXPLAIN re-execute the query, I'll need to check that, can you give me the database django engine you are using?

Dufran commented 1 year ago

I'm on 'django.db.backends.postgresql' Django 4.1

SebCorbin commented 1 year ago

I think this is out of our hands then, from https://www.postgresql.org/docs/current/sql-explain.html

The ANALYZE option causes the statement to be actually executed, not only planned. Then actual run time statistics are added to the display, including the total elapsed time expended within each plan node (in milliseconds) and the total number of rows it actually returned. This is useful for seeing whether the planner's estimates are close to reality.

I'm closing this as it's not a bug., but a behavior of the engine.

Dufran commented 1 year ago

Oh, many thanks for clarification, maybe as OP mentioned it can be added to docs of that parameter?

SebCorbin commented 1 year ago

Right, I'll keep that opened then :)

iafisher commented 1 year ago

I've opened a pull request to add a warning to the documentation about this.

I was trying to figure out whether this had affected my site and although I have SILKY_ANALYZE_QUERIES = True and I am using the Postgres backend, there did not appear to be duplicate data updates, although I could be missing something. I noticed that there is a comment in the code that says (https://github.com/jazzband/django-silk/blob/master/silk/sql.py#L54):

# currently we cannot use explain() method
# for queries other than `select`

which could possibly explain it, although I do not see where this constraint is actually enforced.