本 日 の h o g e

■ [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