trace – 実行された通りに Python コードを追跡する

目的:カバレッジやコールグラフ情報を生成するためにプログラムが実行された通りにコードや関数の動きを監視する
利用できるバージョン:2.3 以上

trace モジュールはプログラムがどういった順番に実行されるかを理解し易くします。実行されたコードをトレースしたり、カバレッジレポートを生成したり、関数間の呼び出し関係を調査したりできます。

コマンドラインインタフェース

コマンドラインから直接 trace を使用するのが簡単です。入力として次の Python スクリプトを使用します。

from recurse import recurse

def main():
    print 'This is the main program.'
    recurse(2)
    return

if __name__ == '__main__':
    main()
def recurse(level):
    print 'recurse(%s)' % level
    if level:
        recurse(level-1)
    return

def not_called():
    print 'This function is never called.'

トレース実行

--trace オプションを使用してプログラム内のどのコードが実行されるかが分かります。

$ python -m trace --trace trace_example/main.py
 --- modulename: main, funcname: <module>
main.py(7): """
main.py(12): from recurse import recurse
 --- modulename: recurse, funcname: <module>
recurse.py(7): """
recurse.py(12): def recurse(level):
recurse.py(18): def not_called():
main.py(14): def main():
main.py(19): if __name__ == '__main__':
main.py(20):     main()
 --- modulename: main, funcname: main
main.py(15):     print 'This is the main program.'
This is the main program.
main.py(16):     recurse(2)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(2)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(1)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(0)
recurse.py(14):     if level:
recurse.py(16):     return
recurse.py(16):     return
recurse.py(16):     return
main.py(17):     return
 --- modulename: trace, funcname: _unsettrace
trace.py(80):         sys.settrace(None)

この出力の最初の部分は trace が実行したセットアップ処理です。残りの出力は、関数が定義されているモジュールとその関数へのエントリ、実行されたソースファイルの行番号です。 main() で呼び出されて期待した通りに recurse() は3回呼び出されることが分かります。

コードカバレッジ

コマンドラインから trace--count オプションを与えるとコードカバレッジレポートを生成します。ソースコードのどの行が実行されて、どの行がスキップされたかが分かります。プログラムは通常、複数のソースファイルで構成されるので、分割されたカバレッジレポートがそれぞれに生成されます。デフォルトでは、カバレッジレポートファイルはモジュールと同じディレクトリに .py ではなく .cover という拡張子でモジュールと同じ名前で書き込まれます。

$ python -m trace --count trace_example/main.py
This is the main program.
recurse(2)
recurse(1)
recurse(0)

2つのファイルが出力されます。 trace_example/main.cover

       
    1: from recurse import recurse
       
    1: def main():
    1:     print 'This is the main program.'
    1:     recurse(2)
    1:     return
       
    1: if __name__ == '__main__':
    1:     main()

trace_example/recurse.cover です。

       
    1: def recurse(level):
    3:     print 'recurse(%s)' % level
    3:     if level:
    2:         recurse(level-1)
    3:     return
       
    1: def not_called():
           print 'This function is never called.'

Note

def recurse(level): 行の件数は 1 ですが、この関数が1度だけ呼び出されたという意味ではありません。これは関数の 定義 が1度だけ行われたことを表します。

おそらくは違うオプションでカバレッジデータを保存するためにプログラムを数回実行して、それらを組み合わせたレポートも生成できます。

$ python -m trace --coverdir coverdir1 --count --file coverdir1/coverage_report.dat trace_example/main.py
Skipping counts file 'coverdir1/coverage_report.dat': [Errno 2] No such file or directory: 'coverdir1/coverage_report.dat'
This is the main program.
recurse(2)
recurse(1)
recurse(0)

$ python -m trace --coverdir coverdir1 --count --file coverdir1/coverage_report.dat trace_example/main.py
This is the main program.
recurse(2)
recurse(1)
recurse(0)

$ python -m trace --coverdir coverdir1 --count --file coverdir1/coverage_report.dat trace_example/main.py
This is the main program.
recurse(2)
recurse(1)
recurse(0)

カバレッジ情報が .cover ファイルに記録されたら --report オプションでレポートを生成できます。

$ python -m trace --coverdir coverdir1 --report --summary --missing --file coverdir1/coverage_report.dat trace_example/main.py
lines   cov%   module   (path)
  515     0%   trace   (/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/trace.py)
    8   100%   trace_example.main   (trace_example/main.py)
    8    87%   trace_example.recurse   (trace_example/recurse.py)

3回プログラムを実行したので、カバレッジレポートは最初のレポートよりも3倍多くなります。 --summary オプションは上述したレポートのカバレッジ情報のパーセンテージを追加します。 recurse モジュールは 87% だけ実行されました。recurse の cover ファイルをざっと見てみると not_called() 関数が実行されていないことが >>>>>> の接頭辞で表されています。

       
    3: def recurse(level):
    9:     print 'recurse(%s)' % level
    9:     if level:
    6:         recurse(level-1)
    9:     return
       
    3: def not_called():
>>>>>>     print 'This function is never called.'

呼び出し関係

カバレッジ情報に加えて trace が関数間の呼び出し関係を集めてレポートを生成します。

関数呼び出しのシンプルなリストは --listfuncs オプションを使用してください。

$ python -m trace --listfuncs trace_example/main.py
This is the main program.
recurse(2)
recurse(1)
recurse(0)

functions called:
filename: /Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/trace.py, modulename: trace, funcname: _unsettrace
filename: trace_example/main.py, modulename: main, funcname: <module>
filename: trace_example/main.py, modulename: main, funcname: main
filename: trace_example/recurse.py, modulename: recurse, funcname: <module>
filename: trace_example/recurse.py, modulename: recurse, funcname: recurse

どの関数から呼び出したかの詳細については --trackcalls オプションを使用してください。

$ python -m trace --listfuncs --trackcalls trace_example/main.py
This is the main program.
recurse(2)
recurse(1)
recurse(0)

calling relationships:

*** /Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/trace.py ***
    trace.Trace.runctx -> trace._unsettrace
  --> trace_example/main.py
    trace.Trace.runctx -> main.<module>

*** trace_example/main.py ***
    main.<module> -> main.main
  --> trace_example/recurse.py
    main.<module> -> recurse.<module>
    main.main -> recurse.recurse

*** trace_example/recurse.py ***
    recurse.recurse -> recurse.recurse

プログラミングインタフェース

trace のインタフェース上でもう少し制御するためにプログラム内で Trace オブジェクトを使用して実行できます。 Trace クラスは1つの関数を実行する、もしくはトレースする Python コマンドを実行する前にフィクスチャとその他の依存関係を設定します。

import trace
from trace_example.recurse import recurse

tracer = trace.Trace(count=False, trace=True)
tracer.run('recurse(2)')

recurse() 関数の内部のみをトレースするサンプルなので main.py からの情報が出力結果には含まれません。

$ python trace_run.py
 --- modulename: trace_run, funcname: <module>
<string>(1):   --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(2)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(1)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(0)
recurse.py(14):     if level:
recurse.py(16):     return
recurse.py(16):     return
recurse.py(16):     return

これと同じ出力は runfunc() メソッドでも生成されます。 runfunc() はトレーサが呼び出されるときに関数へ渡す任意の位置引数とキーワード引数を取ります。

import trace
from trace_example.recurse import recurse

tracer = trace.Trace(count=False, trace=True)
tracer.runfunc(recurse, 2)
$ python trace_runfunc.py
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(2)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(1)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(0)
recurse.py(14):     if level:
recurse.py(16):     return
recurse.py(16):     return
recurse.py(16):     return

結果データを保存する

件数とカバレッジ情報はコマンドラインインタフェースと同様に記録されます。そのデータは Trace オブジェクトの CoverageResults インスタンスを使用して明示的に保存されなければなりません。

import trace
from trace_example.recurse import recurse

tracer = trace.Trace(count=True, trace=False)
tracer.runfunc(recurse, 2)

results = tracer.results()
results.write_results(coverdir='coverdir2')
$ python trace_CoverageResults.py
recurse(2)
recurse(1)
recurse(0)

$ find coverdir2
coverdir2
coverdir2/trace_example.recurse.cover

coverdir2/trace_example.recurse.cover のコンテンツです。

       #!/usr/bin/env python
       # encoding: utf-8
       #
       # Copyright (c) 2008 Doug Hellmann All rights reserved.
       #
       """
>>>>>> """
       
       #__version__ = "$Id$"
       #end_pymotw_header
       
>>>>>> def recurse(level):
    3:     print 'recurse(%s)' % level
    3:     if level:
    2:         recurse(level-1)
    3:     return
       
>>>>>> def not_called():
>>>>>>     print 'This function is never called.'

レポートを生成するための件数データを保存するために Trace へ渡す infileoutfile 引数を使用してください。

import trace
from trace_example.recurse import recurse

tracer = trace.Trace(count=True, trace=False, outfile='trace_report.dat')
tracer.runfunc(recurse, 2)

report_tracer = trace.Trace(count=False, trace=False, infile='trace_report.dat')
results = tracer.results()
results.write_results(summary=True, coverdir='/tmp')

以前に保存されたデータを読み込むために infile へ、トレースした新たな結果を書き込むために outfile へファイル名を渡します。 infileoutfile が同じファイルなら、データを累積してファイルが更新されます。

$ python trace_report.py
recurse(2)
recurse(1)
recurse(0)
lines   cov%   module   (path)
    8    50%   trace_example.recurse   (/Users/dhellmann/Devel/pymotw-ja/t2y/PyMOTW/trace/trace_example/recurse.py)

Trace オプション

Trace のコンストラクタは実行時の振る舞いを制御する複数のオプションパラメータを取ります。

count
ブーリアン。行番号を数えるかを指定します。デフォルトは True です。
countfuncs
ブーリアン。実行して呼び出された関数の数を表示するかを指定します。デフォルトは False です。
countcallers
ブーリアン。呼び出し側と呼び出される側を追跡するかを指定します。デフォルトは False です。
ignoremods
シーケンス。カバレッジを追跡するときに無視するモジュールやパッケージを指定します。デフォルトは空のタプルです。
ignoredirs
シーケンス。無視するモジュールやパッケージを含むディレクトリを指定します。デフォルトは空のタプルです。
infile
キャッシュされた件数を含む入力ファイル名です。デフォルトは None です。
outfile
件数をキャッシュするための出力ファイル名です。デフォルトは None で、データは保存されません。

See also

trace
本モジュールの標準ライブラリドキュメント
Tracing a Program As It Runs
sys モジュールは実行時にインタープリタに独自トレース関数を追加するための仕組みを提供します
coverage.py
Ned Batchelder のカバレッジモジュール
figleaf
Titus Brown のカバレッジアプリケーション
Bookmark and Share