DTrace と SystemTap で CPython を測定する
*****************************************

Dtrace と SystemTap はモニタリングツールで、コンピュータシステムのプロ
セスが何をしているかを調べる方法を提供します。 どちらもドメイン固有言
語 (domain-specific language) を使用して、次のことができるスクリプトを
ユーザが書けます:

* 観測対象のプロセスを絞り込む

* 関心のあるプロセスからデータを収集する

* 収集したデータからレポートを生成する

Python 3.6 では、 CPython は "プローブ" としても知られる "マーカー" を
埋め込んだビルドが行えます。 マーカーは DTrace や SystemTap のスクリプ
トから観測でき、システムの CPython プロセスが何をしているかを観察する
のが簡単になります。

DTrace マーカーは CPython インタプリタの実装詳細です。 CPython のバー
ジョン間でプローブの互換性があるという保証はありません。 CPython のバ
ージョンを変えると、 DTrace スクリプトは警告無しに動作しなくなったり、
おかしな動作をする可能性があります。


静的マーカーの有効化
====================

macOS には組み込みの DTrace サポートが備わっています。 Linux では
SystemTap 用のマーカーを埋め込んで CPython をビルドするためには、
SystemTap 開発ツールをインストールしなければなりません。

Linux マシンでは、 SystemTap 開発ツールのインストールは次のように行え
ます:

   $ yum install systemtap-sdt-devel

もしくは:

   $ sudo apt-get install systemtap-sdt-dev

続いて "--with-dtrace オプションで CPython を構成" する必要があります:

   checking for --with-dtrace... yes

macOS では Python プロセスをバックグラウンドで実行し、Python プロバイ
ダが提供するすべてのプローブを列挙すると、利用可能な DTrace プローブを
確認できます。

   $ python3.6 -q &
   $ sudo dtrace -l -P python$!  # or: dtrace -l -m python3.6

      ID   PROVIDER            MODULE                          FUNCTION NAME
   29564 python18035        python3.6          _PyEval_EvalFrameDefault function-entry
   29565 python18035        python3.6             dtrace_function_entry function-entry
   29566 python18035        python3.6          _PyEval_EvalFrameDefault function-return
   29567 python18035        python3.6            dtrace_function_return function-return
   29568 python18035        python3.6                           collect gc-done
   29569 python18035        python3.6                           collect gc-start
   29570 python18035        python3.6          _PyEval_EvalFrameDefault line
   29571 python18035        python3.6                 maybe_dtrace_line line

Linux では、ビルドしたバイナリに ".note.stapsdt" セクションが含まれて
いるか調べると、SystemTap の静的マーカーの有無を確認できます。

   $ readelf -S ./python | grep .note.stapsdt
   [30] .note.stapsdt        NOTE         0000000000000000 00308d78

Python を共有ライブラリとしてビルドした場合 (configure オプション "--
enable-shared" を指定した場合) は、共有ライブラリの中を調べる必要があ
ります。 例えば次のようにします。

   $ readelf -S libpython3.3dm.so.1.0 | grep .note.stapsdt
   [29] .note.stapsdt        NOTE         0000000000000000 00365b68

十分に新しい readelf ではメタデータを出力できます:

   $ readelf -n ./python

   Displaying notes found at file offset 0x00000254 with length 0x00000020:
       Owner                 Data size          Description
       GNU                  0x00000010          NT_GNU_ABI_TAG (ABI version tag)
           OS: Linux, ABI: 2.6.32

   Displaying notes found at file offset 0x00000274 with length 0x00000024:
       Owner                 Data size          Description
       GNU                  0x00000014          NT_GNU_BUILD_ID (unique build ID bitstring)
           Build ID: df924a2b08a7e89f6e11251d4602022977af2670

   Displaying notes found at file offset 0x002d6c30 with length 0x00000144:
       Owner                 Data size          Description
       stapsdt              0x00000031          NT_STAPSDT (SystemTap probe descriptors)
           Provider: python
           Name: gc__start
           Location: 0x00000000004371c3, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bf6
           Arguments: -4@%ebx
       stapsdt              0x00000030          NT_STAPSDT (SystemTap probe descriptors)
           Provider: python
           Name: gc__done
           Location: 0x00000000004374e1, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bf8
           Arguments: -8@%rax
       stapsdt              0x00000045          NT_STAPSDT (SystemTap probe descriptors)
           Provider: python
           Name: function__entry
           Location: 0x000000000053db6c, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6be8
           Arguments: 8@%rbp 8@%r12 -4@%eax
       stapsdt              0x00000046          NT_STAPSDT (SystemTap probe descriptors)
           Provider: python
           Name: function__return
           Location: 0x000000000053dba8, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bea
           Arguments: 8@%rbp 8@%r12 -4@%eax

上記のメタデータには、SystemTap が適所に配置された機械語命令を書き換え
、SystemTap スクリプトで使うトレースフックを有効にするための情報が含ま
れています。


静的 DTrace プローブ
====================

次の DTrace スクリプトの例は、Python スクリプトの呼び出しと復帰の階層
を表示します。 "start" という関数の呼び出し中だけをトレースするため、
インポート時の関数呼び出しは表示されません:

   self int indent;

   python$target:::function-entry
   /copyinstr(arg1) == "start"/
   {
           self->trace = 1;
   }

   python$target:::function-entry
   /self->trace/
   {
           printf("%d\t%*s:", timestamp, 15, probename);
           printf("%*s", self->indent, "");
           printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2);
           self->indent++;
   }

   python$target:::function-return
   /self->trace/
   {
           self->indent--;
           printf("%d\t%*s:", timestamp, 15, probename);
           printf("%*s", self->indent, "");
           printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2);
   }

   python$target:::function-return
   /copyinstr(arg1) == "start"/
   {
           self->trace = 0;
   }

この例は次のように実行できます:

   $ sudo dtrace -q -s call_stack.d -c "python3.6 script.py"

出力はこのようになります:

   156641360502280  function-entry:call_stack.py:start:23
   156641360518804  function-entry: call_stack.py:function_1:1
   156641360532797  function-entry:  call_stack.py:function_3:9
   156641360546807 function-return:  call_stack.py:function_3:10
   156641360563367 function-return: call_stack.py:function_1:2
   156641360578365  function-entry: call_stack.py:function_2:5
   156641360591757  function-entry:  call_stack.py:function_1:1
   156641360605556  function-entry:   call_stack.py:function_3:9
   156641360617482 function-return:   call_stack.py:function_3:10
   156641360629814 function-return:  call_stack.py:function_1:2
   156641360642285 function-return: call_stack.py:function_2:6
   156641360656770  function-entry: call_stack.py:function_3:9
   156641360669707 function-return: call_stack.py:function_3:10
   156641360687853  function-entry: call_stack.py:function_4:13
   156641360700719 function-return: call_stack.py:function_4:14
   156641360719640  function-entry: call_stack.py:function_5:18
   156641360732567 function-return: call_stack.py:function_5:21
   156641360747370 function-return:call_stack.py:start:28


静的 SystemTap マーカー
=======================

SystemTap との連携を低レベルで行う方法は、静的マーカーを直接使うことで
す。 この場合、マーカーを含むバイナリファイルを明示する必要があります
。

例えば、この SystemTap スクリプトは Python の呼び出し/返却
(call/return) 階層を表示するのに使えます:

   probe process("python").mark("function__entry") {
        filename = user_string($arg1);
        funcname = user_string($arg2);
        lineno = $arg3;

        printf("%s => %s in %s:%d\\n",
               thread_indent(1), funcname, filename, lineno);
   }

   probe process("python").mark("function__return") {
       filename = user_string($arg1);
       funcname = user_string($arg2);
       lineno = $arg3;

       printf("%s <= %s in %s:%d\\n",
              thread_indent(-1), funcname, filename, lineno);
   }

この例は次のように実行できます:

   $ stap \
     show-call-hierarchy.stp \
     -c "./python test.py"

出力はこのようになります:

   11408 python(8274):        => __contains__ in Lib/_abcoll.py:362
   11414 python(8274):         => __getitem__ in Lib/os.py:425
   11418 python(8274):          => encode in Lib/os.py:490
   11424 python(8274):          <= encode in Lib/os.py:493
   11428 python(8274):         <= __getitem__ in Lib/os.py:426
   11433 python(8274):        <= __contains__ in Lib/_abcoll.py:366

それぞれの列の内容は次の通りです:

* スクリプトを起動してからのマイクロ秒単位の時間

* 実行可能ファイルの名前

* プロセスの PID

そして、残りの部分はスクリプトが実行していた呼び出し/返却階層を表示し
ています。

"--enable-shared" を指定した CPython のビルドでは、マーカーは
libpython 共有ライブラリに含まれるため、プローブのドットで区切ったパス
にもそれを反映する必要があります。 例えば、上の例の次の行は:

   probe process("python").mark("function__entry") {

次のように書き換えます:

   probe process("python").library("libpython3.6dm.so.1.0").mark("function__entry") {

(CPython 3.6 の デバッグビルド を想定しています)


利用可能な静的マーカー
======================

function__entry(str filename, str funcname, int lineno)

   このマーカーは Python の関数の実行が開始されたことを示しています。
   このマーカーは、ピュア Python (バイトコード) の関数でしか起動されま
   せん。

   ファイル名、関数名、行番号が位置引数としてトレーススクリプトに渡さ
   れます。 それぞれ "$arg1"、"$arg2"、"$arg3" を使ってアクセスしてく
   ださい:

      * "$arg1" : "(const char *)" ファイル名、 "user_string($arg1)"
        でアクセスできます

      * "$arg2" : "(const char *)" 関数名、 "user_string($arg2)" でア
        クセスできます

      * "$arg3" : "int" 行番号

function__return(str filename, str funcname, int lineno)

   このマーカーは "function__entry()" と対をなし、Python 関数の実行が
   終了したことを示します ("return" による終了と例外による終了の両方を
   含みます)。 ピュア Python (バイトコード) の関数でのみ発火します。

   引数は "function__entry()" と同じです。

line(str filename, str funcname, int lineno)

   このマーカーは、これから実行される Python の行を示しています。 これ
   は Python プロファイラによる行ごとのトレースと同等です。 このマーカ
   ーは C 関数の内部では起動されません。

   引数は "function__entry()" と同じです。

gc__start(int generation)

   Python インタプリタがガベージコレクションのサイクルを開始したときに
   発火します。 "arg0" は "gc.collect()" と同様に、走査する世代を指定
   します。

gc__done(long collected)

   Python インタプリタがガベージコレクションのサイクルを終了したときに
   発火します。 "arg0" は回収したオブジェクトの数です。

import__find__load__start(str modulename)

   "importlib" がモジュールの検索と読み込みを試みる前に発火します。
   "arg0" はモジュール名です。

   Added in version 3.7.

import__find__load__done(str modulename, int found)

   "importlib" の find_and_load 関数が呼び出された後に発火します。
   "arg0" はモジュール名で、"arg1" はモジュールの読み込みが成功したか
   どうかを示します。

   Added in version 3.7.

audit(str event, void *tuple)

   "sys.audit()" または "PySys_Audit()" が呼び出されたときに発火します
   。 "arg0" は C 文字列のイベント名、"arg1" はタプルオブジェクトへの
   "PyObject" ポインタです。

   Added in version 3.8.


C エントリーポイント
--------------------

DTrace マーカーを簡単に発火させられるように、Python の C API は各静的
マーカーに対応するヘルパー関数を提供しています。 DTrace を有効にせずに
ビルドした Python では、これらの関数は何もしません。

通常は Python が呼び出すため、自分で呼び出す必要はありません。

+----------------------------------------------------+---------------------------+---------------------------+
| C API 関数                                         | 静的マーカー              | 注釈                      |
|====================================================|===========================|===========================|
| void PyDTrace_LINE(const char *arg0, const char    | "line()"                  |                           |
| *arg1, int arg2)                                   |                           |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_FUNCTION_ENTRY(const char *arg0,     | "function__entry()"       |                           |
| const char *arg1, int arg2)                        |                           |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_FUNCTION_RETURN(const char *arg0,    | "function__return()"      |                           |
| const char *arg1, int arg2)                        |                           |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_GC_START(int arg0)                   | "gc__start()"             |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_GC_DONE(Py_ssize_t arg0)             | "gc__done()"              |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_INSTANCE_NEW_START(int arg0)         | "instance__new__start()"  | Python では未使用         |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_INSTANCE_NEW_DONE(int arg0)          | "instance__new__done()"   | Python では未使用         |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_INSTANCE_DELETE_START(int arg0)      | "instance__delete__start  | Python では未使用         |
|                                                    | ()"                       |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_INSTANCE_DELETE_DONE(int arg0)       | "instance__delete__done(  | Python では未使用         |
|                                                    | )"                        |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_IMPORT_FIND_LOAD_START(const char    | "import__find__load__sta  |                           |
| *arg0)                                             | rt()"                     |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_IMPORT_FIND_LOAD_DONE(const char     | "import__find__load__don  |                           |
| *arg0, int arg1)                                   | e()"                      |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_AUDIT(const char *arg0, void *arg1)  | "audit()"                 |                           |
+----------------------------------------------------+---------------------------+---------------------------+


C でのプローブの有効性確認
--------------------------

int PyDTrace_LINE_ENABLED(void)

int PyDTrace_FUNCTION_ENTRY_ENABLED(void)

int PyDTrace_FUNCTION_RETURN_ENABLED(void)

int PyDTrace_GC_START_ENABLED(void)

int PyDTrace_GC_DONE_ENABLED(void)

int PyDTrace_INSTANCE_NEW_START_ENABLED(void)

int PyDTrace_INSTANCE_NEW_DONE_ENABLED(void)

int PyDTrace_INSTANCE_DELETE_START_ENABLED(void)

int PyDTrace_INSTANCE_DELETE_DONE_ENABLED(void)

int PyDTrace_IMPORT_FIND_LOAD_START_ENABLED(void)

int PyDTrace_IMPORT_FIND_LOAD_DONE_ENABLED(void)

int PyDTrace_AUDIT_ENABLED(void)

   "PyDTrace" 関数の呼び出しはすべて、これらの関数のいずれかを呼び出し
   て有効性を確認してから行う必要があります。 これにより、プローブが無
   効なときの性能への影響を最小限に抑えられます。

   DTrace を有効にせずにビルドした場合、これらの関数は何もせず "0" を
   返します。


SystemTap Tapset
================

SystemTap との連携を高レベルで行う方法は、"tapset" を使うことです。 こ
れは SystemTap のライブラリに相当し、静的マーカーの低レベルの詳細の一
部を隠します。

共有ライブラリを使わない CPython のビルドを対象とする tapset ファイル
の例を示します:

   /*
      Provide a higher-level wrapping around the function__entry and
      function__return markers:
    \*/
   probe python.function.entry = process("python").mark("function__entry")
   {
       filename = user_string($arg1);
       funcname = user_string($arg2);
       lineno = $arg3;
       frameptr = $arg4
   }
   probe python.function.return = process("python").mark("function__return")
   {
       filename = user_string($arg1);
       funcname = user_string($arg2);
       lineno = $arg3;
       frameptr = $arg4
   }

このファイルを SystemTap の tapset ディレクトリ (例えば
"/usr/share/systemtap/tapset") にインストールすると、次のプローブポイ
ントが利用できます:

python.function.entry(str filename, str funcname, int lineno, frameptr)

   このプローブポイントは Python 関数の実行が開始されたことを示します
   。 ピュア Python (バイトコード) の関数でのみ発火します。

python.function.return(str filename, str funcname, int lineno, frameptr)

   This probe point is the converse of "python.function.return", and
   indicates that execution of a Python function has ended (either via
   "return", or via an exception).  It is only triggered for pure-
   Python (bytecode) functions.


使用例
======

次の SystemTap スクリプトは上の tapset を使い、先ほどの Python 関数の
呼び出し階層をトレースする例を簡潔に実装しています。 静的マーカーの名
前を直接指定する必要がありません:

   probe python.function.entry
   {
     printf("%s => %s in %s:%d\n",
            thread_indent(1), funcname, filename, lineno);
   }

   probe python.function.return
   {
     printf("%s <= %s in %s:%d\n",
            thread_indent(-1), funcname, filename, lineno);
   }

次のスクリプトは上の tapset を使い、実行中の CPython コード全体を top
のように表示します。 システム全体で最も頻繁に実行が開始されたバイトコ
ードフレームの上位 20 件を毎秒表示します:

   global fn_calls;

   probe python.function.entry
   {
       fn_calls[pid(), filename, funcname, lineno] += 1;
   }

   probe timer.ms(1000) {
       printf("\033[2J\033[1;1H") /* clear screen \*/
       printf("%6s %80s %6s %30s %6s\n",
              "PID", "FILENAME", "LINE", "FUNCTION", "CALLS")
       foreach ([pid, filename, funcname, lineno] in fn_calls- limit 20) {
           printf("%6d %80s %6d %30s %6d\n",
               pid, filename, lineno, funcname,
               fn_calls[pid, filename, funcname, lineno]);
       }
       delete fn_calls;
   }
