Profilierung und bei der Suche Engpass einer Kolben Anwendung --- Strom reagiert Zeit ist 30 Sekunden

Question

Meine Flask Anwendung plötzlich sehr, sehr langsam für den letzten Monat worden, und ich habe keine Ahnung, was die respond Zeit von unter 1 s steigert verändert hat bis 30s.

Ich habe Flask mit MongoEngine verwendet, Redis wird auch für Cache verwendet. Die MongoDB befindet sich auf demselben Server wie die Flask-App.

Ich versuchte, die Flask Profilierungs, und hier sind in dem Bericht:

127.0.0.1 - - [17/Feb/2014 19:51:47] "GET/HTTP/1.0" 200 - 
-------------------------------------------------------------------------------- 
PATH: '/items' 
     637497 function calls (618866 primitive calls) in 30.961 seconds 

    Ordered by: internal time, call count 
    List reduced from 702 to 30 due to restriction <30> 

    ncalls tottime percall cumtime percall filename:lineno(function) 
     153 30.127 0.197 30.127 0.197 {method 'recv' of '_socket.socket' objects} 
    319965 0.150 0.000 0.150 0.000 {isinstance} 
1322/740 0.079 0.000 0.178 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/dereference.py:147(_attach_objects) 
     77 0.079 0.001 0.079 0.001 {method 'sendall' of '_socket.socket' objects} 
1322/740 0.077 0.000 0.159 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/dereference.py:68(_find_references) 
    54670 0.046 0.000 0.046 0.000 {hasattr} 
    774/80 0.032 0.000 0.207 0.003 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/base/document.py:539(_from_son) 
     774 0.031 0.000 0.119 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/base/document.py:35(__init__) 
12932/12792 0.028 0.000 0.057 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/base/document.py:113(__setattr__) 
    15557 0.016 0.000 0.020 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/common.py:4(_import_class) 
    46648 0.016 0.000 0.016 0.000 {method 'get' of 'dict' objects} 
    8228 0.015 0.000 0.029 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/base/fields.py:94(__set__) 
1532/287 0.012 0.000 0.161 0.001 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/base/fields.py:233(to_python) 
    11901 0.012 0.000 0.061 0.000 {setattr} 
    8960 0.010 0.000 0.010 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/base/document.py:547(<genexpr>) 
15629/5700 0.010 0.000 0.022 0.000 /usr/lib/python2.7/json/encoder.py:335(_iterencode_dict) 
3328/3207 0.009 0.000 0.019 0.000 /usr/lib/python2.7/copy.py:145(deepcopy) 
    685/61 0.008 0.000 0.032 0.001 /home/deploy/shopping/env/local/lib/python2.7/site-packages/pymongo/cursor.py:843(__deepcopy) 
    3660 0.008 0.000 0.024 0.000 /usr/lib/python2.7/copy.py:66(copy) 
10295/5668 0.008 0.000 0.019 0.000 /usr/lib/python2.7/json/encoder.py:282(_iterencode_list) 
     424 0.007 0.000 0.361 0.001 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/base/fields.py:189(__get__) 
     740 0.007 0.000 0.348 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/dereference.py:12(__call__) 
     660 0.006 0.000 0.008 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/base/datastructures.py:15(__init__) 
     72 0.005 0.000 0.007 0.000 {bson._cbson.decode_all} 
     183 0.005 0.000 0.034 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/queryset/base.py:533(clone_into) 
     241 0.005 0.000 0.023 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/queryset/transform.py:31(query) 
     694 0.005 0.000 0.114 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/document.py:64(__init__) 
     900 0.004 0.000 0.004 0.000 {sorted} 
5388/5387 0.004 0.000 0.007 0.000 {getattr} 
    5940 0.004 0.000 0.004 0.000 /home/deploy/shopping/env/lib/python2.7/site-packages/mongoengine/fields.py:241(to_python) 

Kann mir jemand für die Suche nach dem Engpass eine Richtung weisen, oder eine hilfreiche Profilierung Art und Weise?

Answer 1

http://pythonhosted.org/line_profiler/

ist hier ein Tutorial zwei Profilierwerkzeuge für die Verwendung, die mir in einem ähnlichen Fall geholfen.

Answer 2

Ihre 30 Sekunden wurden für 153 Anrufe an sock.recv ausgegeben, die jeweils ungefähr 0,2 Sekunden dauern.

Was Sie jetzt herausfinden müssen, ist wer diese Funktion aufruft, und dafür benötigen Sie den Call Graph Report vom Profiler. Leider ist das Aufrufdiagramm nicht in der Zusammenfassungsausgabe der Werkzeug Profiler Middleware enthalten, aber wenn Sie das Argument profile_dir verwenden, können Sie die Profildaten in einer Datei speichern.

Sobald Sie eine Datendatei haben Sie die Aufrufdiagramm mit einem kurzen Python-Skript bekommen folgt:

import pstats 
stats = pstats.Stats('tmp/GET.root.000255ms.1392663371.prof') 
stats.sort_stats('time', 'calls') 
stats.print_stats() 
stats.print_callers() 

Die print_stats() Aufruf druckt den gleichen Bericht, den Sie von Werkzeug zu bekommen. Der Aufruf print_callers() druckt das entsprechende Aufrufdiagramm. Die Ausgabe wird lang sein, also sollten Sie sie in eine Datei umleiten.

Wenn Sie sich keine Textberichte ansehen, können Sie gprof2dot verwenden, um ein GraphViz-Diagramm aus denselben Daten zu erstellen.

Hoffe, das hilft.