Pythonでスレッドのスタックトレースを出力したい

これは、なにをしたくて書いたもの？

Pythonで、動作しているスレッドのスタックトレースを出力する方法は？ということで。

環境

今回の環境は、こちら。

$ python3 -V
Python 3.8.10

使う標準ライブラリ

今回の目的は、このあたりを使えば良さそうです。

traceback --- スタックトレースの表示または取得 — Python 3.8.10 ドキュメント

sys --- システムパラメータと関数 — Python 3.8.10 ドキュメント

threading --- スレッドベースの並列処理 — Python 3.8.10 ドキュメント

以降、これらを使ってちょっと試していきたいと思います。

スタックトレースを出力するコードを埋め込む

まずは、スタックトレースを出力したい処理自体の中に、スタックトレースを出力するコードを埋め込んでみます。

thread_dump_example.py

import sys
import threading
import traceback


def main():
    sub()


def sub():
    print('===== print traceback#print_stack')
    traceback.print_stack()

    print()

    print('===== print traceback#print_stack(file=sys.stdout)')
    traceback.print_stack(file=sys.stdout)

    print()

    print('===== print traceback#print_stack(sys._current_frames()[threading.get_ident()])')
    traceback.print_stack(sys._current_frames()[threading.get_ident()])


if __name__ == '__main__':
    main()

main → subと呼び出します。

単純には、traceback#print_stackでOKです。

traceback.print_stack

    traceback.print_stack()

出力結果はこちら。

  File "thread_dump_example.py", line 26, in <module>
    main()
  File "thread_dump_example.py", line 7, in main
    sub()
  File "thread_dump_example.py", line 12, in sub
    traceback.print_stack()

fileパラメーターを使うすることで、スタックトレースの出力先を指定することもできるようです。

    traceback.print_stack(file=sys.stdout)

結果は先ほどと同じなので、ここでは割愛。

最後は、少し毛色を変えてsys#_current_framesを使ってみます。

sys._current_frames

こちらは、呼び出された時点でのアクティブなスレッドのスタックフレームを含んだ辞書を返す関数です。
この辞書に対して、現在のスレッドの識別子をキーに指定することでスタックフレームを取得できます。

threading.get_ident()

あとは、traceback#print_stackに渡せばOKです。

    traceback.print_stack(sys._current_frames()[threading.get_ident()])

結果は、他と同じになります。

最後に、実行結果全体を載せておきましょう。

$ python3 thread_dump_example.py
===== print traceback#print_stack
  File "thread_dump_example.py", line 26, in <module>
    main()
  File "thread_dump_example.py", line 7, in main
    sub()
  File "thread_dump_example.py", line 12, in sub
    traceback.print_stack()

===== print traceback#print_stack(file=sys.stdout)
  File "thread_dump_example.py", line 26, in <module>
    main()
  File "thread_dump_example.py", line 7, in main
    sub()
  File "thread_dump_example.py", line 17, in sub
    traceback.print_stack(file=sys.stdout)

===== print traceback#print_stack(sys._current_frames()[threading.get_ident()])
  File "thread_dump_example.py", line 26, in <module>
    main()
  File "thread_dump_example.py", line 7, in main
    sub()
  File "thread_dump_example.py", line 22, in sub
    traceback.print_stack(sys._current_frames()[threading.get_ident()])

プログラム内で動作している、すべてのアクティブなスレッドからスタックトレースを出力する

これで終わってもなんなので、現在のプログラム内で動作しているすべてのアクティブなスレッドからスタックトレースを
出力することを考えてみます。

ここまでに使ってきたAPIと、threadking#enumerate、Thread.identを使えば良さそうです。

threading.enumerate()

Thread.ident

複数のスレッドを使い、それぞれが一時的にスリープするプログラムを作成してみます。この時に、各スレッドから
スタックトレースを出力してみましょう。

multi_threaded_dump_example.py

import sys
import threading
import time
import traceback
from concurrent.futures import ThreadPoolExecutor


def run():
    wait()


def wait():
    current_thread = threading.current_thread()
    print(f'waiting[{current_thread.ident}] 10sec...')
    time.sleep(10)


def main():
    with ThreadPoolExecutor(max_workers=5) as executor:
        futures = [executor.submit(run) for i in range(5)]

        print('wait thread dump, 3sec...')
        time.sleep(3)

        frames = sys._current_frames()

        for t in threading.enumerate():
            if t.ident in frames:
                print(f'===== thread[{t.ident}] native_id={t.native_id}, alive={t.is_alive()}, daemon={t.isDaemon()}: dump stack')

                traceback.print_stack(frames[t.ident])

                print()

        print('wait, all results....')

        for f in futures:
            f.result()


if __name__ == '__main__':
    main()

スクリプト本体の方は、main関数を呼び出し、複数のスレッドを扱います。スレッド数は5つにしました。

def main():
    with ThreadPoolExecutor(max_workers=5) as executor:
        futures = [executor.submit(run) for i in range(5)]

        ### スタックトレースを出力する処理

        print('wait, all results....')

        for f in futures:
            f.result()

スタックトレースを出力する部分は後で載せますが、各スレッドの処理が終了するまで待ち合わせは行います。

各スレッドで実行するのは、こちらの関数。

def run():
    wait()


def wait():
    current_thread = threading.current_thread()
    print(f'waiting[{current_thread.ident}] 10sec...')
    time.sleep(10)

どのスレッドも10秒待たせるようにしています。

各スレッドを取得し、スタックトレースを出力しているのはこちら。

        frames = sys._current_frames()

        for t in threading.enumerate():
            print(f'===== thread[{t.ident}] native_id={t.native_id}, alive={t.is_alive()}, daemon={t.isDaemon()}: dump stack')

            traceback.print_stack(frames[t.ident])

            print()

まずは、アクティブなスレッドのスタックフレームを含む辞書を取得。

        frames = sys._current_frames()

次にthreading#enumerateで、現在アクティブなスレッドのリストを取得。

threading.enumerate()

あとはこのリストをイテレーションしつつ、スタックフレームを含む辞書からThread.identを指定して各スレッドの
スタックトレースを出力します。

Thread.ident

        for t in threading.enumerate():

            traceback.print_stack(frames[t.ident])

この時、わかりやすいようにスレッドの識別子、ネイティブなスレッドID、生存中のスレッドか否か、Daemonスレッドか
否かも出力するようにしています。

            print(f'===== thread[{t.ident}] native_id={t.native_id}, alive={t.is_alive()}, daemon={t.isDaemon()}: dump stack')

ネイティブなスレッドIDは、LinuxだとLWPのことで良さそうです。

https://github.com/python/cpython/blob/v3.8.10/Python/thread_pthread.h#L322-L349

実行結果。

$ python3 multi_threaded_dump_example.py 
waiting[140368747820800] 10sec...
waiting[140368739428096] 10sec...
waiting[140368658036480] 10sec...
waiting[140368649643776] 10sec...
waiting[140368641251072] 10sec...
wait thread dump, 3sec...
===== thread[140368757622592] native_id=28917, alive=True, daemon=False: dump stack
  File "multi_threaded_dump_example.py", line 42, in <module>
    main()
  File "multi_threaded_dump_example.py", line 31, in main
    traceback.print_stack(frames[t.ident])

===== thread[140368747820800] native_id=28918, alive=True, daemon=True: dump stack
  File "/usr/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "multi_threaded_dump_example.py", line 9, in run
    wait()
  File "multi_threaded_dump_example.py", line 15, in wait
    time.sleep(10)

===== thread[140368739428096] native_id=28919, alive=True, daemon=True: dump stack
  File "/usr/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "multi_threaded_dump_example.py", line 9, in run
    wait()
  File "multi_threaded_dump_example.py", line 15, in wait
    time.sleep(10)

===== thread[140368658036480] native_id=28920, alive=True, daemon=True: dump stack
  File "/usr/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "multi_threaded_dump_example.py", line 9, in run
    wait()
  File "multi_threaded_dump_example.py", line 15, in wait
    time.sleep(10)

===== thread[140368649643776] native_id=28921, alive=True, daemon=True: dump stack
  File "/usr/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "multi_threaded_dump_example.py", line 9, in run
    wait()
  File "multi_threaded_dump_example.py", line 15, in wait
    time.sleep(10)

===== thread[140368641251072] native_id=28922, alive=True, daemon=True: dump stack
  File "/usr/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "multi_threaded_dump_example.py", line 9, in run
    wait()
  File "multi_threaded_dump_example.py", line 15, in wait
    time.sleep(10)

wait, all results....

それっぽい感じになりましたね。

まとめ

Pythonプログラム内で、スレッドのスタックトレースを出力するようにいろいろ試してみました。

これでシグナルハンドラと合わせて使ったりすると、シグナルでスレッドダンプが出力できたりしそうですが、
どうでしょう。

Pythonの場合は、マルチプロセスで動作していることも多いと思うので、これだけでは足りないでしょうけどね。

今度、もう少しこのあたりの事情も見てみようと思います。

CLOVER🍀

That was when it all began.

Pythonでスレッドのスタックトレースを出力したい

これは、なにをしたくて書いたもの？

環境

使う標準ライブラリ

スタックトレースを出力するコードを埋め込む

プログラム内で動作している、すべてのアクティブなスレッドからスタックトレースを出力する

まとめ