Django Rest Framework / Django performance issue
2,416 views
Skip to first unread message
Rakan Alhneiti
Feb 16, 2013, 9:25:52 AM2/16/13
to django-res...@googlegroups.com
Hello,
I am currently deploying Django w/ Django-Rest-Framework on my EC2 small instance server to provide a set of APIs for a couple of Android apps.
The problem is that i am facing a serious performance issue that i had to profile. I found out that most of the time for a single request is spent inside DRF's core.
Sorry for making this a long post but i think i have to show everything so that i can get a proper answer for whats going on. Let me go ahead:
My setup is nginx / uwsgi. Here's how i am running uwsgi using 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 request the following API:
Which matches the following rule:
url(r'^nodes/mostviewed/(?P<category>\d+)/$', MostViewedNodesList.as_view(), name='mostviewed-nodes-list'),
Here's the class-based view:
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 []
The 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 the classmethod 'get_most_viewed' (i know it's wrong to use classmethods rather than 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 this, it's a normal request the is redirected to the designated view, fetching data from MySQL and then returning the serialized result. Nothing out of the ordinary or any complex processing.
Executing:
ab -c 500 -n 5000 http://IP_HERE/api/nodes/mostviewed/9/
Notice that this is without caching. The following is frequently logged:
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)
Load average during testing goes up to ~ 5. And here's the ab result:
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 failed requests due to timeout errors is also because of the performance lag i am facing here.
To be completely honest. I am expecting ~ 60 - 70 requests per second without caching. I know that caching speeds up the process but it also hides the performance issues i have which is why i am pursuing to solve this before i cache stuff.
I decided then to profile this on a vmware CentOS machine using django-profiling which by adding ?prof to the request shows 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 e.g. '_.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 spend on django views & DRF views.
Can someone point out if i am doing anything wrong here? why are requests so slow? does python / django scale? i read that it does but how many requests / second should i expect on a simple DB read & rendering operation such as the one i am doing?
Xavier Ordoquy
Feb 16, 2013, 10:41:56 AM2/16/13
to django-res...@googlegroups.com
Hi
You request seems to span around 5 tables. I wouldn't call it an ordinary or a simple query.
Have you installed django debug toolbar, made a request through the web interface and see how long the sql query took ?
Also the query size, ie number of items returned but also their size matters. You queryset seems to hit 7Mb which sounds huge to me.
As you're using prefetch_related, keep in mind that mysql will have horrible performances with that sort of query.
This seems to be confirmed by the time taken by the prefetch related: 1.645s. That is to say that 3/4 of the time has been spent processing that prefetch related !
All the evidences you gave here lead me to think you have a matter of size with your request for the performances you are targeting.
Regards,
Xavier.
--
You received this message because you are subscribed to the Google Groups "django-rest-framework" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-rest-fram...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
Rakan Alhneiti
Feb 16, 2013, 2:06:17 PM2/16/13
to django-res...@googlegroups.com
Hello Xavier,
Yes i have used debug toolbar. It was this great tool that led me into using prefetch_related after seeing that my code was making 42 queries. After using those i got to 3 queries only as follows (executed in 380 ms):
1) SELECT ••• FROM `objects` LEFT OUTER JOIN `objects` T2 ON (`objects`.`parent_id` = T2.`id`) LEFT OUTER JOIN `objects` T3 ON (T2.`parent_id` = T3.`id`) , `content_api_objectviewsstats` WHERE objects.id=content_api_objectviewsstats.node_id AND content_api_objectviewsstats.term_id='9' ORDER BY `content_api_objectviewsstats`.num_views DESC
2) SELECT ••• FROM `media_image` INNER JOIN `objects_images` ON (`media_image`.`id` = `objects_images`.`image_id`) WHERE `objects_images`.`object_id` IN (6061, 5803, 5971, 2058, 5805, 5797, 5806, 6070, 5807, 6055, 5808, 5783, 5809, 5810, 5811, 6071, 5812, 5813, 6056, 5815, 5799, 5816, 607 ............ etc more than 100 ID
3) SELECT ••• FROM `objects_meta` WHERE `objects_meta`.`object_id` IN (6061, 5803, 5971, 2058, 5805, 5797, 5806, 6070, 5807, 6055, 5808, 5783, 5809, 5810, 5811, 6071, 5812, 5813, 6056, 5815, 5799, 5816, 6072, 5817, 5818, ....... same as images
After seeing those queries i figured out that i need to fetch the objects from the queryset limited by let's say 10 items a time depending on the "page" query parameter. But i found out that, when you slice your queryset before returning it to the view in DRF... DRF will also slice it on it's side too according to the "PAGINATE_BY" configuration & the page query parameter. So if i slice my queryset in page 2 as an example [10:20], DRF will also slice [10:20] and this would result in an empty result set because i returned an array of 10 items to DRF view so when slicing it starting offset 10, the resulting slice will be empty.
In fact, i've added this as a ticket on DRF's github issues page: https://github.com/tomchristie/django-rest-framework/issues/656
From what you've said which is pretty useful as i haven't paid attention to the details you mentioned and what i explained above... i am limited by the frameworks unless i am missing some work around that i should be using.
What do you think?
Thanks
To unsubscribe from this group and stop receiving emails from it, send an email to django-rest-framework+unsub...@googlegroups.com.
Xavier Ordoquy
Feb 16, 2013, 2:23:02 PM2/16/13
to django-res...@googlegroups.com
Hi,
This is really interesting case.
As far as I can tell, DRF uses the Django's pagination. I'll perform some tests and will discuss the matter further with tom on monday.
You'll probably have a follow up on the ticket next week..
Regards,
Xavier Ordoquy.
To unsubscribe from this group and stop receiving emails from it, send an email to django-rest-fram...@googlegroups.com.
Tom Christie
Feb 16, 2013, 2:39:00 PM2/16/13
to django-res...@googlegroups.com
Note that you're using 'list' inside your get_most_viewed method, which isn't needed, and which will forcibly evaluate the entire queryset, regardless of the pagination that occurs later. You should start by getting rid of that and relying on REST framework's (ie Django's) standard pagination, rather than paginating yourself in the view. That should ensure that the prefetch related only gets applied to the first page of results.
Rakan Alhneiti
Feb 16, 2013, 4:55:57 PM2/16/13
to django-res...@googlegroups.com
Hello,
Tom is right... i was using list function back from when i was doing a raw query in which i had to list the resultset for some reason. Now after removing the list function call and returning the result queryset... the above queries are limited to 10 items that i specified in my pagination setting for DRF.
I got to this profiled call stack:
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.051 0.051 /usr/lib/python2.6/site-packages/django/views/generic/base.py:44(view)
1 0.000 0.000 0.051 0.051 /usr/lib/python2.6/site-packages/django/views/decorators/csrf.py:76(wrapped_view)
1 0.000 0.000 0.051 0.051 /usr/lib/python2.6/site-packages/rest_framework/views.py:359(dispatch)
1 0.000 0.000 0.050 0.050 /usr/lib/python2.6/site-packages/rest_framework/generics.py:144(get)
1 0.000 0.000 0.050 0.050 /usr/lib/python2.6/site-packages/rest_framework/mixins.py:46(list)
1 0.000 0.000 0.031 0.031 /usr/lib/python2.6/site-packages/rest_framework/serializers.py:348(data)
21/1 0.000 0.000 0.031 0.031 /usr/lib/python2.6/site-packages/rest_framework/serializers.py:273(to_native)
21/1 0.001 0.000 0.031 0.031 /usr/lib/python2.6/site-packages/rest_framework/serializers.py:190(convert_object)
11/1 0.000 0.000 0.031 0.031 /usr/lib/python2.6/site-packages/rest_framework/serializers.py:303(field_to_native)
23/21 0.000 0.000 0.025 0.001 /usr/lib/python2.6/site-packages/django/db/models/query.py:92(__iter__)
3/1 0.000 0.000 0.025 0.025 /usr/lib/python2.6/site-packages/django/db/models/query.py:77(__len__)
1 0.000 0.000 0.017 0.017 /usr/lib/python2.6/site-packages/django/db/models/query.py:568(_prefetch_related_objects)
1 0.000 0.000 0.017 0.017 /usr/lib/python2.6/site-packages/django/db/models/query.py:1596(prefetch_related_objects)
2 0.000 0.000 0.017 0.008 /usr/lib/python2.6/site-packages/django/db/models/query.py:1748(prefetch_one_level)
4 0.000 0.000 0.017 0.004 /usr/lib/python2.6/site-packages/django/db/models/sql/compiler.py:794(execute_sql)
53 0.001 0.000 0.013 0.000 /usr/lib/python2.6/site-packages/django/db/models/sql/query.py:235(clone)
52 0.000 0.000 0.013 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:870(_clone)
1168/214 0.004 0.000 0.012 0.000 /usr/lib64/python2.6/copy.py:144(deepcopy)
56 0.000 0.000 0.012 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:231(iterator)
1 0.000 0.000 0.011 0.011 /usr/lib/python2.6/site-packages/django/views/generic/list.py:33(paginate_queryset)
According to django debug toolbar, i noticed a couple of things though:
1) The pagination does a "select count(*)" query which is definitely going to be the slowest one amongst all other queries. Is there a way to use SELECT SQL_CALC_FOUND_ROWS instead?
2) My requests to the API after removing "list" take 150 - 300 ms now ... looking at the call stack above, what obvious things that i might be doing in order to make this run faster? any recommendations?
Thanks
Xavier Ordoquy
Feb 16, 2013, 6:07:21 PM2/16/13
to django-res...@googlegroups.com
Le 16 févr. 2013 à 22:55, Rakan Alhneiti <rakan.a...@gmail.com> a écrit :
> Hello,
>
> Tom is right... i was using list function back from when i was doing a raw query in which i had to list the resultset for some reason. Now after removing the list function call and returning the result queryset... the above queries are limited to 10 items that i specified in my pagination setting for DRF.
>
> According to django debug toolbar, i noticed a couple of things though:
>
> 1) The pagination does a "select count(*)" query which is definitely going to be the slowest one amongst all other queries. Is there a way to use SELECT SQL_CALC_FOUND_ROWS instead?
I'm a bit surprised this is the slowest query. It is usually pretty fast as far as I remember.
>
> 1) The pagination does a "select count(*)" query which is definitely going to be the slowest one amongst all other queries. Is there a way to use SELECT SQL_CALC_FOUND_ROWS instead?
If you want to use specific things for mysql, you'll probably need to write your own pagination class.
> 2) My requests to the API after removing "list" take 150 - 300 ms now ... looking at the call stack above, what obvious things that i might be doing in order to make this run faster? any recommendations?
Isn't it fast enough ?
Regards,
Xavier.
Reply all
Reply to author
Forward
0 new messages