トップ «前の日記(08/18/2012) 最新 次の日記(09/01/2012)» 編集

本 日 の h o g e

hogeとはワイルドカードのようなものです。日々起こった、さまざまなこと −すなわちワイルドカード− を取り上げて日記を書く、という意味で名付けたのかというとそうでもありません。適当に決めたらこんな理由が浮かんできました。

更新情報の取得には rdflirs を使ってもらえると嬉しいです.


08/22/2012 ふむ [長年日記]

tDiary 3590日目

[Py][Tips] Python スクリプトのボトルネックを調査する

もう結構前の話だけれど,etherws を使っていて,「server -> client はそうでもないけど client -> server がやたら遅い」という現象を発見して,はて何でだろう? ということでボトルネックになっている箇所を調査した.

使うのは cProfile と pstats という 2 つのモジュール. これらをそれぞれプロファイリングと結果の表示に使う.

まず etherws を以下のようにして cProfile 機能 on で起動し,

# python -m cProfile -o etherws.prof etherws.py sw --foreground

VM 間を繋ぐ コレ と同じ環境を作り,しばらく全力で通信する.

etherws を Ctrl-C 等で停止すると,引数で指定した etherws.prof というファイルが転がっているので,pstats を使ってデータを表示する.

$ python -m pstats etherws.prof

インタラクティブシェルが起動するので,時間でソートして上位 10 件を表示してみる.

etherws.prof% sort time
etherws.prof% stats 10
Thu Aug 23 00:17:39 2012    etherws.prof

         4496160 function calls (4495690 primitive calls) in 471.329 seconds

   Ordered by: internal time
   List reduced from 965 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    41524  191.581    0.005  191.581    0.005 {method 'poll' of 'select.epoll' objects}
    41472  127.394    0.003  248.920    0.006 /usr/lib64/python2.7/site-packages/websocket.py:292(mask)
   124419  109.251    0.001  109.251    0.001 {map}
   124480   24.141    0.000   24.142    0.000 {method 'join' of 'str' objects}
    41603    4.311    0.000    4.311    0.000 {range}
    41472    2.042    0.000  267.134    0.006 /usr/lib64/python2.7/site-packages/websocket.py:288(_get_masked)
    41475    1.195    0.000    1.195    0.000 {method 'send' of '_socket.socket' objects}
    64106    0.612    0.000  272.782    0.004 etherws.py:220(send)
    64106    0.582    0.000  276.070    0.004 etherws.py:244(_forward)
    41472    0.566    0.000  268.295    0.006 /usr/lib64/python2.7/site-packages/websocket.py:258(format)

まぁ epoll とかはしょうがないとして,気になるのは以下で,呼び出し回数 (ncalls) の割に消費時間 (tottime) や下位の関数呼び出しも含めた消費時間 (cumtime) が多い.

41472  127.394    0.003  248.920    0.006 /usr/lib64/python2.7/site-packages/websocket.py:292(mask)

で,websocket.py の該当箇所を読んでみると,

@staticmethod
def mask(mask_key, data):
    """
    mask or unmask data. Just do xor for each byte

    mask_key: 4 byte string(byte).

    data: data to mask/unmask.
    """
    _m = map(ord, mask_key)
    _d = map(ord, data)
    for i in range(len(_d)):
        _d[i] ^= _m[i % 4]
    s = map(chr, _d)
    return "".join(s)

WebSocket プロトコルのマスクを行う箇所のようで,data が個々のフレームを指しているようだ.

確かにこの処理内容だとフレームのコピーが数回発生することになる. Ether フレーム 1 個につきこれが毎度呼ばれると考えると,通信速度に影響してきそうだ,ということが分かる.

そこで何とかならんかなと色々試した挙げ句,以下の様な改造を施すことで,速度を大体 1.25 倍くらいには改善することができた. 1.25 倍というのは例えば 500Mbps を 625Mbps にするということで,たった数行の改造によって得られる効果としては充分だろう.

@@ -23,6 +23,7 @@
 import socket
 from urlparse import urlparse
 import os
+import array
 import struct
 import uuid
 import hashlib
@@ -309,12 +310,11 @@

         data: data to mask/unmask.
         """
-        _m = map(ord, mask_key)
-        _d = map(ord, data)
-        for i in range(len(_d)):
+        _m = array.array("B", mask_key)
+        _d = array.array("B", data)
+        for i in xrange(len(_d)):
             _d[i] ^= _m[i % 4]
-        s = map(chr, _d)
-        return "".join(s)
+        return _d.tostring()

 class WebSocket(object):
    """

...というのを pull request していたのだけれど,merge して頂けたようなので (ありがとうございます),その経緯を書いてみた次第.

ちなみに「server -> client はそうでもないけど client -> server がやたら遅い」という非対称性は WebSocket プロトコルの問題 (client -> server 通信時はデータをマスクすることが MUST だが逆はマスクしてはいけない) だったので解決不能だった :-P