PythonGILトレース

Python GIL（グローバルインタープリターロック）の目的（つまりCPython）を説明する記事はたくさんあります。つまり、GILは、マルチスレッドのクリーンなPythonコードが複数のプロセッサコアを使用するのを防ぎます。



ただし、Vaexでは、GILを無効にしたC ++で最も計算量の多いタスクを実行します。これは、Pythonが高レベルの接着剤としてのみ機能する高性能Pythonライブラリの通常の方法です。



GILは明示的に無効にする必要があり、プログラマーの責任であり、忘れることができます。これは、容量の非効率的な使用につながります。最近、私自身は忘れっぽいの役割であった、とで同様の問題を発見した Apacheのアロー（これはVaexの依存関係であるため、ArrowでGILが無効になっていない場合、私たち（および他のすべての人）はパフォーマンスの低下を経験します）。



さらに、64コアで実行している場合、Vaexのパフォーマンスが理想からかけ離れていることがあります。6400％ではなく4000％のCPUを使用している可能性がありますが、これは私には適していません。この効果を調べるためにスイッチをランダムに挿入する代わりに、何が起こっているのかを理解したいと思います。問題がGILにある場合は、Vaexが遅くなる理由と方法を理解したいと思います。

なぜ私はこれを書いているのですか

ネイティブ拡張機能を使用してPythonをプロファイリングおよびトレースするためのツールと手法のいくつか、およびこれらのツールを組み合わせてGILを有効または無効にした場合のPythonのパフォーマンスを分析および視覚化する方法について説明する一連の記事を作成する予定です。



これにより、言語エコシステムでのトレース、プロファイリング、その他のパフォーマンス測定、およびPythonエコシステム全体のパフォーマンスが向上することを願っています。

要件

Linux

Linuxマシンへのrootアクセスが必要です（sudoで十分です）。または、システム管理者に以下のコマンドを実行するように依頼してください。この記事の残りの部分では、ユーザー特権で十分です。

パフォーマンス

たとえば、Ubuntuにperfがインストールされていることを確認してください。次のように実行できます。

$ sudo yum install perf

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

カーネル構成

ユーザーとして実行：

# Enable users to run perf (use at own risk)
$ sudo sysctl kernel.perf_event_paranoid=-1

# Enable users to see schedule trace events:
$ sudo mount -o remount,mode=755 /sys/kernel/debug
$ sudo mount -o remount,mode=755 /sys/kernel/debug/tracing

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

Pythonパッケージ

VizTracerとper4mを使用 し ます

$ pip install "viztracer>=0.11.2" "per4m>=0.1,<0.2"

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

perfを使用してスレッドとプロセスの状態を追跡する

そのためのAPIがないため、PythonでGILの状態を把握する方法はありません（ポーリングを使用する以外 ）。カーネルから状態を監視できます。そのためには、perfツールが必要です 。



その助け（perf_eventsとしても知られています）を使用して、プロセスとスレッドの状態の変化をリッスンし（スリープと実行のみに関心があります）、それらをログに記録できます。パフォーマンスは威圧的に見えるかもしれませんが、それは強力なツールです。それについてもっと知りたい場合は、JuliaEvansまたは BrendanGreggのWebサイトの記事を読むことをお勧めし ます。



調整するために、最初に簡単なプログラムにperfを適用しましょう ：

import time
from threading import Thread

def sleep_a_bit():
    time.sleep(1)

def main():
    t = Thread(target=sleep_a_bit)
    t.start()
    t.join()

main()

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

ノイズを減らすために、いくつかのイベントをリッスンします（ワイルドカードの使用に注意してください）。

$ perf record -e sched:sched_switch  -e sched:sched_process_fork \
        -e 'sched:sched_wak*' -- python -m per4m.example0
[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 0,032 MB perf.data (33 samples) ]

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

そして、perf scriptコマンドを使用して、解析に適した読み取り可能な結果を​​出力します。





4番目の列（秒単位の時間）を見てください。プログラムがスリープ状態になりました（1秒が経過しました）。ここに、スリープ状態への入り口が表示されます。

python 3040114 [031] 5563911.112513: sched:sched_switch: prev_comm=python prev_pid=3040114 prev_prio=120 prev_state=S ==> next_comm=swapper/31 next_pid=0 next_prio=120

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

これは、カーネルがPythonスレッドの状態をS



（=スリープ）に変更したことを意味します 。



1秒後、プログラムは目覚めました。

swapper 0 [031] 5563912.113697: sched:sched_wakeup: comm=python pid=3040114 prio=120 target_cpu=031

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

もちろん、何が起こっているのかを理解するには、ツールを収集する必要があります。はい、結果はper4mを使用して簡単に解析することもできます が、続行する前に、VizTracerを使用してもう少し複雑なプログラムのフローを視覚化したいと 思います。

VizTracer

これは、プログラムがブラウザーで実行している作業を視覚化できるPythonトレーサーです。より複雑なプログラムに適用してみましょう ：

import threading
import time

def some_computation():
    total = 0   
    for i in range(1_000_000):
        total += i
    return total

def main():
    thread1 = threading.Thread(target=some_computation)
    thread2 = threading.Thread(target=some_computation)
    thread1.start()
    thread2.start()
    time.sleep(0.2)
    for thread in [thread1, thread2]:
        thread.join()

main()

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

トレーサー操作の結果：

$ viztracer -o example1.html --ignore_frozen -m per4m.example1
Loading finish                                        
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example1.html ...
Dumping trace data to json, total entries: 94, estimated json file size: 11.0KiB
Generating HTML report
Report saved.

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

結果のHTMLは次のようになります。





some_computation



GILがこれを防止していることはわかっていますが 、並行して（2回）実行されたようです。何が起きてる？

VizTracerとperfの結果を組み合わせる

example0.pyのようにperfを適用してみましょう。ここで、VizTracerと同じ時計-k CLOCK_MONOTONIC



を使用する引数を 追加し、HTMLの代わりにJSONを生成するように依頼しましょう 。

$ perf record -e sched:sched_switch  -e sched:sched_process_fork -e 'sched:sched_wak*' \
   -k CLOCK_MONOTONIC  -- viztracer -o viztracer1.json --ignore_frozen -m per4m.example1

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

次に、per4mを使用して、perfスクリプトの結果をVizTracerが読み取れるJSONに変換します。

$ perf script | per4m perf2trace sched -o perf1.json
Wrote to perf1.json

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

ここで、VizTracerを使用して、2つのJSONファイルを組み合わせてみましょう。

$ viztracer --combine perf1.json viztracer1.json -o example1_state.html
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example1.html ...
Dumping trace data to json, total entries: 131, estimated json file size: 15.4KiB
Generating HTML report
Report saved.

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

これが私たちが得たものです：





明らかに、スレッドはGILのために定期的にスリープし、並行して実行されません。



注：スリープフェーズの長さは約5ミリ秒で、これはデフォルトのsys.getswitchintervalに対応します 。

GILの定義

プロセスはスリープ状態になりますが、呼び出しtime.sleep



またはGILによって開始されたスリープ状態の違いはわかりません 。違いを見分ける方法はいくつかありますが、そのうちの2つを見てみましょう。

スタックトレースを介して

助けを借りて perf record -g



（または、より良いのは perf record --call-graph dwarf



、を意味します -g



）、各パフォーマンスイベントのスタックトレースを取得します。

$ perf record -e sched:sched_switch  -e sched:sched_process_fork -e 'sched:sched_wak*'\
   -k CLOCK_MONOTONIC  --call-graph dwarf -- viztracer -o viztracer1-gil.json --ignore_frozen -m per4m.example1
Loading finish                                        
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/viztracer1-gil.json ...
Dumping trace data to json, total entries: 94, estimated json file size: 11.0KiB
Report saved.
[ perf record: Woken up 3 times to write data ]
[ perf record: Captured and wrote 0,991 MB perf.data (164 samples) ]

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

（パフォーマンス上の理由で追加した--no-inline



）perfスクリプトの結果を見ると、 多くの情報が得られます。状態変更イベントを見てください。take_gilが呼び出されたことが わかります。





注：別名 、他のミューテックスに興味がある場合はpthread_cond_timedwait



、https： //github.com/sumerc/gilstats.pyによってeBPFに使用され ます。



別の注意：ここにはPythonスタックトレースがないことに注意してください_PyEval_EvalFrameDefault



。代わりに、さらに多くのトレースを取得し ました。将来的には、スタックトレースの挿入方法を書く予定です。



変換ツール per4m perf2trace



はこれを理解し、トレースにtake_gil



次のものが含まれている場合に異なる結果を生成します 。

$ perf script --no-inline | per4m perf2trace sched -o perf1-gil.json
Wrote to perf1-gil.json
$ viztracer --combine perf1-gil.json viztracer1-gil.json -o example1-gil.html
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example1.html ...
Dumping trace data to json, total entries: 131, estimated json file size: 15.4KiB
Generating HTML report
Report saved.

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

我々が得る：





これで、GILがどこで機能するかを正確に確認できます。

プロービングを通じて（kprobes / uprobes）

プロセスがいつスリープ状態になるか（GILまたはその他の理由により）はわかっていますが、GILがいつオンまたはオフになるかについて詳しく知りたい場合は、結果がいつ呼び出されて返されるかを知る必要が take_gil



あり drop_gil



ます。このトレースは、perfでプローブすることで取得できます。ユーザー環境では、プローブはアップローブであり、kprobeに類似しています。これは、ご想像のとおり、カーネル環境で機能します。繰り返しになりますが、JuliaEvansは追加情報の優れた情報源です 。



4つのプローブをインストールします。

sudo perf probe -f -x `which python` python:take_gil=take_gil
sudo perf probe -f -x `which python` python:take_gil=take_gil%return
sudo perf probe -f -x `which python` python:drop_gil=drop_gil
sudo perf probe -f -x `which python` python:drop_gil=drop_gil%return

Added new events:

  python:take_gil      (on take_gil in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
  python:take_gil_1    (on take_gil in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)

You can now use it in all perf tools, such as:

        perf record -e python:take_gil_1 -aR sleep 1

Failed to find "take_gil%return",
 because take_gil is an inlined function and has no return point.
Added new event:
  python:take_gil__return (on take_gil%return in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)

You can now use it in all perf tools, such as:

        perf record -e python:take_gil__return -aR sleep 1

Added new events:
  python:drop_gil      (on drop_gil in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
  python:drop_gil_1    (on drop_gil in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)

You can now use it in all perf tools, such as:

        perf record -e python:drop_gil_1 -aR sleep 1

Failed to find "drop_gil%return",
 because drop_gil is an inlined function and has no return point.
Added new event:
  python:drop_gil__return (on drop_gil%return in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)

You can now use it in all perf tools, such as:

        perf record -e python:drop_gil__return -aR sleep 1

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

いくつかの不満があり、インラインのもののために drop_gil



、 take_gil



いくつかのプローブ/イベントが追加されました（つまり、関数はバイナリファイルで数回提示されます）が、すべてが機能します。



注：対応するtake_gil



/ drop_gil



（およびその結果）がこの問題を解決するために正常に機能するように、Pythonバイナリ（conda-forgeから）がコンパイルされたのは幸運だったかもしれません 。



プローブはパフォーマンスに影響を与えず、プローブが「アクティブ」である場合（たとえば、パフォーマンスからプローブを監視する場合）にのみ、別のブランチでコードを実行することに注意してください。監視中に、影響を受けるページが監視対象プロセス用にコピーされ、 チェックポイントが適切な場所に挿入されます（x86プロセッサの場合はINT3）。チェックポイントは、オーバーヘッドがほとんどないパフォーマンスのイベントを発生させます。プローブを削除する場合は、次のコマンドを実行します。

$ sudo perf probe --del 'python*'

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

これで、perfはリッスンできる新しいイベントを認識したので、追加の引数を指定してもう一度実行してみましょう -e 'python:*gil*'



。

$ perf record -e sched:sched_switch  -e sched:sched_process_fork -e 'sched:sched_wak*' -k CLOCK_MONOTONIC  \
  -e 'python:*gil*' -- viztracer  -o viztracer1-uprobes.json --ignore_frozen -m per4m.example1

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

注：削除しました。削除し --call-graph dwarf



ないと、perfが間に合わず、イベントが失われます。



次に、per4m perf2traceを使用して、VizTracerで理解できるJSONに変換すると同時に、新しい統計を取得します。

$ perf script --no-inline | per4m perf2trace gil -o perf1-uprobes.json
...
Summary of threads:

PID         total(us)    no gil%    has gil%    gil wait%
--------  -----------  -----------  ------------  -------------
3353567*     164490.0         65.9          27.3            6.7
3353569       66560.0          0.3          48.2           51.5
3353570       60900.0          0.0          56.4           43.6

High 'no gil' is good, we like low 'has gil',
 and we don't want 'gil wait'. (* indicates main thread)
... 
Wrote to perf1-uprobes.json

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

サブコマンド per4m perf2trace gil



は、結果としてgil_loadも提供し ます。このことから、予想どおり、両方のスレッドがGILを約半分の時間待機していることがわかります。



perfによって記録された同じperf.dataファイルを使用して、スレッドまたはプロセスの状態に関する情報を生成することもできます。しかし、スタックトレースなしで実行していたため、GILが原因でプロセスがスリープしたかどうかはわかりません。

$ perf script --no-inline | per4m perf2trace sched -o perf1-state.json
Wrote to perf1-state.json

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

最後に、3つの結果すべてをまとめましょう。

$ viztracer --combine perf1-state.json perf1-uprobes.json viztracer1-uprobes.json -o example1-uprobes.html 
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example1-uprobes.html ...
Dumping trace data to json, total entries: 10484, estimated json file size: 1.2MiB
Generating HTML report
Report saved.

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

VizTracerは、誰がGILを持っていて、誰がそれを待っていたかについての良いアイデアを提供します：





各スレッドの上には、スレッドまたはプロセスがGILを待機し、オンになっている（LOCKとしてマークされている）ときに書き込まれます。これらの期間は、スレッドまたはプロセスが起動している（実行中！）期間と重複していることに注意してください 。また、GILが原因であるはずなので、実行状態のスレッドまたはプロセスは1つしか表示されないことに注意してください。



呼び出し間の時間take_gil



、つまりロック間の時間（したがって、スリープまたはウェイクアップ間の時間 ）は、上記のgil wait％列の表とまったく同じです。LOCKとラベル付けされた各スレッドのGILターンオン期間は、gil％列の時間に対応します。

クラーケンを解放する... ghm、GIL

純粋なPythonプログラムがマルチスレッド化されている場合、GILが一度に1つのスレッドまたはプロセスのみを実行できるようにすることでパフォーマンスを制限する方法を見てきました（もちろん、1つのPythonプロセスに対して、そして将来的には1つの（サブ）インタープリターに対して） 。 NumPy関数の実行時に発生するように、GILを無効にするとどうなるかを見てみましょう。



2番目の例 some_numpy_computation



では、2つのスレッドでNumPy関数M = 4を並列に呼び出し、メインスレッドは純粋なPythonコードを実行します。

import threading
import time
import numpy as np

N = 1024*1024*32
M = 4
x = np.arange(N, dtype='f8')

def some_numpy_computation():
    total = 0
    for i in range(M):
        total += x.sum()
    return total

def main(args=None):
    thread1 = threading.Thread(target=some_numpy_computation)
    thread2 = threading.Thread(target=some_numpy_computation)
    thread1.start()
    thread2.start()
    total = 0
    for i in range(2_000_000):
        total += i
    for thread in [thread1, thread2]:
        thread.join()
main()

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

このスクリプトをperfとVizTracerで実行する代わりにper4m giltracer



、上記のすべての手順を自動化するユーティリティを使用し ます。彼女はそれを少し賢くします。基本的に、perfを2回実行します。1回目はスタックトレースなしで、2回目はスタックトレースありで実行し、メイン関数を実行する前にモジュール/スクリプトをインポートして、同じインポートのような興味のないトレースを取り除きます。これは、イベントを失うことがないように、十分に迅速に行われます。

$ giltracer --state-detect -o example2-uprobes.html -m per4m.example2
...

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

ストリームの合計：

PID         total(us)    no gil%    has gil%    gil wait%
--------  -----------  -----------  ------------  -------------
3373601*    1359990.0         95.8           4.2            0.1
3373683       60276.4         84.6           2.2           13.2
3373684       57324.0         89.2           1.9            8.9

High 'no gil' is good, we like low 'has gil',
 and we don't want 'gil wait'. (* indicates main thread)
...
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example2-uprobes.html ...
...

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

メインスレッドはPythonコードを実行しますが（GILが有効になっており、LOCKという単語で示されます）、他のスレッドも並行して実行されます。純粋なPythonの例では、1つのスレッドまたはプロセスが同時に実行されていることに注意してください。そしてここでは、実際には3つのスレッドが並行して実行されます。これが可能なのは、C / C ++ / Fortranに含まれているNumPyルーチンがGILを無効にしたためです。



ただし、GILはスレッドに影響を与えます。これは、NumPy関数がPythonに戻るときに、長いブロックに見られるように、GILを再度取得する必要があるため take_gil



です。これには、各スレッドの時間の10％がかかります。

Jupyter統合

私のワークフローでは、Linuxマシンにリモート接続されたMacBook（perfは実行されませんが、dtraceをサポートします）をリモートで実行することが多いため、Jupyterノートブックを使用してコードをリモートで実行します。そして、私はJupyter開発者なので、でラッパーを作成する必要がありました cell magic



。

# this registers the giltracer cell magic
%load_ext per4m

%%giltracer
# this call the main define above, but this can also be a multiline code cell
main()

Saving report to /tmp/tmpvi8zw9ut/viztracer.json ...
Dumping trace data to json, total entries: 117, estimated json file size: 13.7KiB
Report saved.

[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0,094 MB /tmp/tmpvi8zw9ut/perf.data (244 samples) ]

Wait for perf to finish...
perf script -i /tmp/tmpvi8zw9ut/perf.data --no-inline --ns | per4m perf2trace gil -o /tmp/tmpvi8zw9ut/giltracer.json -q -v 
Saving report to /home/maartenbreddels/github/maartenbreddels/fastblog/_notebooks/giltracer.html ...
Dumping trace data to json, total entries: 849, estimated json file size: 99.5KiB
Generating HTML report
Report saved.

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

giltracer.htmlをダウンロード



する新しいタブでgiltracer.htmlを開きます（セキュリティのために機能しない場合があります）

結論

perfを使用すると、プロセスまたはスレッドの状態を判別できます。これは、PythonでGILが有効になっているプロセスまたはスレッドを理解するのに役立ちます。また、スタックトレースを使用すると、GILがスリープの原因であり、time.sleep



たとえばではないことを確認できます 。



PERFでuprobesを組み合わせることで、あなたが呼び出しをトレースし、関数の結果を返すことができるtake_gil



と 獲得 drop_gil



あなたのPythonプログラム上のGILの影響にさらに多くの洞察を。



私たちの作業は、perfスクリプトをJSON形式のVizTracerに変換する実験的なper4mパッケージと、いくつかのオーケストレーションツールによって促進されます。

たくさんのブカフ、マスターしなかった

GILの影響を確認したいだけの場合は、これを1回実行します。

sudo yum install perf
sudo sysctl kernel.perf_event_paranoid=-1
sudo mount -o remount,mode=755 /sys/kernel/debug
sudo mount -o remount,mode=755 /sys/kernel/debug/tracing
sudo perf probe -f -x `which python` python:take_gil=take_gil
sudo perf probe -f -x `which python` python:take_gil=take_gil%return
sudo perf probe -f -x `which python` python:drop_gil=drop_gil
sudo perf probe -f -x `which python` python:drop_gil=drop_gil%return
pip install "viztracer>=0.11.2" "per4m>=0.1,<0.2"

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

使用例：

# module
$ giltracer per4m/example2.py
# script
$ giltracer -m per4m.example2
# add thread/process state detection
$ giltracer --state-detect -m per4m.example2
# without uprobes (in case that fails)
$ giltracer --state-detect --no-gil-detect -m per4m.example2

      
      

        
        
        
      

    
        
        
        
      
      

        
        
        
      

    
    

今後の計画

これらのツールを開発する必要がなかったらいいのにと思います。うまくいけば、私は誰かに私よりも優れた製品を作成するように促すことができました。高性能コードの記述に集中したいと思います。しかし、私は将来のためにそのような計画を持っています：

• VizTracerでパフォーマンスメーターを調べて、キャッシュミスやプロセスのダウンタイムを確認します。
• http://www.brendangregg.com/offcpuanalysis.htmlなどのツールと組み合わせるために、パフォーマンストレースにPythonスタックトレースを実装します
• macOSで使用するには、dtraceを使用して同じ演習を繰り返します。
• どのC関数がGILを無効にしないかを自動的に検出します（https://github.com/vaexio/vaex/pull/1114、https://github.com/apache/arrow/pull/7756）
• , https://github.com/h5py/h5py/issues/1516