【Nim】FlameGraphを使ったプロファイル結果の可視化

やりたいこと

 Nim言語を実行した際に、どの処理にどれだけ掛かっているかを把握して処理高速化の目途付けが出来るようにしたい
 具体的には以下のような出力が欲しい
 (縮小して小さいですが、クリック等で操作できるはず)

Flame Graph Reset Zoom Search ic all (11,803 samples, 100%) +%(arithmetics) (10 samples, 0.08%) op(rco_contest_2018_qual_A) (980 samples, 8.30%) op(rco_cont.. op1`gensym23(segtree) (1,341 samples, 11.36%) op1`gensym23(seg.. <=%(comparisons) (224 samples, 1.90%) <.. preProcessing(rco_contest_2018_qual_A) (6 samples, 0.05%) <%(comparisons) (15 samples, 0.13%) cmp(system) (163 samples, 1.38%) newObjNoInit(gc) (977 samples, 8.28%) newObjNoIni.. genericAssign(assign) (4,084 samples, 34.60%) genericAssign(assign) readLine(io) (4 samples, 0.03%) <%(comparisons) (13 samples, 0.11%) interiorAllocatedPtr(alloc) (86 samples, 0.73%) -%(arithmetics) (5 samples, 0.04%) anonymous(rco_contest_2018_qual_A) (26 samples, 0.22%) <%(comparisons) (8 samples, 0.07%) solve(rco_contest_2018_qual_A) (11,788 samples, 99.87%) solve(rco_contest_2018_qual_A) +%(arithmetics) (80 samples, 0.68%) rawDealloc(alloc) (85 samples, 0.72%) getSize(bitset) (47 samples, 0.40%) freeBigChunk(alloc) (10 samples, 0.08%) interiorAllocatedPtr(alloc) (21 samples, 0.18%) freeBigChunk(alloc) (38 samples, 0.32%) +%(arithmetics) (23 samples, 0.19%) <%(comparisons) (6 samples, 0.05%) <=%(comparisons) (282 samples, 2.39%) <.. <=%(comparisons) (21 samples, 0.18%) max=(macros) (35 samples, 0.30%) <=%(comparisons) (276 samples, 2.34%) <.. +%(arithmetics) (51 samples, 0.43%) cellToUsr(gc) (337 samples, 2.86%) ce.. incRef(gc) (5 samples, 0.04%) <%(comparisons) (5 samples, 0.04%) update(segtree) (1,452 samples, 12.30%) update(segtree) all_prod(segtree) (52 samples, 0.44%) decRef(gc) (75 samples, 0.64%) +%(arithmetics) (107 samples, 0.91%) newObjNoInit(gc) (523 samples, 4.43%) newOb.. <%(comparisons) (8 samples, 0.07%) <%(comparisons) (186 samples, 1.58%) align(system) (173 samples, 1.47%) add(avltree) (56 samples, 0.47%) interiorAllocatedPtr(alloc) (22 samples, 0.19%) getBitDivMod(bitset) (513 samples, 4.35%) getBi.. genericAssignAux(assign) (3,700 samples, 31.35%) genericAssignAux(assign) rawDealloc(alloc) (10 samples, 0.08%) +%(arithmetics) (5 samples, 0.04%) <=%(comparisons) (94 samples, 0.80%) <%(comparisons) (557 samples, 4.72%) <%(co.. -%(arithmetics) (18 samples, 0.15%) addChunkToMatrix(alloc) (6 samples, 0.05%) <=(system) (303 samples, 2.57%) <=.. <=%(comparisons) (1,944 samples, 16.47%) <=%(comparisons) usrToCell(gc) (6 samples, 0.05%) <%(comparisons) (83 samples, 0.70%) add(avltree) (12 samples, 0.10%) *%(arithmetics) (94 samples, 0.80%) readLine(io) (4 samples, 0.03%) mappingInsert(alloc) (6 samples, 0.05%) +%(arithmetics) (170 samples, 1.44%) genericAssignAux(assign) (3,980 samples, 33.72%) genericAssignAux(assign) <=(system) (16 samples, 0.14%) genericAssignAux(assign) (2,993 samples, 25.36%) genericAssignAux(assign) -%(arithmetics) (4 samples, 0.03%) del(avltree) (47 samples, 0.40%) decRef(gc) (22 samples, 0.19%) +%(arithmetics) (469 samples, 3.97%) +%(a.. set(segtree) (1,600 samples, 13.56%) set(segtree) decRef(gc) (5 samples, 0.04%) isOnStack(gc_common) (276 samples, 2.34%) i.. getSize(bitset) (187 samples, 1.58%) -%(arithmetics) (9 samples, 0.08%) del(avltree) (12 samples, 0.10%) cellToUsr(gc) (51 samples, 0.43%) cellToUsr(gc) (80 samples, 0.68%) rco_contest_2018_qual_A(rco_contest_2018_qual_A) (11,803 samples, 100.00%) rco_contest_2018_qual_A(rco_contest_2018_qual_A) setInput(rco_contest_2018_qual_A) (9 samples, 0.08%) <=%(comparisons) (22 samples, 0.19%) add(avltree) (49 samples, 0.42%) +%(arithmetics) (42 samples, 0.36%) <%(comparisons) (115 samples, 0.97%) <%(comparisons) (9 samples, 0.08%) +%(arithmetics) (12 samples, 0.10%) <%(comparisons) (8 samples, 0.07%) -%(arithmetics) (6 samples, 0.05%) <=%(comparisons) (47 samples, 0.40%) get(segtree) (84 samples, 0.71%) cmp(system) (10 samples, 0.08%) cellToUsr(gc) (107 samples, 0.91%) -%(arithmetics) (6 samples, 0.05%) del(avltree) (20 samples, 0.17%) anonymous(macros) (9 samples, 0.08%) <%(comparisons) (10 samples, 0.08%) <%(comparisons) (7 samples, 0.06%) +%(arithmetics) (11 samples, 0.09%) getBitDivMod(bitset) (167 samples, 1.41%) mappingInsert(alloc) (28 samples, 0.24%) count(strutils) (6 samples, 0.05%) (bitutils) (175 samples, 1.48%) </span>(bitset) (1,035 samples, 8.77%) (bitset) op(<a class="keyword" href="https://d.hatena.ne.jp/keyword/rco">rco</a>_contest_2018_qual_A) (35 samples, 0.30%) %(macros) (46 samples, 0.39%) find(strutils) (6 samples, 0.05%) <<(macros) (80 samples, 0.68%) decRef(<a class="keyword" href="https://d.hatena.ne.jp/keyword/gc">gc</a>) (36 samples, 0.31%) move(<a class="keyword" href="https://d.hatena.ne.jp/keyword/rco">rco</a>_contest_2018_qual_A) (5,194 samples, 44.01%) move(rco_contest_2018_qual_A) -%(arithmetics) (38 samples, 0.32%) del(avltree) (29 samples, 0.25%) input(macros) (9 samples, 0.08%) <%(comparisons) (13 samples, 0.11%) update(segtree) (61 samples, 0.52%) usrToCell(<a class="keyword" href="https://d.hatena.ne.jp/keyword/gc">gc</a>) (58 samples, 0.49%) init(segtree) (131 samples, 1.11%) add(avltree) (22 samples, 0.19%) inRange(avltree) (7 samples, 0.06%) interiorAllocatedPtr(alloc) (122 samples, 1.03%) -%(arithmetics) (20 samples, 0.17%) +%(arithmetics) (337 samples, 2.86%) +%.. <=%(comparisons) (67 samples, 0.57%) genericAssignAux(assign) (4,026 samples, 34.11%) genericAssignAux(assign) +%(arithmetics) (19 samples, 0.16%) </span>=(bitutils) (50 samples, 0.42%) <%(comparisons) (18 samples, 0.15%) -%(arithmetics) (11 samples, 0.09%) align(system) (91 samples, 0.77%) del(avltree) (39 samples, 0.33%) -%(arithmetics) (5 samples, 0.04%) +%(arithmetics) (8 samples, 0.07%) usrToCell(<a class="keyword" href="https://d.hatena.ne.jp/keyword/gc">gc</a>) (20 samples, 0.17%) <%(comparisons) (10 samples, 0.08%) newObjNoInit(<a class="keyword" href="https://d.hatena.ne.jp/keyword/gc">gc</a>) (468 samples, 3.97%) newO.. unsureAsgnRef(<a class="keyword" href="https://d.hatena.ne.jp/keyword/gc">gc</a>) (459 samples, 3.89%) unsu.. e1`gensym23(segtree) (50 samples, 0.42%) <%(comparisons) (7 samples, 0.06%) find(strutils) (6 samples, 0.05%) -%(arithmetics) (58 samples, 0.49%) init(segtree) (131 samples, 1.11%) <%(comparisons) (8 samples, 0.07%) +%(arithmetics) (4 samples, 0.03%) del(avltree) (5 samples, 0.04%) <%(comparisons) (12 samples, 0.10%) decRef(<a class="keyword" href="https://d.hatena.ne.jp/keyword/gc">gc</a>) (13 samples, 0.11%) <%(comparisons) (37 samples, 0.31%) rawAlloc(alloc) (75 samples, 0.64%) incRef(<a class="keyword" href="https://d.hatena.ne.jp/keyword/gc">gc</a>) (42 samples, 0.36%) newObjNoInit(<a class="keyword" href="https://d.hatena.ne.jp/keyword/gc">gc</a>) (3,168 samples, 26.84%) newObjNoInit(gc) add(avltree) (6 samples, 0.05%) <%(comparisons) (7 samples, 0.06%) <=%(comparisons) (549 samples, 4.65%) <=%(c.. <%(comparisons) (6 samples, 0.05%) op1`gensym23(segtree) (53 samples, 0.45%) <span data-unlink>=(bitset) (320 samples, 2.71%) .. nimNewSeqOfCap(mmdisp) (1,068 samples, 9.05%) nimNewSeqOfCa.. addChunkToMatrix(alloc) (28 samples, 0.24%) add(avltree) (37 samples, 0.31%) +%(arithmetics) (4 samples, 0.03%)

大まかな流れ

  1. std/nimprof を利用してプロファイルテキストを生成する
  2. PythonでFrameGraph生成用ファイルに変換する
  3. Perlsvgファイルに変換する

 以下のサイトを参考にさせて頂きました
※リンク先手順通りやれば、Pythonでのテキスト変換挟まなくても良さそうでした

chy72.hatenablog.com

環境構築

 調べてやれそうなやり方を繋ぎ合わせたため、Nim・PythonPerlの3言語を使う必要があります
 Nimの実行環境は整っているものとします

 Pythonは3.10を使っていますので、これ以降のバージョンを使っている場合は問題ないはずです
 追加で必要なライブラリも特にはありません

 Perlは、以下のサイトを参考にインストールしました

 Perlのインストール、プログラムの実施 #Perl - Qiita

 Perl導入後、Nimでプロファイル計測を行うことができない現象が発生しました
 PATHを編集したりしていた所、何故か直ってしまいました
 恐らく、Nimのコンパイル実行で使うgccと、Perlで使うgccが影響し合ったと思われますが、再現したら教えてください

使い方

std/nimprof を利用してプロファイルテキストを生成する

 プロファイル計測したいNimのコードの最初の方に以下のコードを書きます

import nimprof
setSamplingFrequency(1000)  # 1ms

 そして、Nimを実行する際の引数に「--profiler:on --stackTrace:on」を加えて実行します
 自分はテキストで標準入出力をしているので、以下のようなコマンドになりました

nim c -r --profiler:on --stackTrace:on -d:release ファイル名.nim < nim_input.txt > nim_output.txt

 完了すると、「profile_results.txt」というファイルが出来ていると思います

PythonでFrameGraph生成用ファイルに変換する

 次に、以下のコードのPythonファイルを同階層に準備して実行します

コード折り畳み
def findCallCount(line):
    args = line.split(" ")
    for i, arg in enumerate(args):
        if arg[:4] != "Call": continue
        return args[i+1].split("/")[0]
    return ""

def parseTree(lines):
    result = []
    ignored = False
    for line in lines[1:]:
        if line == "": continue
        if line[0] == " ":
            flames = line.split(" ")
            file = flames[2].replace(".nim", "").replace(":", "")
            fun = flames[3].replace(";", "").replace(":", "")
            if file[0]=="." or fun[0]==".": continue
            if file == "nimprof" : ignored = True
            if ignored: continue
            result[-1].append(f"{fun}({file})")
        else:
            ignored = False
            result.append([])
            result[-1].append(findCallCount(line))

    return result

def parse(file_path):
    result = []
    with open(file_path) as f:
        lines = f.readlines()
    tree = parseTree(lines)
    for t in tree:
        result.append(";".join(reversed(t[1:]))+ f" {t[0]}\n")
    return result

file_path = "./profile_results.txt"
res = parse(file_path)
output = "./profile_export.txt"
with open(output, "w") as f:
    f.writelines(res)

 実行完了すると「profile_export.txt」というファイルが出来ていると思います

Perlsvgファイルに変換する

 FlameGraphへ変換するPerlのコードを以下のサイトから入手します

 FlameGraph/flamegraph.pl at master · brendangregg/FlameGraph · GitHub

 そして、以下のコマンドを実行します

perl flamegraph.pl < profile_export.txt > flamegraph.svg

 実行完了すると「flamegraph.svg」というファイルが出来ていると思います
 このファイルをブラウザで開くとプロファイル結果を見ることが出来ます

実際に処理改善してみる

 A - ゲーム実況者Xの挑戦で提出したコードを元に改善してみます
 以下が元のプロファイル結果で、例として右の方のセグ木の時間に着目します
 update()の内、op()が結構な割合を占めています

 op()は、以下のコードが書かれていました

proc op(a, b: (int, int)):(int, int) = min(a, b)

 min()を使っていたので、if文を使った処理へ書き換えてみます

proc op(a, b: (int, int)):(int, int) = 
    if a[0] <= b[0]: return a
    else: return b

 再度、プロファイルを取り直したものが以下になります

 全体に対する処理時間の割合が減ったように見えます
 コードテストも回してみます
 計測誤差もあるとは思いますが、実行時間を改善することが出来ました!

おわりに

 自分への備忘録として書きましたが、誰かの役に立てば幸いです