マルチプロセスなPythonプログラムをざっくりプロファイルしてChromeの開発者ツールで見る話。あとSpotify。

この記事は undefined Advent Calendar 5日目の記事です。昨日の担当はundefinedさんでした。今年はなにも参加してないんですよね。

ちなみに前回の記事は去年のアドベントカレンダーですね。こちらもどうぞ。

unarist.hatenablog.com

なにも発信してないと死んだかと思われそうなので*1なんか書こうという話です。

マルチプロセスなPythonプログラムを以下略

気がついたらお仕事で使う言語がScalaからPythonに変わってました*2。NumPyとかPandasとかMatplotlibとかで遊んでます。

で、n個のデータをmプロセスで処理するみたいなのを書いてたら、なんかよくわからん遅くなりかたをして、なんか可視化したいなーと思ったのが事の始まりです。細かいプロファイルを取りたいというより、大きなカタマリがいつどのデータを扱ってるんや、みたいなのが見たかったわけですね。

可視化の方法やツールをあれこれ考えた結果、JSっ子なので、Chromeの開発者ツールが使えないかなと思いたちました。いわゆるFlameGraphと呼ばれる、スタックフレームを積み上げたグラフです。かつこの実装は、スクロールや拡大縮小もスムーズだし、スレッド違いで複数のグラフを並べて表示できるし、各イベントの属性みたいなのも出せるし。

特にこのツール、JSON形式でインポート・エクスポートができるので、この形式のJSONをこしらえてやれば、データだけ自作することもできるはずです。

Trace Event Format

だいぶ古い（2016年）資料ですが、Chromeの開発チームが作った資料*3があります。 https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit

色々書いてありますが、今回の話をする上で最低限の構造はだいたいこんなです。

[
    { "pid":1, "tid":1, "ts":1000, "dur":10000, "ph":"X", "name":"hoge", "args":{ } },
    { "pid":1, "tid":1, "ts":2000, "dur":4000, "ph":"X", "name":"piyo", "args":{ } },
    { "pid":1, "tid":1, "ts":5000, "dur":7000, "ph":"X", "name":"piyo", "args":{ } },
    { "pid":"p2", "tid":"t2", "ts":3000, "dur":10000, "ph":"X", "name":"hoge", "args":{ "foo": "bar", "hoge":1 } }
]

とりあえずこれを test.json とか適当なファイル名で保存して、開発者ツールのPerformanceタブでインポートしてみましょう。そんな感じです。ほかに chrome://tracing や https://ui.perfetto.dev/ でも読めて、それぞれちょっと操作感が違います。

phがイベントの種類で、Xは Complete Event を表す
- 始点と終点を記録する Duration Event に対して、1イベントで始点と継続時間を記録するのが Complete Event
- 他にも色々あるので、詳しくは前掲の資料を眺めつつ試してみるとよいです
- パフォーマンス計測に困らない！tracing活用術100 - Qiita みたいな話も把握しておくといいのかもしれない（さっき見つけた）
pidとかtidとかargsの値は数値でも文字列でもよい
時間の単位はマイクロ秒

Pythonで吐き出す

話を戻してPythonでこれを作りたいわけです。作るだけですね。例えば、こう…。

import contextlib
import os
import time

class Profiler:
    def __init__(self, pid = None, tid = 0) -> None:
        self.buf = []
        self.pid = pid if pid is not None else os.getpid()
        self.tid = tid

    @contextlib.contextmanager
    def duration(self, name: str, **args):
        st = time.time()
        yield None
        self.buf.append({"ph": "X", "ts": st * 1000000, "dur": (time.time() - st) * 1000000, "name": name, "args": args})
    
    def to_list(self):
        return [{"pid": self.pid, "tid": self.tid, **item} for item in self.buf]

んでこんな感じに使ってみます。

from time import sleep
from profiler import Profiler
import json
from multiprocessing import Pool

def proc(init_t: int, interval_t: int, count: int):
    prof = Profiler()
    with prof.duration("proc", init_t=init_t, interval_t=interval_t, count=count):
        sleep(init_t)
        for i in range(count):
            with prof.duration(f"step {i}"):
                sleep(interval_t)
    return prof.to_list()
    

if __name__ == '__main__':
    results = Pool(4).starmap(proc, [(0, 1, 5), (0, 1, 5), (2, 1, 5), (5, 1, 5)] * 2, 1)
    with open("./prof.json", "w", encoding="utf-8") as w:
        json.dump([item for result in results for item in result], w)

4プロセスに処理時間の異なる8ジョブ突っこんでどんな感じに実行されるのかな？てのがこう、一目瞭然になります。べんり。

実際には返り値は別の用途に使いたいとか、map使わないから返すのめんどいとかあるやもしれません。最終的にひとつのJSON配列になればいいので、例えばワーカープロセスごとにJSONファイルに書き出してしまうとかもありです。そうしました。

あと上記例ではプロセスIDは素直にpidに入れていますが、プロセス→スレッドの階層で畳める必要がないならpidは固定にしてtidで分けた方が展開が楽&タイムライン間の隙間が減って縦の密度を上げられます。

ほかにも遊びかたを見つけたら Scrapbox の方に書き足すかもしれません。

ちなみにこの手法で調べたお仕事のやつですが、未だに遅い原因はわかってないです。かなしい。

追記 2023/01/30 中の人がもうちょっと真面目に作ってた。ですよね。

GitHub - natduca/py_trace_event: Python performance tracing

2022年のSpotify

こんな感じでした。さもありなん。分布とかもうちょっと自由に見れると遊べるのだけど。

せやなー pic.twitter.com/udY5C3GCNV
— (@unarist) 2022年11月30日

スマホ音ゲーとか2次元アイドルものは本当に多かった。聞いた数も多かったし、こんなにあるのかとびっくりした。Re:ステージ！とSB69は続投。D4DJは今年はまった。エビストはナナシスと合わせて最近やっと曲を聞きはじめたけど、これらもよい。あと今年はラピスリライツなんてのもあったんですが…あったんですが……最近サービス終了してしまった*4。曲は今でも聞けますどうぞ。あとはプリパラなんかも結構聞いてた気がする。アイドルものではないけれど、アサルトリリィの曲もぼちぼち聞いた。

この辺はどれもSpotifyでたまたま見つけて、アニメやゲームの方にも手を出した、みたいなのが多いので、なかなかSpotifyの恩恵は大きかったと言えよう。

全然別の系統で今年触れたアーティストとしては、ザバダック、さよならポニーテール、名取さな、加藤和彦などなど……雑多だねえ。