3

I have a REST api with DRF and start to see already a performance hit with 100 objects and 1 user requesting (me - testing).

When requesting the more complex query, I get these results for CPU, always 5 - 10s:

Resource    Value
>User CPU time  5987.089 msec
System CPU time 463.929 msec
Total CPU time  6451.018 msec
Elapsed time    6800.938 msec
Context switches    9 voluntary, 773 involuntary

but the SQL query stays below 100 ms

The more simple queries show similar behaviour, with CPU times around 1s and query time around 20 ms

So far, what I have tried out:

  • I am doing select_related() and prefetch_related(), which did improve the query time but not CPU time
  • I am using Imagekit to generate pictures, on a S3 instance. I removed the whole specification to test and this had minor impact
  • I run a method field to fetch user-specific data. Removing this had only minor impact

I have checked logs files on the backend and nothing specific shows up here... Backend is Nginx - supervisord - gunicorn - postgresql - django 1.8.1

Here are the serializer and view:

class ParticipationOrganizationSerializer(ModelSerializer):
    organization = OrganizationSerializer(required=False, read_only=True, )
    bookmark = SerializerMethodField(
        required=False,
        read_only=True,
    )
    location_map = LocationMapSerializer(
        required=False,
        read_only=True,
    )

    class Meta:
        model = Participation
        fields = (
            'id',
            'slug',
            'organization',
            'location_map',
            'map_code',
            'partner',
            'looking_for',
            'complex_profile',
            'bookmark',
            'confirmed',
        )
        read_only_fields = (
            'id',
            'slug',
            'organization',
            'location_map',
            'map_code',
            'partner',
            'bookmark',
            'confirmed',
        )

    def get_bookmark(self, obj):
        request = self.context.get('request', None)
        if request is not None:
            if(request.user.is_authenticated()):
                # print(obj.bookmarks.filter(author=request.user).count())
                try:
                    bookmark = obj.bookmarks.get(author=request.user)
                    # bookmark = Bookmark.objects.get(
                    #     author=request.user,
                    #     participation=obj,
                    # )
                    return BookmarkSerializer(bookmark).data
                except Bookmark.DoesNotExist:
                    # We have nothing yet
                    return None
                except Bookmark.MultipleObjectsReturned:
                    # This should not happen, but in case it does, delete all
                    # the bookmarks for safety reasons.
                    Bookmark.objects.filter(
                        author=request.user,
                        participation=obj,
                    ).delete()
                    return None
        return None


class ParticipationOrganizationViewSet(ReadOnlyModelViewSet):
    """
    A readonly ViewSet for viewing participations of a certain event.
    """
    serializer_class = ParticipationOrganizationSerializer
    queryset = Participation.objects.all().select_related(
        'location_map',
        'organization',
        'organization__logo_image',
    ).prefetch_related(
        'bookmarks',
    )
    lookup_field = 'slug'


    def get_queryset(self):
        event_slug = self.kwargs['event_slug']

        # Filter for the current event
        # Filter to show only the confirmed participations
        participations = Participation.objects.filter(
            event__slug=event_slug,
            confirmed=True
        ).select_related(
            'location_map',
            'organization',
            'organization__logo_image',
        ).prefetch_related(
            'bookmarks',
        )

        # Filter on partners? This is a parameter passed on in the url
        partners = self.request.query_params.get('partners', None)
        if(partners == "true"):
            participations = participations.filter(partner=True)
        return participations

# http://stackoverflow.com/questions/22616973/django-rest-framework-use-different-serializers-in-the-same-modelviewset
    def get_serializer_class(self):
        if self.action == 'list':
            return ParticipationOrganizationListSerializer
        if self.action == 'retrieve':
            return ParticipationOrganizationSerializer
        return ParticipationOrganizationListSerializer

Any help is very much appreciated!

update

I dumped the data to my local machine and I am observing similar times. I guess this rules out the whole production setup (nginx, gunicorn)?

update 2

Here are the results of the profiler.

Also I made some progress in improving the speeds by

  1. Simplifying my serializers

  2. Doing the tests with curl and having Debug Toolbar off

    ncalls  tottime percall cumtime percall filename:lineno(function)
    0   0   0   profile:0(profiler)     
    1   0   0   3.441   3.441   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/views.py:442(dispatch)
    1   0   0   3.441   3.441   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/viewsets.py:69(view)
    1   0   0   3.441   3.441   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/django/views/decorators/csrf.py:57(wrapped_view)
    1   0   0   3.44    3.44    /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/mixins.py:39(list)
    1   0   0   3.438   3.438   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/serializers.py:605(to_representation)
    1   0   0   3.438   3.438   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/serializers.py:225(data)
    1   0   0   3.438   3.438   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/serializers.py:672(data)
    344/114 0.015   0   3.318   0.029   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/serializers.py:454(to_representation)
    805 0.01    0   2.936   0.004   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/fields.py:1368(to_representation)
    2767    0.013   0   2.567   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/django/dispatch/dispatcher.py:166(send)
    2070    0.002   0   2.52    0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/registry.py:52(existence_required_receiver)
    2070    0.005   0   2.518   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/registry.py:55(_receive)
    2070    0.004   0   2.513   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/utils.py:147(call_strategy_method)
    2070    0.002   0   2.508   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/strategies.py:14(on_existence_required)
    2070    0.005   0   2.506   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/__init__.py:86(generate)
    2070    0.002   0   2.501   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/backends.py:109(generate)
    2070    0.003   0   2.499   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/backends.py:94(generate_now)
    2070    0.01    0   2.496   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/backends.py:65(get_state)
    690 0.001   0   2.292   0.003   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/__init__.py:148(__nonzero__)
    690 0.005   0   2.291   0.003   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/__init__.py:124(__bool__)
    2070    0.007   0   2.276   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/backends.py:112(_exists)
    2070    0.01    0   2.269   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/storages/backends/s3boto.py:409(exists)
    4140    0.004   0   2.14    0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/storages/backends/s3boto.py:282(entries)
    1633    0.003   0   2.135   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/storages/backends/s3boto.py:288()
    1633    0.001   0   2.129   0.001   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/boto/s3/bucketlistresultset.py:24(bucket_lister)
    2   0   0   2.128   1.064   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/boto/s3/bucket.py:390(_get_all)
    2   0   0   2.128   1.064   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/boto/s3/bucket.py:426(get_all_keys)
    1331    0.003   0   1.288   0.001   /usr/lib/python2.7/ssl.py:335(recv)
    1331    1.285   0.001   1.285   0.001   /usr/lib/python2.7/ssl.py:254(read)
    2   0   0   0.983   0.491   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/boto/connection.py:886(_mexe)
    2   0   0   0.983   0.491   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/boto/s3/connection.py:643(make_request)
    2   0   0   0.983   0.491   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/boto/connection.py:1062(make_request)
    2   0.004   0.002   0.896   0.448   /usr/lib/python2.7/httplib.py:585(_read_chunked)
    2   0   0   0.896   0.448   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/boto/connection.py:393(read)
    2   0   0   0.896   0.448   /usr/lib/python2.7/httplib.py:540(read)
    166 0.002   0   0.777   0.005   /usr/lib/python2.7/httplib.py:643(_safe_read)
    166 0.005   0   0.775   0.005   /usr/lib/python2.7/socket.py:336(read)
    2   0   0   0.568   0.284   /usr/lib/python2.7/httplib.py:793(send)
    2   0   0   0.568   0.284   /usr/lib/python2.7/httplib.py:998(_send_request)
    2   0   0   0.568   0.284   /usr/lib/python2.7/httplib.py:820(_send_output)
    2   0   0   0.568   0.284   /usr/lib/python2.7/httplib.py:977(request)
    2   0   0   0.568   0.284   /usr/lib/python2.7/httplib.py:962(endheaders)
    1   0   0   0.567   0.567   /usr/lib/python2.7/httplib.py:1174(connect)
    1380    0.001   0   0.547   0   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/__init__.py:82(url)
    1380    0.007   0   0.546   0   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/__init__.py:72(_storage_attr)
    105 0.009   0   0.528   0.005   /usr/lib/python2.7/socket.py:406(readline)
    2   0   0   0.413   0.207   /usr/lib/python2.7/httplib.py:408(begin)
    2   0   0   0.413   0.207   /usr/lib/python2.7/httplib.py:1015(getresponse)
    2   0   0   0.407   0.203   /usr/lib/python2.7/httplib.py:369(_read_status)
    2750    0.003   0   0.337   0   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/fields.py:399(get_attribute)
    1   0.223   0.223   0.335   0.335   /usr/lib/python2.7/socket.py:537(create_connection)
    2865    0.012   0   0.334   0   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/rest_framework/fields.py:65(get_attribute)
    1610    0.005   0   0.314   0   /home/my_app/.virtualenvs/my_app/src/django-s3-folder-storage/s3_folder_storage/s3.py:13(url)
    1610    0.012   0   0.309   0   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/storages/backends/s3boto.py:457(url)
    690 0.005   0   0.292   0   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/models/fields/utils.py:10(__get__)
    690 0.007   0   0.251   0   /home/my_app/.virtualenvs/my_app/local/lib/python2.7/site-packages/imagekit/cachefiles/__init__.py:20(__init__)
    2   0   0   0.248   0.124   
    >>>> cutting here, low impact calls
Philippe
  • 97
  • 1
  • 9
  • Do you have `django-debug-toolbar` installed? That might give you some insight as to where performance could be optimized. https://github.com/django-debug-toolbar/django-debug-toolbar – jape Jan 08 '16 at 20:54
  • Yup, debug-toolbar is what gives me the numbers here. – Philippe Jan 08 '16 at 21:08
  • While the `ModelSerializer`s offer a very convenient way of dealing with Django models, they sometimes introduce (in my experience) huge overhead. Give the plain `Serializer` a try. Yes, it could take some take to reimplement the stuff, but I was able to significantly benefit in terms of speed. – Alex Morozov Jan 08 '16 at 21:23
  • Have you tried installing [`django-extensions`](https://github.com/django-extensions/django-extensions) and doing `python runprofileserver`? It will tell you _which_ methods are hotspots. – Ross Rogers Jan 09 '16 at 18:13
  • How many SQL queries are being made? While there might not be much time spent executing them, Django does processing against them which could be potentially stacking up. This is why [N+1 queries](http://stackoverflow.com/q/26593312/359284) can be so costly. You also forgot to include the `BookmarkSerializer`/`LocationSerializer`. – Kevin Brown-Silva Jan 11 '16 at 20:47
  • It might help to narrow this problem down by removing any nested serializers and `SerializerMethodField` instances, so only the raw data is being returned. Figure out if that is too slow, and then slowly add things back in until you determine what is the slow part. – Kevin Brown-Silva Jan 11 '16 at 20:48
  • @RossRogers I added the profiler results – Philippe Jan 12 '16 at 11:45
  • @KevinBrown I did this over the weekend and managed to get good improvements. I simplified the serializing and got times cut in half. The nr of queries are around 100 (a few for the original query and then 1 for each object because of the bookmark). However, biggest impact seemed to be the overhead introduced by either debug_toolbar, or retrofit (when checking times on android). Using curl showed results below 1s. – Philippe Jan 12 '16 at 11:47
  • @AlexMorozov I did not see any improvements when using plain Serializer, but there are improvements by using another serializer like https://github.com/clarkduvall/serpy – Philippe Jan 12 '16 at 11:49
  • @zwervertje, got it. Thanks for a link! – Alex Morozov Jan 12 '16 at 12:29
  • It's possible that the hooks set in place by DjDT are slowing down the page load. We tend to disable the SQL tab (until we need it) for this reason, as that's usually our pain point (probably not yours though). – Kevin Brown-Silva Jan 12 '16 at 13:25
  • If you have 100 queries, you need to figure out how to combine them. It sounds like you have the [n+1 query problem](http://stackoverflow.com/questions/97197/what-is-the-n1-selects-issue). – Ross Rogers Jan 12 '16 at 15:10
  • I do see the n+1 problem, but not sure what the options are. I can not do a select_related in this case, so doing a prefetch instead. After this I can either bruteforce a loop to get the data I need, or do another query per object. I just accepted the extra query instead of doing heavy CPU cycles, but I am willing to learn something new! – Philippe Jan 13 '16 at 12:20
  • Which model is the `n` queries going to? – Ross Rogers Jan 22 '16 at 16:29
  • @RossRogers it's caused by calling bookmark = obj.bookmarks.get(author=request.user) in get_bookmark – Philippe Jan 24 '16 at 08:56
  • You can flog the performance by doing some ugly prefetch cache manipulation, [which is what I did here.](http://stackoverflow.com/a/29037715/20712) – Ross Rogers Jan 25 '16 at 22:44

0 Answers0