前回 uWSGI の prefork を調べた際に、任意の Worker のスレッドダンプを出力する方法を見つけられなかったので、スレッドダンプを JSON として返す function を書きました。

しかし、Master / Worker で統一的にスレッドダンプを取りたかったので色々と試した結果、pystuck を使ってそれぞれのスレッドダンプを取得することができました。

pystuck

pystuck は、RPyC というリモートプロシージャコールを使って、RPyC のサーバー側のスレッドダンプを返します。

import pystuck
pystuck.run_server()

サーバー側で上記のように記載すると host=127.0.0.1 , port=6666 で RPyC のリクエストを待ちます。

pystuck コマンドを実行すると、クライアントが起動します。--host や --port を指定することで、接続する Server の IP と Port を変更できます。クライアントが起動すると以下のように表示されます。

# pystuck
Welcome to the pystuck interactive shell.
Use the 'modules' dictionary to access remote modules (like 'os', or '__main__')
Use the `%show threads` magic to display all thread stack traces.

In [1]:

あとは %show threads とタイプすれば、Server のスレッドダンプを見ることができます(後述)。

Worker

uWSGI の Master プロセスで pystuck の Server を起動するには app.py や __init__.py で pystuck.run_server() を実行すれば良いのですが、それぞれの Worker のスレッドダンプを取得するには、Worker 側でも pystuck の Server を起動する必要もあります。uWSGI の場合は @postfork という decorator を使い、 fork 後に Server を起動するようにしました。

@postfork
def worker_init():
    pystuck.run_server()

Unix Domain Socket

pystuck.run_server() を実行する際に、Master / Worker 間で同じ port を使わないようにする必要があるのですが、調整がちょっと面倒なので Unix Domain Socket を使います。pystuck では Server は Unix Domain Socket が使えるのですが、Client は使えるようになっていなかったので、使えるように修正しました。

https://github.com/masayuki038/pystuck/tree/unix-domain-socket-on-client

Master と Worker でファイルパスが重複しないように、Worker 側のファイル名には PID を入れました。

Code

サンプルコードは以下のとおりです。

 1from time import sleep
 2import os
 3import json
 4import threading
 5
 6from flask import Flask, jsonify
 7
 8from uwsgidecorators import postfork
 9import pystuck
10pystuck.run_server(unix_socket='/tmp/utd-master')
11
12i = 0
13app = Flask(__name__)
14
15@postfork
16def worker_init():
17    pystuck.run_server(unix_socket=f'/tmp/utd-{os.getpid()}')
18
19
20def process():
21    while True:
22        try:
23            global i
24            i += 1
25            print(f"i: {i}")
26        except Exception as err:
27            print(f"err: {err}")
28
29        sleep(5)
30
31
32th = threading.Thread(target=process, name='test-thread', daemon=False)
33th.start()
34
35
36@app.route('/hello')
37def hello_world():
38    sleep(5)
39    return jsonify({'message': f'Hello World, {i}, {threading.currentThread().ident}'})

これを実行する(worker=2)と、uWSGI のプロセスが以下のように起動します。

root@6caf7639d198:/# ps afx
  PID TTY      STAT   TIME COMMAND
  575 pts/4    Ss     0:00 bash
  589 pts/4    R+     0:00  \_ ps afx
    6 pts/1    Ss     0:00 bash
  523 pts/1    Sl+    0:01  \_ uwsgi uwsgi.ini
  526 pts/1    Sl+    0:00      \_ uwsgi uwsgi.ini
  527 pts/1    Sl+    0:00      \_ uwsgi uwsgi.ini
  528 pts/1    S+     0:00      \_ uwsgi uwsgi.ini
    1 pts/0    Ss+    0:00 /bin/bash

そして以下のようにファイルが生成されます。

root@6caf7639d198:/# ls -l /tmp
total 0
srwxr-xr-x 1 root root 0 Sep 29 15:53 utd-526
srwxr-xr-x 1 root root 0 Sep 29 15:53 utd-527
srwxr-xr-x 1 root root 0 Sep 29 15:53 utd-master

PID=528 は　Worker ではなく uWSGI の httpd のプロセスなので、ファイルは出力されません。

あとはスレッドダンプを出力したいプロセスのファイルを指定して pystuck コマンドを起動します。

root@6caf7639d198:/# pystuck --unix-socket /tmp/utd-527
Welcome to the pystuck interactive shell.
Use the 'modules' dictionary to access remote modules (like 'os', or '__main__')
Use the `%show threads` magic to display all thread stack traces.

In [1]: %show threads
<Thread(Thread-2, started daemon 139703068108544)>
  File "/usr/local/lib/python3.7/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.7/threading.py", line 926, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.7/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/root/works/app.py", line 25, in process
    print(f"i: {i}")

<Thread(Thread-5, started daemon 139703076501248)>
  File "/usr/local/lib/python3.7/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.7/threading.py", line 926, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.7/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.7/site-packages/rpyc/utils/server.py", line 262, in start
    self.accept()
  File "/usr/local/lib/python3.7/site-packages/rpyc/utils/server.py", line 138, in accept
    sock, addrinfo = self.listener.accept()
  File "/usr/local/lib/python3.7/socket.py", line 212, in accept
    fd, addr = self._accept()

Conclusion

pystuck を使って uWSGI の Master / Worker のスレッドダンプが見れるようになりました。

スレッドダンプツールとしては、他に pystack を試してみましたが、空のファイルが生成されるだけでスレッドダンプを出力することができませんでした。(理由は追いかけてません)

最初は Linux の signal を trap してスレッドダンプを出力しようとしたのですが、uWSGI が trap しているらしく、handler が呼ばれませんでした。

また、uWSGI thread dump trigger という gist にアップされたコードも試してみました。これは uWSGI が独自で持つ Signal Framework を使っています。実際に試してみたところ、uWSGI の signal の handler を実行するスレッドが HTTP Request を処理するスレッドと同じだった為、HTTP Requet が滞留している原因を調べる用途には使えないと思い、このアプローチは採用しませんでした。

これで HTTP リクエストが詰まっても原因究明ができそうです。