profiling and finding bottleneck of a flask application --- current respond time is 30 second

Question

My Flask application suddenly become very very slow for the past month and I have no idea what changes has boost the respond time from under 1s to 30s.

I've been using Flask with MongoEngine, Redis is also used for cache. The MongoDB is placed on the same server as Flask app.

I tried profiling the Flask, and here are the report:

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)

Can anyone point me a direction for finding the bottleneck, or a more helpful profiling way?

http://docs.mongodb.org/manual/tutorial/manage-the-database-profiler/ for mongodb query profiling. — Ross, Feb 17 '14 at 16:21
You could also take [*a single stackshot*](http://stackoverflow.com/a/4299378/23771) and it will tell you everything there is to know about what is taking the time (with 29/30 = 97% probability). — Mike Dunlavey, Feb 24 '14 at 17:28
This question is closed so I can't add a new answer, but anyone landing on this - there is now a [line profiling tool _specifically_ for Flask now](https://github.com/jlfwong/flask_debugtoolbar_lineprofilerpanel) rather than battling with the standard line_profiler. — roganjosh, Jun 13 '18 at 14:48
@roganjosh Unfortunately, it looks likes this tool doesn't work with flask-restful (flask used for only API) — Lokesh, Oct 16 '19 at 10:03
@roganjosh Unfortunately, it looks likes this tool doesn't work with flask-restful (flask used for only API) — Lokesh, Oct 16 '19 at 10:04

score 13 · Answer 1 · answered Feb 17 '14 at 19:48

Your 30 seconds were spent on 153 calls to sock.recv, each taking roughly 0.2 seconds.

What you need to find out now is who is calling this function, and for that you need the call graph report from the profiler. Unfortunately the call graph is not included in the summary output from the Werkzeug profiler middleware, but if you use the profile_dir argument you can have the profile data saved to a file.

Once you have a data file you can get the call graph with a short Python script follows:

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

The print_stats() call prints the same report you get from Werkzeug. The print_callers() call prints the corresponding call graph. The output is going to be long, so you should redirect it to a file.

If looking at text reports is not your thing, then you can use gprof2dot to generate a GraphViz graph from the same data.

Hope this helps.

score 8 · Answer 2 · answered Feb 17 '14 at 12:19

8

http://pythonhosted.org/line_profiler/

Here is a tutorial for using two profiling tools which helped me in a similar case.

answered Feb 17 '14 at 12:19

Bartosz Marcinkowski

6,651
4
39
69

5

This question is closed so I can't add a new answer, but anyone landing on this - there is now a [line profiling tool _specifically_ for Flask now](https://github.com/jlfwong/flask_debugtoolbar_lineprofilerpanel) rather than battling with the standard line_profiler. – roganjosh Jun 13 '18 at 14:50
Snakeviz is another tool you might want to consider. A simple "pip install" and you have an interactive graph of where your bottlenecks are. Very nice. – JimmidyJoo Jul 16 '18 at 15:40

profiling and finding bottleneck of a flask application --- current respond time is 30 second

2 Answers2