Django Query extremely slow

Question

I have a problem with a Django application. Queries on the model Scope are extremely slow and after some debugging I still have no clue where the problem lies.

When I query the db like scope = Scope.objects.get(pk='Esoterik I') it takes 5 to 10 seconds. The database has less than 10 entries and an index on the primary key, so it is way too slow. When executing the an equivalent query on the db like SELECT * FROM scope WHERE title='Esoterik I'; everything is ok and it takes only about 50ms.

The same problem happens if I query a set of results like scope_list = Scope.objects.filter(members=some_user) and then call print(scope_list) or iterate over the list elements. The query itself only takes a few ms but the print or iterating of the elements takes again like 5 to 10 seconds but the set has only two entries.

Database Backend is Postgresql. The same problem occurs on the local development server and apache.

Here the code of the model:

class Scope(models.Model):
    title = models.CharField(primary_key=True, max_length=30)

    ## the semester the scope is linked with
    assoc_semester  =   models.ForeignKey(Semester, null=True) 

    ## the grade of the scope. can be Null if the scope is not a class
    assoc_grade     =   models.ForeignKey(Grade, null=True)

    ## the timetable of the scope. can be null if the scope is not direct associated with a class
    assoc_timetable =   models.ForeignKey(Timetable, null=True)

    ## the associated subject of the scope
    assoc_subject   =   models.ForeignKey(Subject)

    ## the calendar of the scope
    assoc_calendar  =   models.ForeignKey(Calendar)

    ## the usergroup of the scope
    assoc_usergroup =   models.ForeignKey(Group)

    members = models.ManyToManyField(User)

    unread_count = None

update

Here is the output of the python profiler. It seems that query.py was getting called 1.6 million times - a little too much.

Vernverna

does this model have __unicode__() method? could you post it? – Marcellamarcelle

yes it has: def __unicode__(self): return self.title – Vernverna

I would suggest installing Django Debug Toolbar so that you can individually see each query. It will give you a much better idea of what is slowing you down. – Shaper

Are you testing this from the django shell or from some view? Is DEBUG True or False in settings.py? – Bioscope

Are both environments you mention connecting to the same PostgreSQL server and if so are you using a host name or IP address in the database settings? – Hilltop

You could install geordi to fully profile the view. You can see exactly where all the time is spend in every function that's called. Perhaps it isn't the database after all. – Markel

the problem occurs booth in the views and shell. booth setups run on different machines and use their own database. i will try the debug toolbar and geordi – Vernverna

@7tupel: I have a very similar issue. How did you resolve this? – Backache

Answer 1

You should try and first isolate the problem. Run manage.py shell and run the following:

scope = Scope.objects.get(pk='Esoterik I')
print scope

Now django queries are not executed until they very much have to. That is to say, if you're experiencing slowness after the first line, the problem is somewhere in the creation of the query which would suggest problems with the object manager. The next step would be to try and execute raw SQL through django, and make sure the problem is really with the manager and not a bug in django in general.

If you're experiencing slowness with the second line, the problem is eitherwith the actual execution of the query, or with the display\printing of the data. You can force-execute the query without printing it (check the documentation) to find out which one it is.

That's as far as I understand but I think the best way to solve this is to break the process down to different parts and finding out which part is the one causing the slowness

Interatomic

scope = Scope.objects.get(pk='Something') and Scope.objects.get(pk='something') booth take the same time. if i use filter() instead of get() i run into performance problems when the query is executed (e.g. if i try to do a print() with the queryset contents), so it seems the query is correctly built but on executuion time something goes wrong – Vernverna

when i try to do a raw query the execution takes the same very long time. – Vernverna

Answer 2

For being sure about the database execution time, it is better to test queries generated by Django since Django-generated queries may not be a simple SELECT * from blah blah

To see the Django generated query:

_somedata = Scope.objects.filter(pk='Esoterik I') # you must use filter in here
print somedata.query.__format__('')

This will display you the complete query generated by Django. Then copy it and open a Postgresql console and use Postgresql analyze tools:

EXPLAIN ANALYZE <your django query here>;

like:

EXPLAIN ANALYZE SELECT * FROMsomeapp_scope WHERE id = 'Esoterik I';

EXPLAIN will show average execution data while ANAYLZE will also show you some extra data about execution time of that analyze.

You can also see if any index is used by postgresql during query execution in those analyze results.

Orion

i tried that. the raw query made by django takes 26ms execution time and the simple SELECT * ... takes 15ms. so it seems the generated sql is not the problem – Vernverna