GoogleAppEngineのサーバサイドの処理時間をProfileで表示させる為にcProfile使う
Python旅館ネタ。これまた、tmatsuo氏に教えてもらた。
googleAppEngine内で、何の処理にドンだけ時間が掛かってるとか、どの処理が何回呼ばれてるとかそういうのが知りたい時にprofileを使うとある程度分かります。
やり方は凄い簡単で、デフォで使ってるmainメソッドを、real_mainメソッドに改名してprofile_main()から呼ぶだけ、profile_main()内では、＜pre＞タグ使ってhtmlを追加する処理が書いてあるのでみたい要素をprintするだけです。この方法の他にLoggingに回す方法もあるらしいです。
def main(): logging.getLogger().setLevel(logging.DEBUG) logging.info('-'*80) urls = [('/ngram/api/post', UpDate), ('/ngram/api/search', Search), ('/ngram/api/get/wassr', getWassr), ('/ngram/api/make/wassrIndex', mkWassrIndex), ('/ngram.*', Index)] application = webapp.WSGIApplication(urls, debug=True) wsgiref.handlers.CGIHandler().run(application) if __name__ == '__main__': main()
良くある感じで、例えばこんな状態で、mainが定義されてて呼ばれてます。
そこに対して、以下のように
- main()をreal_main()に改名
- profile_main()を適宜追加する
- 呼出をmain()からprofile_main()に変更する
たったこれだけです。
def real_main(): logging.getLogger().setLevel(logging.DEBUG) logging.info('-'*80) urls = [('/ngram/api/post', UpDate), ('/ngram/api/search', Search), ('/ngram/api/get/wassr', getWassr), ('/ngram/api/make/wassrIndex', mkWassrIndex), ('/ngram.*', Index)] application = webapp.WSGIApplication(urls, debug=True) wsgiref.handlers.CGIHandler().run(application) def profile_main(): # This is the main function for profiling # We've renamed our original main() above to real_main() import cProfile, pstats prof = cProfile.Profile() prof = prof.runctx("real_main()", globals(), locals()) print "<pre id='profile'>" stats = pstats.Stats(prof) stats.sort_stats("call") # Or cumulative stats.print_stats(10) # 80 = how many to print print "-"*80 stats.sort_stats("time") # Or cumulative stats.print_stats(10) # 80 = how many to print # The rest is optional. stats.print_callees() stats.print_callers() print "</pre>"
上記例では、 stats.sort_stats("call")と stats.sort_stats("time")を使ってそれぞれソートし直して10個ずつ表示させています。また、 stats.print_callees()と stats.print_callers()で、どのメソッドが何を呼んでいるのかが分かります。
なんにも処理してないですが、こんな風に表示されます
1664 function calls (1621 primitive calls) in 0.203 CPU seconds
Ordered by: call count
List reduced from 373 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
109 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects}
100 0.000 0.000 0.000 0.000 {len}
62 0.000 0.000 0.000 0.000 /Applications/MyApp/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/tools/dev_appserver.py:972()
60 0.000 0.000 0.000 0.000 {method 'append' of 'array.array' objects}
56 0.000 0.000 0.000 0.000 /Applications/MyApp/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/net/proto/ProtocolBuffer.py:294(putVarInt32)
55 0.000 0.000 0.000 0.000 {method 'join' of 'str' objects}
54 0.000 0.000 0.000 0.000 {method 'startswith' of 'str' objects}
38 0.000 0.000 0.000 0.000 /Applications/MyApp/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/tools/dev_appserver.py:1011(log)
37 0.000 0.000 0.000 0.000 {method 'extend' of 'list' objects}
35/22 0.000 0.000 0.000 0.000 {getattr}
--------------------------------------------------------------------------------
1664 function calls (1621 primitive calls) in 0.203 CPU seconds
Ordered by: internal time
List reduced from 373 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.105 0.105 0.105 0.105 {method 'read' of 'file' objects}
2 0.090 0.045 0.090 0.045 {imp.load_module}
1 0.002 0.002 0.002 0.002 /Applications/MyApp/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/webapp/__init__.py:521(_init_url_mappings)
6 0.001 0.000 0.001 0.000 {imp.find_module}
18/4 0.000 0.000 0.092 0.023 /Applications/MyApp/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/tools/dev_appserver.py:969(decorate)
1 0.000 0.000 0.001 0.001 /Applications/MyApp/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/api/datastore_file_stub.py:349(__WritePickled)
1 0.000 0.000 0.000 0.000 {posix.rename}
37 0.000 0.000 0.000 0.000 {method 'extend' of 'list' objects}
1 0.000 0.000 0.000 0.000 {posix.tempnam}
62 0.000 0.000 0.000 0.000 /Applications/MyApp/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/tools/dev_appserver.py:972()
これで、ローカルではサクサクなのにappspot.comに上げたらメチャ重くなったとかそういう時にどこがボトルネックになっているのかある程度特定できるようになります。
