ページ

2011年2月4日

gevent_request_profilerを試してみたよ

gevent_request_profilerを試してみました。wsgiアプリケーションのhttpサーバをgeventを使って動かしていると、時々何かがブロックしているかも?って言うときがあります。また、ブロックしなくても、各処理にどれくらいの時間がかかっているのかプロファイルしたいことがよくあります。グリーンスレッドだと、何かが長時間ブロックするすると、他の処理がすべて待たされるので深刻です。普通のプロファイラだと、グリーンスレッドの本当の実行時間を教えてくれません。それをためのプロファイラです。まあ、greenletがどういう風に処理を実行しているのか垣間見れるのも面白いです。

さて、インストールですが、githubからチェックアウトして、インストールしました。そのたと、次のもっとも単純そうなコードを実行します。

from gevent import monkey
monkey.patch_all()

from tellapart.frontend import gevent_profiler
profiler = gevent_profiler.Profiler(request_profiling_pct=1.0)

from gevent import wsgi

def app(environ, start_response):
    path = environ["PATH_INFO"]
    if path == "/":
        start_response("200 OK", [("Content-Type", "text/html")])
        return "Hello, Profiler"

    start_response("404 Not Found", [])
    return []

if __name__ == "__main__":
    server = wsgi.WSGIServer(("", 5000), app)#, handler_class=WebSocketHandler)
    try:
        server.serve_forever()
    except KeyboardInterrupt:
        server.stop()
profilerのオブジェクトを作るときにgevent.wsgiをいじくったりするので、profilerのオブジェクトを作った後にgevent.wsgiをロードしないといけません。実行結果は、
>>> Begin RequestProfile
  Path: /
  Start time: 2011-02-04 05:35:31.300684 UTC
  End time: 2011-02-04 05:35:31.302821 UTC
  Elapsed wall time: 2.1 ms
  Elapsed CPU time: 0.8 ms
  Number of spans: 1
  Longest span CPU time: 0.8 ms
Span(
  greenlet_id=1,
  start_time=1296797731300.7,
  end_time=1296797731301.5,
  duration=0.8 ms,
  finished=True,
  fn_name=gevent.wsgi.WSGIServer.handle,
  stack_trace=  File "/Users/hiro/.virtualenvs/main/lib/python2.7/site-packages/tellapart_gevent_profiler-0.5-py2.7.egg/tellapart/frontend/gevent_profiler.py", line 274, in run
    ProfilingGreenlet._HUB._record_execution_span(self)
  File "/Users/hiro/.virtualenvs/main/lib/python2.7/site-packages/tellapart_gevent_profiler-0.5-py2.7.egg/tellapart/frontend/gevent_profiler.py", line 200, in _record_execution_span
    traceback.extract_stack(), finished)
)
<<< End RequestProfile

スレッドが一つだけなので、単純です。処理時間も見えるので素敵です。次に、グリーンスレッドを作って実行してみます。
import gevent
from gevent import monkey
monkey.patch_all()

from tellapart.frontend import gevent_profiler
profiler = gevent_profiler.Profiler(request_profiling_pct=1.0)

from gevent import wsgi

def loop():
    x = 0
    for i in range(100*10000):
        x += i
    #gevent.sleep(0)
    for i in range(100*10000):
        x += i
        

def app(environ, start_response):
    path = environ["PATH_INFO"]
    if path == "/":
        gevent.spawn(loop)
        gevent.joinall([gevent.spawn(loop) for _ in range(3)])
        start_response("200 OK", [("Content-Type", "text/html")])
        return "Hello, Profiler"

    start_response("404 Not Found", [])
    return []

if __name__ == "__main__":
    server = wsgi.WSGIServer(("", 5000), app)#, handler_class=WebSocketHandler)
    try:
        server.serve_forever()
    except KeyboardInterrupt:
        server.stop()
実行した結果は

>>> Begin RequestProfile
  Path: /
  Start time: 2011-02-04 08:17:11.701029 UTC
  End time: 2011-02-04 08:17:14.698614 UTC
  Elapsed wall time: 2997.6 ms
  Elapsed CPU time: 2989.4 ms
  Number of spans: 6
  Longest span CPU time: 1749.7 ms
Span(
  greenlet_id=1,
  start_time=1296807431701.0,
  end_time=1296807431706.3,
  duration=5.3 ms,
  finished=False,
  fn_name=gevent.wsgi.WSGIServer.handle,
  [snip]
)
Span(
  greenlet_id=2,
  start_time=1296807431712.1,
  end_time=1296807433461.7,
  duration=1749.7 ms,
  finished=True,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=3,
  start_time=1296807433462.9,
  end_time=1296807433829.8,
  duration=366.9 ms,
  finished=True,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=4,
  start_time=1296807433830.0,
  end_time=1296807434345.0,
  duration=515.0 ms,
  finished=True,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=5,
  start_time=1296807434345.3,
  end_time=1296807434687.5,
  duration=342.3 ms,
  finished=True,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=1,
  start_time=1296807434688.3,
  end_time=1296807434698.4,
  duration=10.1 ms,
  finished=True,
  fn_name=gevent.wsgi.WSGIServer.handle,
  [snip]
<<< End RequestProfile
スレッドが順番に実行されているのがわかります。スタックトレースは長いので削ってあります。loopメソッドの中は一気に処理が進むので、gevent.sleepを実行して、CPUを他のスレッドに渡してあげます(gevent.sleepのコメントを外す)。その結果が次です。

>>> Begin RequestProfile
  Path: /
  Start time: 2011-02-04 08:18:17.436797 UTC
  End time: 2011-02-04 08:18:18.885329 UTC
  Elapsed wall time: 1448.5 ms
  Elapsed CPU time: 1440.1 ms
  Number of spans: 10
  Longest span CPU time: 216.0 ms
Span(
  greenlet_id=1,
  start_time=1296807497436.8,
  end_time=1296807497444.1,
  duration=7.3 ms,
  finished=False,
  fn_name=gevent.wsgi.WSGIServer.handle,
  [snip]
)
Span(
  greenlet_id=2,
  start_time=1296807497449.6,
  end_time=1296807497654.6,
  duration=205.0 ms,
  finished=False,
  fn_name=__main__.loop,
  [snip] 
)
Span(
  greenlet_id=3,
  start_time=1296807497654.9,
  end_time=1296807497832.5,
  duration=177.6 ms,
  finished=False,
  fn_name=__main__.loop,
    [snip]
)
Span(
  greenlet_id=4,
  start_time=1296807497833.1,
  end_time=1296807498049.1,
  duration=216.0 ms,
  finished=False,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=5,
  start_time=1296807498049.5,
  end_time=1296807498217.7,
  duration=168.2 ms,
  finished=False,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=2,
  start_time=1296807498218.2,
  end_time=1296807498383.1,
  duration=164.9 ms,
  finished=True,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=5,
  start_time=1296807498383.3,
  end_time=1296807498548.7,
  duration=165.4 ms,
  finished=True,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=4,
  start_time=1296807498548.9,
  end_time=1296807498714.2,
  duration=165.3 ms,
  finished=True,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=3,
  start_time=1296807498714.4,
  end_time=1296807498878.7,
  duration=164.3 ms,
  finished=True,
  fn_name=__main__.loop,
  [snip]
)
Span(
  greenlet_id=1,
  start_time=1296807498879.0,
  end_time=1296807498885.1,
  duration=6.2 ms,
  finished=True,
  fn_name=gevent.wsgi.WSGIServer.handle,
  [snip]
)
<<< End RequestProfile
finishedがFalseになっているものは、gevent.sleepでスレッドが切り替わったものです。それぞれの処理の実行時間が分かります。グラフィカルに見えるように処理すればもっとかっこいいのですが･･･。stack_traceのところをみれば、コードのどこでスレッドが切り替わったのかも分かります。wsgiのリクエストだけプロファイルできますが、なかなかいい感じかも。
このエントリーを含むはてなブックマーク Add to Delicious Bookmark この記事をクリップ！ 投稿者 Hiroki Ohtani ラベル: ,
リアクション: 

0 コメント:

コメントを投稿

登録: コメントの投稿 (Atom)