トレースの例

デフォルトでは、すべてのコンポーネントでトレースが無効になっています。そのため、ランタイムシステムトレースを有効にするために最低限必要なことは、構成ファイルに mftrace.level または mftrace.level.mf.rts エントリを指定することです。たとえば、MFTRACE_CONFIG 環境変数セットを次のように設定したとします。

set MFTRACE_CONFIG=e:\mydir\ctf.cfg

export MFTRACE_CONFIG=/home/mydir/ctf.cfg

ここで、e:\mydir\ctf.cfg/home/mydir/ctf.cfg には次のエントリのみが含まれるとします。

mftrace.level=error

イベント ID 255 のエントリを持つトレースファイルは、ランタイムシステムエラーを生成したプロセスによって作成されます。このイベントを発行するために mf.rts コンポーネントのプロパティを指定する必要はありません。トレースレベルがエラーに設定されていれば十分です。

次の例では、アプリケーション mymain が使用されています。このアプリケーションは、次のコードを含むmymain.cbl および mysub.cbl という 2 つのプログラムで構成されています。

mymain.cbl：

 identification division.
 program-id. mymain.
 environment division.
 data division.
 working-storage section.
 01 my-var pic 9(9) external.
 procedure division.
     move 1 to my-var

     perform 5 times
         call 'mysub'
         add 1 to my-var
     end-perform

     cancel 'mysub'

     call 'myprog'
     goback.

mysub.cbl：

 identification division.
 program-id. mysub.
 environment division.
 data division.
 working-storage section.
 01 my-var pic 9(9) external.
 procedure division.
     display my-var
     goback.

mymain が実行されると、myprog の呼び出しのため、ランタイムシステムエラー 173 (呼び出されたプログラムファイルがドライブまたはディレクトリに見つからないエラー) が発生します。上記の構成を使用して生成されたトレースファイルの内容は、次のようになります。

1>   # -MFTRACE Text Emitter-
2>   # CommandLine      = mymain
3>   # ProcessId        = 2404
4>   # Date             = 2004/12/14
5>   # Time             = 11:54:42.875
6>   # Operating System = Windows XP Service Pack 1 (Build 2600)
7>   # Computer Name    = PC-NAME
8>   # Format           = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
9>   11:54:42.875 MF.RTS 255 3 173 1 "myprog"

1>   # -MFTRACE Text Emitter-
2>   # CommandLine      = mymain
3>   # ProcessId        = 442550
4>   # Date             = 2005/01/21
5>   # Time             = 11:19:44.498
6>   # Operating System = AIX 5.1
7>   # Computer Name    = asterix
8>   # Format           = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
9>   11:19:44.498 MF.RTS 255 3 173 1 "myprog"

1> # -MFTRACE Text Emitter- 2> # CommandLine = mymain 3> # ProcessId = 442550 4> # Date = 2005/01/21 5> # Time = 11:19:44.498 6> # Operating System = AIX 5.1 7> # Computer Name = asterix 8> # Format = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA) 9>   11:19:44.498 MF.RTS 255 3 173 1 "myprog"

1> から 8> と記されている項目は、TEXTFILE エミッターが出力するヘッダーレコードであり、トレースされるアプリケーションに関する情報を提供します。8> は後続のトレースエントリの形式を示します (この例ではデフォルトのトレースエントリ形式を使用しています)。したがって、エントリ 9> のフィールドは次のように解釈できます。

トレースファイル内の情報	擬似変数	説明
11:54:42.875 11:19:44.498	$(TIME)	トレースエントリが出力された時刻。
MF.RTS	$(COMPONENT)	トレースエントリを出力するコンポーネントの名前。MF.RTS は、ランタイムシステムを意味します。
255	$(EVENT)	イベント識別子。mf.rts コンポーネントのイベント識別子 255 は、ランタイムシステムエラーを意味します。
3	$(LEVEL)	エラーのレベル。次の値に基づきます。 0 = デバッグ 1 = 情報 2 = 警告 3 = エラー 4 = 致命的
173 1 "myprog"	$(DATA)	イベント固有のデータ。

INFO のトレースレベルを指定するように構成ファイル内の文を変更した後に mymain を再実行すると、次のようになります。

mftrace.level=info

作成されたトレースファイルには、実行時システムエラーイベントに加えて、実行時システムの初期化および初期化解除イベントのエントリが含まれています。このトレースファイルの内容は次のようになります。

    # -MFTRACE Text Emitter-
    # CommandLine      = mymain
    # ProcessId        = 2820
    # Date             = 2004/12/14
    # Time             = 12:27:04.317
    # Operating System = Windows XP Service Pack 1 (Build 2600)
    # Computer Name    = PC-NAME
    # Format           = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
    12:27:04.317 MF.RTS 128 1
    12:27:04.327 MF.RTS 129 1
    12:27:04.337 MF.RTS 255 3 173 1 "myprog"
    12:27:04.367 MF.RTS 130 1
    12:27:04.367 MF.RTS 131 1

    # -MFTRACE Text Emitter-
    # CommandLine      = mymain
    # ProcessId        = 1646624
    # Date             = 2005/01/21
    # Time             = 11:28:09.105
    # Operating System = AIX 5.1
    # Computer Name    = asterix
    # Format           = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
    11:28:09.105 MF.RTS 128 1
    11:28:09.135 MF.RTS 129 1
    11:28:09.225 MF.RTS 255 3 173 1 "myprog"
    11:28:09.226 MF.RTS 130 1
    11:28:09.226 MF.RTS 131 1

ランタイムシステムエラーが発生する前にアプリケーションが起動したプログラムを確認するには、PGM プロパティを設定する必要があります。プログラムがどこからロードされたか、およびいつ取り消されたかを確認するには、次のように PGMLOAD プロパティも設定する必要があります。

mftrace.level=info
mftrace.comp.mf.rts#pgm=true
mftrace.comp.mf.rts#pgmload=true

mymain を再実行すると、作成されたトレースファイルには、プログラムのロード、エントリ、終了、および取り消しイベントの追加項目が含まれます。このトレースファイルの内容は次のようになります。

    # -MFTRACE Text Emitter-
    # CommandLine      = mymain
    # ProcessId        = 4092
    # Date             = 2004/12/14
    # Time             = 13:44:30.868
    # Operating System = Windows XP Service Pack 1 (Build 2600)
    # Computer Name    = PC-NAME
    # Format           = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
    13:44:30.868 MF.RTS 128 1
    13:44:30.888 MF.RTS 129 1
    13:44:30.888 MF.RTS 19 1 0 0 "mymain" "" ""
    13:44:30.888 MF.RTS 6 1 17 0 "mymain"
    13:44:31.008 MF.RTS 19 1 0 0 "mysub" "gnt" "E:\myprogs"
    13:44:31.008 MF.RTS 6 1 1 0 "MYSUB"
    13:44:31.008 MF.RTS 7 1
    13:44:31.008 MF.RTS 6 1 1 0 "MYSUB"
    13:44:31.008 MF.RTS 7 1
    13:44:31.008 MF.RTS 6 1 1 0 "MYSUB"
    13:44:31.008 MF.RTS 7 1
    13:44:31.008 MF.RTS 6 1 1 0 "MYSUB"
    13:44:31.008 MF.RTS 7 1
    13:44:31.008 MF.RTS 6 1 1 0 "MYSUB"
    13:44:31.008 MF.RTS 7 1
    13:44:31.008 MF.RTS 20 1 0 0 "mysub"
1>  13:44:31.008 MF.RTS 6 1 1 0 "MYSUB"
    13:44:31.008 MF.RTS 7 1
    13:44:31.139 MF.RTS 255 3 173 1 "myprog"
    13:44:31.199 MF.RTS 130 1
    13:44:31.199 MF.RTS 20 1 0 0 "mymain"
2>  13:44:31.199 MF.RTS 6 1 17 0 "mymain"
    13:44:31.199 MF.RTS 7 1
    13:44:31.199 MF.RTS 131 1

    # -MFTRACE Text Emitter-
    # CommandLine      = mymain
    # ProcessId        = 1622058
    # Date             = 2005/01/21
    # Time             = 11:30:27.441
    # Operating System = AIX 5.1
    # Computer Name    = asterix
    # Format           = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
    11:30:27.441 MF.RTS 128 1
    11:30:27.451 MF.RTS 129 1
    11:30:27.452 MF.RTS 19 1 0 0 "mymain" "" ""
    11:30:27.510 MF.RTS 6 1 17 0 "mymain"
    11:30:27.513 MF.RTS 19 1 0 0 "mysub" "gnt" "/home/myprogs"
    11:30:27.513 MF.RTS 6 1 1 0 "MYSUB"
    11:30:27.513 MF.RTS 7 1
    11:30:27.513 MF.RTS 6 1 1 0 "MYSUB"
    11:30:27.513 MF.RTS 7 1
    11:30:27.513 MF.RTS 6 1 1 0 "MYSUB"
    11:30:27.513 MF.RTS 7 1
    11:30:27.513 MF.RTS 6 1 1 0 "MYSUB"
    11:30:27.513 MF.RTS 7 1
    11:30:27.513 MF.RTS 6 1 1 0 "MYSUB"
    11:30:27.513 MF.RTS 7 1
    11:30:27.513 MF.RTS 20 1 0 0 "mysub"
1>  11:30:27.513 MF.RTS 6 1 1 0 "MYSUB"
    11:30:27.513 MF.RTS 7 1
    11:30:27.515 MF.RTS 255 3 173 1 "myprog"
    11:30:27.515 MF.RTS 130 1
    11:30:27.515 MF.RTS 20 1 0 0 "mymain"
2>  11:30:27.515 MF.RTS 6 1 17 0 "mymain"
    11:30:27.515 MF.RTS 7 1
    11:30:27.516 MF.RTS 131 1

1> および 2> と記されている項目は、同じプログラムのイベントタイプ 20 のエントリ (論理キャンセル) の直後に、プログラムのイベントタイプ 6 および 7 のエントリ (プログラムのエントリおよび終了) を示します。これは、コンパイラがすべてのプログラムにキャンセルルーチンを埋め込んで、プログラムが開いたファイルを閉じるためです。これらのキャンセルルーチンは、論理キャンセル操作の一部としてランタイムシステムによって暗黙的に呼び出されます。

メモリ管理イベントを除くすべてのランタイムシステムイベントのトレースを有効にするには、次の構成ファイルエントリを使用します。

mftrace.level = info
mftrace.comp.mf.rts#all=true
mftrace.comp.mf.rts#memory=false

mymain を再実行すると、作成されたトレースファイルに外部データ項目の追加エントリが含まれます。AMODE 指令でプログラムをコンパイルした場合は、各 Mainframe Pointer Manager イベントのエントリも含まれます。このトレースファイルの内容は次のようになります。

    # -MFTRACE Text Emitter-
    # CommandLine      = mymain
    # ProcessId        = 2716
    # Date             = 2004/12/14
    # Time             = 14:33:22.704
    # Operating System = Windows XP Service Pack 1 (Build 2600)
    # Computer Name    = PC-NAME
    # Format           = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
    14:33:22.704 MF.RTS 128 1
    14:33:22.714 MF.RTS 129 1
    14:33:22.714 MF.RTS 19 1 0 0 "mymain" "" ""
    14:33:22.714 MF.RTS 6 1 17 0 "mymain"
1>  14:33:22.714 MF.RTS 26 1 "MY_VAR" 9
    14:33:22.714 MF.RTS 19 1 0 0 "mysub" "gnt" "E:\myprogs"
    14:33:22.724 MF.RTS 6 1 1 0 "MYSUB"
    14:33:22.724 MF.RTS 7 1
    14:33:22.724 MF.RTS 6 1 1 0 "MYSUB"
    14:33:22.724 MF.RTS 7 1
    14:33:22.724 MF.RTS 6 1 1 0 "MYSUB"
    14:33:22.724 MF.RTS 7 1
    14:33:22.724 MF.RTS 6 1 1 0 "MYSUB"
    14:33:22.724 MF.RTS 7 1
    14:33:22.724 MF.RTS 6 1 1 0 "MYSUB"
    14:33:22.724 MF.RTS 7 1
    14:33:22.724 MF.RTS 20 1 0 0 "mysub"
    14:33:22.724 MF.RTS 6 1 1 0 "MYSUB"
    14:33:22.724 MF.RTS 7 1
    14:33:22.724 MF.RTS 255 3 173 1 "myprog"
    14:33:22.764 MF.RTS 130 1
    14:33:22.764 MF.RTS 20 1 0 0 "mymain"
    14:33:22.764 MF.RTS 6 1 17 0 "mymain"
    14:33:22.764 MF.RTS 7 1
2>  14:33:22.764 MF.RTS 27 1 "MY_VAR"
    14:33:22.764 MF.RTS 131 1

    # -MFTRACE Text Emitter-
    # CommandLine      = mymain
    # ProcessId        = 1073210
    # Date             = 2005/01/21
    # Time             = 11:33:52.015
    # Operating System = AIX 5.1
    # Computer Name    = asterix
    # Format           = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
    11:33:52.015 MF.RTS 128 1
    11:33:52.031 MF.RTS 129 1
    11:33:52.032 MF.RTS 19 1 0 0 "mymain" "" ""
    11:33:52.090 MF.RTS 6 1 17 0 "mymain"
1>  11:33:52.091 MF.RTS 26 1 "my_var" 9
    11:33:52.093 MF.RTS 19 1 0 0 "mysub" "gnt" "/home/myprogs"
    11:33:52.093 MF.RTS 6 1 1 0 "MYSUB"
    11:33:52.093 MF.RTS 7 1
    11:33:52.093 MF.RTS 6 1 1 0 "MYSUB"
    11:33:52.093 MF.RTS 7 1
    11:33:52.093 MF.RTS 6 1 1 0 "MYSUB"
    11:33:52.093 MF.RTS 7 1
    11:33:52.093 MF.RTS 6 1 1 0 "MYSUB"
    11:33:52.093 MF.RTS 7 1
    11:33:52.093 MF.RTS 6 1 1 0 "MYSUB"
    11:33:52.093 MF.RTS 7 1
    11:33:52.093 MF.RTS 20 1 0 0 "mysub"
    11:33:52.093 MF.RTS 6 1 1 0 "MYSUB"
    11:33:52.094 MF.RTS 7 1
    11:33:52.095 MF.RTS 255 3 173 1 "myprog"
    11:33:52.096 MF.RTS 130 1
    11:33:52.096 MF.RTS 20 1 0 0 "mymain"
    11:33:52.096 MF.RTS 6 1 17 0 "mymain"
    11:33:52.096 MF.RTS 7 1
    11:33:52.096 MF.RTS 41 1 0
    11:33:52.096 MF.RTS 41 1 1
2>  11:33:52.096 MF.RTS 27 1 "my_var"
    11:33:52.096 MF.RTS 131 1

1> および 2> と記された項目は、外部データ項目の追加エントリを示します。