Python、使ってますか。
わたしは最近、諸事情により、最近PythonとC言語とCUDAを使ったソフトウェアの高速化に取り組んでいます（できているとは言っていない）。ちなみに、ディープラーニングじゃないよ。
高速化するときに最も重要な道具は、ベンチマークとプロファイラであることを疑う人は居ないと思います。ベンチマークで高速化の効果を測定し、プロファイラでボトルネックを発見する。これが基本的かつ王道のサイクルですよね。
ところで、プロファイラはどのような仕組みで動いているのでしょうか。追いかけたこと、あります？
何を測っているのか知らずにプロファイラを使う者がおるか！
プロファイラは何を測っていて、何を測っていないのか。
Pythonに最初からついてくるプロファイラ「cProfile」を使ってプロファイリングを行っていたのですが（CUDAとC以前にPythonがボトルネックっぽいので）、わたしはてっきりこのプロファイラはGILを握っている全てのスレッドのそれぞれの動作を測ってるんだと思ってました。だって、「マルチスレッドだけどGILのせいで同時に動くスレッドは１つしかない」というPythonのプログラムの動作をプロファイリングする方法としては、それが一番妥当かつ自然に感じられたからです （でも、今考え直してみると、そうでもない気がしてきた…わからん）。ドキュメントにはマルチスレッドに関しては何にも書いてないし。
しかし、Profilerの出力する結果を見ているとどうにもおかしい気がしてきまして。おおむね予想通りの結果も出てくるけど、どこかおかしい気もする。わたしの予想の方が間違っているのか、プロファイラの測定の誤差や限界なのか。うーん。
なんでそんな考えが浮かんでくるのかといえば、（今回のも含めて）高速化したいプログラムというのは大抵複雑だからです。
というわけで、超単純なサンプルで測ってみました：
import threading
import cProfile
import math
class Worker(threading.Thread):
def __init__(self, n: int):
threading.Thread.__init__(self)
self.n = n
self.sum = 0
def run(self):
for i in range(0, self.n):
self.sum += math.sin(i * i)
def main():
th = Worker(100000)
th.start()
th.join()
if __name__ == '__main__':
main()
見たまんまですが、math.sin(i * i)の和を計算するという何の意味もない計算を、メインスレッドとは別のスレッドで行う、無意味だけど時間の掛かるプログラムです。
これをcProfileして出た結果は：
% python -m cProfile -s 'cumtime' test.py
45 function calls in 21.670 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 21.670 21.670 {built-in method builtins.exec}
1 0.000 0.000 21.670 21.670 <string>:1(<module>)
1 0.000 0.000 21.670 21.670 test.py:17(main)
5 21.670 4.334 21.670 4.334 {method 'acquire' of '_thread.lock' objects}
1 0.000 0.000 21.665 21.665 threading.py:1024(join)
1 0.000 0.000 21.665 21.665 threading.py:1062(_wait_for_tstate_lock)
1 0.000 0.000 0.005 0.005 threading.py:828(start)
1 0.000 0.000 0.005 0.005 threading.py:533(wait)
1 0.000 0.000 0.005 0.005 threading.py:263(wait)
1 0.000 0.000 0.000 0.000 {built-in method _thread.start_new_thread}
...（略）...
無意味な計算のために20秒ほど掛かっていていますが、その計算に関わっているWorker.run関数やmath.sinは一切リストアップされておらず、スレッドのjoinのみが入っています。
…えー。つまり、cProfileはマルチスレッド対応してないんだねぇ。
…今まで計測した結果、全部無駄だねぇ。…まぁ、そういう事もあるよ。
ソースコードを追いかける
せっかくですから、この機会にソースコードを追いかけて、どのようにプロファイルをしているのか、その仕組みを掴んでおくことにします。事前に予告しておきますが、本当に眺めて見学するだけです。さらに深くソースコードを追いかけたい時のとっかかりにでも使ってください。とはいえ、プロファイラの中身について言及している記事はインターネッツ上にあんまりないので、今回このように記事を書いております。
マルチスレッドのプログラムを手っ取り早くプロファイルしたい人は、読み飛ばして次の「マルチスレッドで走るPythonプログラムをプロファイルするには？」へ進むのも良いかもしれません。
さて。コンソールからpython -m cProfile test.pyを実行すると、cProfile.Profilerの次の関数が最終的には呼ばれます：
# https://github.com/python/cpython/blob/fcd5e84a515e19409840c570730f0728e9fcfc83/Lib/cProfile.py#L97
def runctx(self, cmd, globals, locals):
self.enable()
try:
exec(cmd, globals, locals) # コマンドライン引数で指定されたファイルの中の文字列を実行する
finally:
self.disable()
return self
exec関数はいわゆるeval関数の親戚で、与えられた文字列(cmd)を、所定の環境の下で実行する組み込み関数です。となると、その周囲を囲うenable/disableが重要そうです。
self.enableの実態を追いかけていくとC言語の関数に行き着きまして：
// https://github.com/python/cpython/blob/62be74290aca26d16f3f55ece7ff6dad14e60e8d/Modules/_lsprof.c#L683
static PyObject*
profiler_enable(ProfilerObject *self, PyObject *args, PyObject *kwds)
{
int subcalls = -1;
int builtins = -1;
static char *kwlist[] = {"subcalls", "builtins", 0};
if (!PyArg_ParseTupleAndKeywords(args, kwds, "|ii:enable",
kwlist, &subcalls, &builtins))
return NULL;
if (setSubcalls(self, subcalls) < 0 || setBuiltins(self, builtins) < 0)
return NULL;
PyEval_SetProfile(profiler_callback, (PyObject*)self);
self->flags |= POF_ENABLED;
Py_RETURN_NONE;
}
いちばん重要なのは、PyEval_SetProfileの呼び出しだと思います。これはpythonインタプリタの提供するプロファイルのための関数を設定する関数で、cProfileはこの言語処理系の機能をそのまま使っています。ちょっと面白いのは、この関数は外部に公開された、つまり（中の人でなくても）誰でも使えるC言語の関数なことで、やろうと思えば誰でも「ぼくのかんがえたさいきょうのプロファイラ」が作れるということになります。
さて、そのPyEval_SetProfileのソースも見てみましょう：
// https://github.com/python/cpython/blob/8479a3426eb7d1840473f7788e639954363ed37e/Python/ceval.c#L4371
void
PyEval_SetProfile(Py_tracefunc func, PyObject *arg)
{
PyThreadState *tstate = _PyThreadState_GET();
PyObject *temp = tstate->c_profileobj;
Py_XINCREF(arg);
tstate->c_profilefunc = NULL;
tstate->c_profileobj = NULL;
/* Must make sure that tracing is not ignored if 'temp' is freed */
tstate->use_tracing = tstate->c_tracefunc != NULL;
Py_XDECREF(temp);
tstate->c_profilefunc = func;
tstate->c_profileobj = arg;
/* Flag that tracing or profiling is turned on */
tstate->use_tracing = (func != NULL) || (tstate->c_tracefunc != NULL);
}
一行目のPyThreadState_GETはスレッドごとに違うPyThreadStateオブジェクトを返す関数（参考：スレッド局所記憶）です。なので、プロファイラの関数はスレッドごとに設定されます。というわけで、python -m cProfile test.pyで測定した時は、メインスレッド以外の別のスレッドに関してはやっぱり一切計測しません。
tstate->c_profilefuncに設定される関数は、C言語とPythonの関数のCALL/RETURNの時に呼ばれるようになっていまして、cProfileでプロファイルを取る時の関数もその情報を使って集計しているのがわかります。
実際にこの関数が呼ばれているところも追いかけておきましょう。
PythonからPythonの関数の呼び出し
Pyrhonの関数のCALL/RETURNに関しては、関数の本体（のバイトコード）を実行する_PyEval_EvalFrameDefaultというインタプリタの核心部みたいな関数の最初と最後で呼ばれます：
# https://github.com/python/cpython/blob/842a2f07f2f08a935ef470bfdaeef40f87490cfc/Python/ceval.c#L940
if (tstate->c_profilefunc != NULL) {
/* Similar for c_profilefunc, except it needn't
return itself and isn't called for "line" events */
if (call_trace_protected(tstate->c_profilefunc,
tstate->c_profileobj,
tstate, f, PyTrace_CALL, Py_None)) {
/* Profile function raised an error */
goto exit_eval_frame;
}
}
}
# https://github.com/python/cpython/blob/842a2f07f2f08a935ef470bfdaeef40f87490cfc/Python/ceval.c#L3575
return_or_yield:
if (tstate->use_tracing) {
if (tstate->c_tracefunc) {
if (call_trace_protected(tstate->c_tracefunc, tstate->c_traceobj,
tstate, f, PyTrace_RETURN, retval)) {
Py_CLEAR(retval);
}
}
if (tstate->c_profilefunc) {
if (call_trace_protected(tstate->c_profilefunc, tstate->c_profileobj,
tstate, f, PyTrace_RETURN, retval)) {
Py_CLEAR(retval);
}
}
}
この関数は、Pythonで書かれた関数を実際に実行するコードです。バイトコードの実行ループがあるので（今回の話とは一切無関係ですが）読んでいて面白い関数ではあります。おすすめです。
PythonからC言語の関数呼び出しは別扱い
C言語の関数の呼び出しは、もうちょっと複雑です。Pythonの内部で使われているVMのオペコードのうち、CALL_METHOD/CALL_FUNCTION/CALL_FUNCTION_KW/CALL_FUNCTION_EX命令が実行された時に呼ばれる、次の関数からC言語の関数の実行が移譲されています：
// https://github.com/python/cpython/blob/842a2f07f2f08a935ef470bfdaeef40f87490cfc/Python/ceval.c#L4648
/* Issue #29227: Inline call_function() into _PyEval_EvalFrameDefault()
to reduce the stack consumption. */
Py_LOCAL_INLINE(PyObject *) _Py_HOT_FUNCTION
call_function(PyObject ***pp_stack, Py_ssize_t oparg, PyObject *kwnames)
{
// ... 前処理 ...
/* Always dispatch PyCFunction first, because these are
presumed to be the most frequent callable object.
*/
if (PyCFunction_Check(func)) {
PyThreadState *tstate = _PyThreadState_GET();
C_TRACE(x, _PyCFunction_FastCallKeywords(func, stack, nargs, kwnames));
}
else if (Py_TYPE(func) == &PyMethodDescr_Type) {
PyThreadState *tstate = _PyThreadState_GET();
if (nargs > 0 && tstate->use_tracing) {
/* We need to create a temporary bound method as argument
for profiling.
If nargs == 0, then this cannot work because we have no
"self". In any case, the call itself would raise
TypeError (foo needs an argument), so we just skip
profiling. */
PyObject *self = stack[0];
func = Py_TYPE(func)->tp_descr_get(func, self, (PyObject*)Py_TYPE(self));
if (func != NULL) {
C_TRACE(x, _PyCFunction_FastCallKeywords(func,
stack+1, nargs-1,
kwnames));
Py_DECREF(func);
}
else {
x = NULL;
}
}
else {
x = _PyMethodDescr_FastCallKeywords(func, stack, nargs, kwnames);
}
}
else {
// ... Pythonの関数のときの処理 ...
}
// ... 後処理 ...
return x;
}
この最初の２つのif文がC言語で書かれた関数ないしメソッドの呼び出しに対応しているようです。２番めのPy_TYPE(func) == &PyMethodDescr_Type の方は、調べた限りでは、
>>> po = "po!" >>> f = po.upper >>> f() 'PO!'
のような感じで、メソッドにselfだけ束縛した場合に実行される分岐のようです（あんまり自信ない）。
C_TRACEというマクロの定義は次の通りで、callという引数で指定されるC言語関数呼び出しコールの前後でPyTrace_C_CALLとPyTrace_C_RETURNをプロファイラのコールバック関数に対して通知するようになっています。
// https://github.com/python/cpython/blob/842a2f07f2f08a935ef470bfdaeef40f87490cfc/Python/ceval.c#L4617
#define C_TRACE(x, call)
if (tstate->use_tracing && tstate->c_profilefunc) {
if (call_trace(tstate->c_profilefunc, tstate->c_profileobj,
tstate, tstate->frame,
PyTrace_C_CALL, func)) {
x = NULL;
}
else {
x = call;
if (tstate->c_profilefunc != NULL) {
if (x == NULL) {
call_trace_protected(tstate->c_profilefunc,
tstate->c_profileobj,
tstate, tstate->frame,
PyTrace_C_EXCEPTION, func);
/* XXX should pass (type, value, tb) */
} else {
if (call_trace(tstate->c_profilefunc,
tstate->c_profileobj,
tstate, tstate->frame,
PyTrace_C_RETURN, func)) {
Py_DECREF(x);
x = NULL;
}
}
}
}
} else {
x = call;
}
ここ以外にももっと複雑な関数呼び出しのためのdo_call_core関数もあるのですが、そっちもだいたい似た感じなので省略します。
Pythonの関数のCALL/RETURNは、呼び出された関数の中で記録されるのに対して、C言語の方は呼び出す直前なところがちょっと面白いところでしょうか。もちろん、C言語の関数はPythonのインタプリタから遠く独立していることを踏まえれば、合理的な実装だと思います。
オチはなし：意外と素朴な実装だったなぁ（小学生並みの感想）
…えー、とくにオチはないです。強いて言うなら、意外と素朴な実装でしたね。Linuxカーネルのよくわかんない機能とか使ってるのかなぁという予想も事前にしていたのですが、そんな事はなくて、地道に適当なタイミングで適切に関数を呼び出して記録しているだけでした。
cProfileとprofileの具体的な違いは？
Pythonでプロファイルを取る方法は、cProfileだけではなく、profileというのもあります。こちらは100% Pure Pythonで、cProfileが使えない環境ではこちらを使ってね、とドキュメントには書いてあります。こちらはどのような実装になっているのでしょうか？Pythonのインタプリタの奥深くにプロファイルのための機能が実装されている以上、profileもこれを使っていそうな気はするんですが…。
コードを調べると：
# https://github.com/python/cpython/blob/ad1a25f499362eaf9cbfcafa0b8e2454eb43dcf1/Lib/profile.py#L418
def runctx(self, cmd, globals, locals):
self.set_cmd(cmd)
sys.setprofile(self.dispatcher)
try:
exec(cmd, globals, locals)
finally:
sys.setprofile(None)
return self
案の定、sys.setprofileという、PyEval_SetProfileのPython版を使って、C言語の関数ではなくPythonの関数をcallbackとしているだけのように読めます。
1つの引数を取る関数をプロファイルしたい場合、次のようにできます:
import cProfile import re cProfile.run('re.compile("foo|bar")')
cProfileのコードはそんなにトリッキーな事をしているようには読めないので、cpythonがコンパイルできる環境ならcProfileも使えると思うんですが、cProfileが使えない環境は実際にあるのだろうか…。
いかがでしたか？
「だからなんだ」と言われればそれでオシマイなんですが、ソースコードを読むのはやっぱり重要だと痛感しました。ドキュメントにはすべては書いてないので。この記事が、いつか、cProfileの挙動に違和感を持った人の参考になりますように。
というわけで、次の記事では、マルチスレッドのPythonプログラムをプロファイルする方法を探していきます。
