読者です 読者をやめる 読者になる 読者になる

When it’s ready.

出来るまで出来ない

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が定義されてて呼ばれてます。

そこに対して、以下のように

  1. main()をreal_main()に改名
  2. profile_main()を適宜追加する
  3. 呼出を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に上げたらメチャ重くなったとかそういう時にどこがボトルネックになっているのかある程度特定できるようになります。