2013-02-16 32 views
6

Attualmente sto distribuendo Django con Django-Rest-Framework sul mio server di piccole istanze EC2 per fornire un set di API per un paio di app Android.Django Rest Framework/Django performance issue

Il problema è che sto affrontando un serio problema di prestazioni che ho dovuto profilare. Ho scoperto che la maggior parte del tempo per una singola richiesta viene spesa all'interno del core di DRF.

Ci scusiamo per aver fatto questo post lungo ma penso di dover mostrare tutto in modo da ottenere una risposta adeguata a cosa sta succedendo. Lasciami andare:

La mia configurazione è nginx/uwsgi. Ecco come sto facendo funzionare uwsgi utilizzando parvenu:

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 

Supponendo che chiedo la seguente API:

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

che corrisponde al seguente regola:

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

Ecco la vista di classe a base di:

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 [] 

La classe serializer:

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') 

E infine il classmethod 'get_most_viewed' (lo so che è sbagliato usare classmethods piuttosto che il metodo Manager)

@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')) 

Come si può vedere da tutto questo, si tratta di un normale richiesta viene reindirizzato alla vista designata, recuperando i dati da MySQL e quindi restituendo il risultato serializzato. Niente di straordinario o di elaborazione complessa.

Esecuzione:

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

Si noti che questo è senza caching. Il seguente è spesso registrato:

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) 

carico medio durante i test va fino a ~ 5. Ed ecco il risultato 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 

Prima di tutto, 7 richieste al secondo è molto deludente. ~ 1700 richieste non riuscite a causa di errori di timeout sono anche a causa del ritardo delle prestazioni che sto affrontando qui.

Per essere completamente onesti. Mi aspetto ~ 60 - 70 richieste al secondo senza cache. So che il caching accelera il processo ma nasconde anche i problemi di prestazioni che ho, motivo per cui sto cercando di risolverlo prima di mettere in cache le cose. ?

ho deciso quindi al profilo presente su una macchina vmware CentOS usando django-profiling, che con l'aggiunta prof alla richiesta mostra stack di chiamate:

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) 

E come si può vedere, la maggior parte del tempo viene speso su django views & viste DRF.

Qualcuno può far notare se sto facendo qualcosa di sbagliato qui? Perché le richieste sono così lente?Scala python/Django? Ho letto che lo fa, ma quante richieste/secondo dovrei aspettarmi su un semplice DB leggere l'operazione di rendering & come quella che sto facendo?

risposta

2

fa scala pitone/django

Django poteri alcuni servizi piuttosto massicce, come Disqus e Instagram, quindi sì, è in scala bene.

ho deciso quindi al profilo questo

Come si può vedere quasi tutto il tempo viene speso all'interno del metodo .get_most_viewed(), in modo che sembra il problema che hai. (potrebbe esserci di sbagliato lì, ma il tuo profilo suggerisce che 2.028 su 2.037 del tempo è trascorso lì, quindi circa il 99,6% delle volte)

Le mie abilità ORM non sono proprio all'altezza di capire esattamente come dovresti occuparsi di questa query abbastanza complessa e, in ogni caso, è necessario vedere le definizioni del modello, ma è necessario esaminare il debug e semplificare tale query, piuttosto che osservare altre parti della vista.

Si potrebbe desiderare di entrare nella shell di Django usando la shell di manage.py, in modo da poter tracciare quella particolare query in esclusione al resto della vista.

anche forse provare a ottenere qualche aiuto su come è possibile semplificare la query qui, o sul canale o Django Django mailing list IRC (È probabile avere più fortuna se si chiede specificamente su tale query, piuttosto che la più generale quadro/REST Django formulato domanda qui, la maggior parte dei quali in realtà non sembra essere rilevante per il problema vostro seeing.

Speranza che aiuta a puntare nella giusta direzione per ottenere questo risolto.

+0

Grazie. In realtà è correlato come sembra che prefetch_related sta caricando circa 7Mb di dati da mysql. Il problema è descritto qui: https://github.com/tomchristie/django-rest-framework/issues/656 e puoi anche controllare la conversazione sulla mailing list di restframework con il commento di Xavier su questo stesso identico problema. – Maverick

0

È usa la rievocazione precoce (come la lista (queryset)). Forse hai appena finito la memoria quando molti lavoratori concurrent server le tue richieste? Quindi devi decidere: veloce er risultati o più utilizzo della memoria (65 MB per richiesta? questo potrà mangiare tutta la memoria in secondi)

e profiler dice che il codice utilizza QuerySet.all(), che:

restituisce una copia della corrente QuerySet (o QuerySet sottoclasse).

E questo chiama deepcopy che richiede molto tempo.

Quindi trovare il luogo in cui viene chiamato all() e non utilizzarlo.

Problemi correlati