2014-02-17 65 views
5

我的燒瓶應用程序突然變爲非常非常慢過去一個月,我不知道什麼變化提高了從1s以下的響應時間到30秒分析和查找燒瓶應用程序的瓶頸---當前響應時間爲30秒

我一直在使用Flask和MongoEngine,Redis也用於緩存。 MongoDB與Flask應用程序放在同一臺服務器上。

我試圖剖析燒瓶中,這裏是報告:

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) 

任何人都可以點我的方向尋找瓶頸,或更有幫助的分析方法是什麼?

+0

http://docs.mongodb.org/manual/tutorial/manage-the-database-profiler/用於mongodb查詢分析。 – Ross

+0

你也可以採取[*一個stackshot *](http://stackoverflow.com/a/4299378/23771),它會告訴你一切要知道什麼是花時間(29/30 = 97 %概率)。 –

回答

7

你花了30秒花費了153個電話到sock.recv,每個花費大約0.2秒。

您現在需要了解的是誰在調用此函數,並且您需要來自Profiler的調用圖報告。不幸的是,調用圖不包含在Werkzeug分析器中間件的彙總輸出中,但如果使用參數profile_dir,則可以將配置文件數據保存到文件中。

一旦你有一個數據文件,你可以用很短的Python腳本調用圖如下:

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

print_stats()調用打印你從WERKZEUG獲得相同的報告。調用print_callers()將打印相應的調用圖。輸出將會很長,所以你應該把它重定向到一個文件。

如果查看文本報告不是您的事情,那麼您可以使用gprof2dot從相同的數據生成GraphViz圖。

希望這會有所幫助。