Problems with Django Rest Framework / Django

Question

I am currently deploying Django w / Django-Rest-Framework on my small EC2 instance server to provide a set of APIs for several Android applications.

The problem is that I ran into a serious performance issue that I had to profile. I found out that most of the time for a single request is spent inside the DRF core.

Sorry for making a long post, but I think I need to show everything so that I can get the correct answer to what is happening. Let me go further:

My setup is nginx / uwsgi. This is how I run uwsgi using the upstart:

description "pycms" start on [2345] stop on [06] respawn # start from virtualenv path chdir /www/python/apps/pycms/ exec uwsgi -b 25000 --chdir=/www/python/apps/pycms --module=wsgi:application --env DJANGO_SETTINGS_MODULE=settings --socket=127.0.0.1:8081 --processes=5 --harakiri=20 --max-requests=5000 --vacuum --master --pidfile=/tmp/pycms-master.pid 

Assuming I am requesting the following API:

 http://IP_ADDRESS/api/nodes/mostviewed/9/ 

Which corresponds to the following rule:

 url(r'^nodes/mostviewed/(?P<category>\d+)/$', MostViewedNodesList.as_view(), name='mostviewed-nodes-list'), 

Here's the presentation class:

 class MostViewedNodesList(generics.ListAPIView): """ API endpoint that lists featured nodes """ model = ObjectStats serializer_class = NodeSerializer permission_classes = (permissions.AllowAny,) def get_queryset(self): if(self.kwargs.has_key('category')): category_id = self.kwargs.get('category') return ObjectStats.get_most_viewed(category_id) else: return [] 

Serializer Class:

 class NodeSerializer(serializers.ModelSerializer): images = ImageSerializer() favorite = ObjectField(source='is_favorite') rating = ObjectField(source='get_rating') meta = ObjectField(source='get_meta') url = ObjectField(source='get_absolute_url') channel_title = ObjectField(source='channel_title') class Meta: model = Node fields = ('id', 'title', 'body', 'images', 'parent', 'type', 'rating', 'meta', 'favorite', 'url', 'channel_title') 

And finally, classmethod 'get_most_viewed' (I know it is wrong to use classmods methods, not the manager method)

 @classmethod def get_most_viewed(cls, category_id): return list(Node.objects.extra( where=['objects.id=content_api_objectviewsstats.node_id', 'content_api_objectviewsstats.term_id=%s'], params=[category_id], tables=['content_api_objectviewsstats'], order_by=['-content_api_objectviewsstats.num_views'] ).prefetch_related('images', 'objectmeta_set').select_related('parent__parent')) 

As you can see from all of this, this is a normal query that redirects to the specified view, retrieves data from MySQL, and then returns a serialized result. Nothing unusual or complicated handling.

Performance:

 ab -c 500 -n 5000 http://IP_HERE/api/nodes/mostviewed/9/ 

Please note that this is not caching. Often the following is recorded:

 HARAKIRI: --- uWSGI worker 5 (pid: 31015) WAS managing request /api/nodes/mostviewed/9/ since Sat Feb 16 13:07:21 2013 --- DAMN ! worker 2 (pid: 31006) died, killed by signal 9 :( trying respawn ... Respawned uWSGI worker 2 (new pid: 31040) 

The average value of the load during testing increases to ~ 5. And here the result is ab:

 Concurrency Level: 500 Time taken for tests: 251.810 seconds Complete requests: 1969 Failed requests: 1771 (Connect: 0, Receive: 0, Length: 1771, Exceptions: 0) Write errors: 0 Non-2xx responses: 1967 Total transferred: 702612 bytes HTML transferred: 396412 bytes Requests per second: 7.82 [#/sec] (mean) Time per request: 63943.511 [ms] (mean) Time per request: 127.887 [ms] (mean, across all concurrent requests) Transfer rate: 2.72 [Kbytes/sec] received 

First of all, 7 requests per second is VERY disappointing. ~ 1700 unsuccessful requests due to timeout errors also due to a performance lag that I encountered.

Be absolutely honest. I expect ~ 60 - 70 requests per second without caching. I know that caching speeds up the process, but also hides the performance problems that I have, and therefore I pursue this decision before I cache the material.

I then decided to profile this on a CentOS vmware machine using django profiling, which by adding? prof to the request, shows the call stack:

 Instance wide RAM usage Partition of a set of 373497 objects. Total size = 65340232 bytes. Index Count % Size % Cumulative % Kind (class / dict of class) 0 2270 1 7609040 12 7609040 12 dict of django.db.models.sql.query.Query 1 19503 5 6263400 10 13872440 21 dict (no owner) 2 63952 17 5739672 9 19612112 30 str 3 51413 14 5090344 8 24702456 38 list 4 58435 16 4991160 8 29693616 45 tuple 5 24518 7 4434112 7 34127728 52 unicode 6 8517 2 2384760 4 36512488 56 dict of django.db.models.base.ModelState 7 2270 1 2378960 4 38891448 60 dict of django.db.models.query.QuerySet 8 2268 1 2376864 4 41268312 63 dict of 0x14d6920 9 6998 2 2088304 3 43356616 66 django.utils.datastructures.SortedDict <619 more rows. Type eg '_.more' to view.> CPU Time for this request 663425 function calls (618735 primitive calls) in 2.037 CPU seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 2.037 2.037 /usr/lib/python2.6/site-packages/django/views/generic/base.py:44(view) 1 0.000 0.000 2.037 2.037 /usr/lib/python2.6/site-packages/django/views/decorators/csrf.py:76(wrapped_view) 1 0.000 0.000 2.037 2.037 /usr/lib/python2.6/site-packages/rest_framework/views.py:359(dispatch) 1 0.000 0.000 2.036 2.036 /usr/lib/python2.6/site-packages/rest_framework/generics.py:144(get) 1 0.000 0.000 2.036 2.036 /usr/lib/python2.6/site-packages/rest_framework/mixins.py:46(list) 1 0.000 0.000 2.029 2.029 apps/content_api/views.py:504(get_queryset) 1 0.000 0.000 2.029 2.029 apps/objects_stats/models.py:11(get_most_viewed) 23/21 0.000 0.000 2.028 0.097 /usr/lib/python2.6/site-packages/django/db/models/query.py:92(__iter__) 4/2 0.003 0.001 2.028 1.014 /usr/lib/python2.6/site-packages/django/db/models/query.py:77(__len__) 1 0.000 0.000 1.645 1.645 /usr/lib/python2.6/site-packages/django/db/models/query.py:568(_prefetch_related_objects) 1 0.002 0.002 1.645 1.645 /usr/lib/python2.6/site-packages/django/db/models/query.py:1596(prefetch_related_objects) 2 0.024 0.012 1.643 0.822 /usr/lib/python2.6/site-packages/django/db/models/query.py:1748(prefetch_one_level) 2288 0.007 0.000 1.156 0.001 /usr/lib/python2.6/site-packages/django/db/models/manager.py:115(all) 6252 0.019 0.000 0.762 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:231(iterator) 4544 0.025 0.000 0.727 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:870(_clone) 4544 0.109 0.000 0.694 0.000 /usr/lib/python2.6/site-packages/django/db/models/sql/query.py:235(clone) 2270 0.004 0.000 0.619 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:619(filter) 2270 0.013 0.000 0.615 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:633(_filter_or_exclude) 1144 0.019 0.000 0.581 0.001 /usr/lib/python2.6/site-packages/django/db/models/fields/related.py:456(get_query_set) 1144 0.019 0.000 0.568 0.000 /usr/lib/python2.6/site-packages/django/db/models/fields/related.py:560(get_query_set) 55917/18180 0.192 0.000 0.500 0.000 /usr/lib64/python2.6/copy.py:144(deepcopy) 2270 0.003 0.000 0.401 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:820(using) 

And as you can see, most of the time is spent on django views and DRF views.

Can someone point out that I'm doing something wrong? Why are requests so slow? Is python / django scale? I read what it does, but how many queries / seconds should I expect from a simple read and output DB operation, such as the one I am doing?

Answer 1

makes python / django scale

Django has some pretty massive services like Disqus and Instagram, so yes, it scales very well.

Then I decided to profile this

As you can see, almost all the time is spent inside the .get_most_viewed () method so that it looks like you have a problem. (maybe not so, but your profile assumes that 2.028 of 2.037 times were spent on it, so about 99.6% of the time)

My ORM skills do not really allow me to determine exactly how you should deal with this rather complex query, and in any case you will need to see the model definitions, but you need to study the debugging and simplify this query, and not look at other parts of the review.

You might want to go into the Django shell using the manage.py shell so that you can profile this particular request with an exception for the rest of the view.

Also try to get some help on how you can simplify this request here, either on the Django channel IRC channel or on the django mailing list (most likely you are more fortunate if you ask specifically about this request and not about the more general Django / REST, here most of the questions are apparently not related to the problem you are seeing.

Hope this helps you in the right direction to resolve this issue.

Answer 2

The conversation continued on the DRF mailing list https://groups.google.com/forum/?fromgroups=#!topic/django-rest-framework/AkLKdfxCrcU

Answer 3

You are using early eveluation (e.g. list (queryset)). Maybe you just ran out of memory when many willing workers upload your requests? So you have to decide: faster results or more memory usage (65 MB per request - this can consume all the memory in seconds)

and the profiler says your code uses QuerySet.all (), which:

Returns a copy of the current QuerySet (or subclass of QuerySet).

And this causes deep tolerance, which takes a lot of time.

So, find the place where all () is called, and don't use it.