トレースの例
デフォルトでは、すべてのコンポーネントでトレースが無効になっています。そのため、ランタイム システム トレースを有効にするために最低限必要なことは、構成ファイルに mftrace.level または mftrace.level.mf.rts エントリを指定することです。たとえば、MFTRACE_CONFIG 環境変数セットを次のように設定したとします。
Windows：
set MFTRACE_CONFIG=c:\mydir\ctf.cfg
UNIX：
export MFTRACE_CONFIG=/home/mydir/ctf.cfg
c:\mydir\ctf.cfg (Windows) および /home/mydir/ctf.cfg (UNIX) には、次のエントリのみが含まれるとします。
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 (呼び出されたプログラム ファイルがドライブまたはディレクトリに見つからないエラー) が発生します。上記の構成を使用して生成されたトレース ファイルの内容は、次のようになります。
Windows：
1> # -MFTRACE Text Emitter- 2> # CommandLine = mymain 3> # ProcessId = 17356 4> # Date = 2018/09/13 5> # Time = 15:12:27.993 6> # Operating System = Windows 10.0 (Build 16299) 7> # Computer Name = NWZ-ZINO10 8> # Format = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA) 9> 15:12:27.993 MF.RTS 255 3 173 1 "myprog"
UNIX：
1> # -MFTRACE Text Emitter- 2> # CommandLine = /opt/microfocus/VisualCOBOL/bin/rts32 mymain 3> # ProcessId = 442550 4> # Date = 2017/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 (Windows) 11:19:44.498 (UNIX) | $(TIME) | トレース エントリが出力された時刻。 |
| MF.RTS | $(COMPONENT) | トレース エントリを出力したコンポーネントの名前。MF.RTS は、ランタイム システムを意味します。 |
| 255 | $(EVENT) | イベント識別子。mf.rts コンポーネントのイベント識別子 255 は、ランタイム システム エラーを意味します。 |
| 3 | $(LEVEL) | エラーのレベル。次の値に基づきます。
|
| 173 1 "myprog" | $(DATA) | イベント固有のデータ。 |
次のように、INFO のトレース レベルを指定するように構成ファイル内の文を変更して、mymain を再実行したとします。
mftrace.level=info
作成されたトレース ファイルには、ランタイム システム エラー イベントに加えて、ランタイム システムの初期化および初期化解除イベントのエントリが含まれます。このトレース ファイルの内容は次のようになります。
Windows：
# -MFTRACE Text Emitter- # CommandLine = mymain # ProcessId = 15364 # Date = 2018/09/13 # Time = 15:15:34.667 # Operating System = Windows 10.0 (Build 16299) # Computer Name = NWZ-ZINO10 # Format = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA) 15:15:34.667 MF.RTS 128 1 15:15:34.668 MF.RTS 74 1 "5.0.0.12" 15:15:34.670 MF.RTS 129 1 15:15:34.684 MF.RTS 255 3 173 1 "myprog" 15:15:36.403 MF.RTS 130 1 15:15:36.403 MF.RTS 131 1
UNIX：
# -MFTRACE Text Emitter- # CommandLine = /opt/microfocus/VisualCOBOL/bin/rts32 mymain # ProcessId = 1646624 # Date = 2017/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.106 MF.RTS 74 1 "5.0.0.12" 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 を再実行すると、作成されたトレース ファイルには、プログラムのロード、進入、終了、および取り消しイベントの追加エントリが含まれます。このトレース ファイルの内容は次のようになります。
Windows：
# -MFTRACE Text Emitter-
# CommandLine = mymain
# ProcessId = 8012
# Date = 2018/09/13
# Time = 14:59:34.417
# Operating System = Windows 10.0 (Build 16299)
# Computer Name = NWZ-ZINO10
# Format = $(TIME) $(COMPONENT) $(EVENT) $(LEVEL)$(DATA)
14:59:34.417 MF.RTS 128 1
14:59:34.419 MF.RTS 74 1 "5.0.0.12"
14:59:34.420 MF.RTS 23 1 0 0 "vcruntime140" 00007FFDB8F00000
14:59:34.420 MF.RTS 23 1 0 0 "api-ms-win-crt-conio-l1-1-0" 00007FFDBB890000
14:59:34.420 MF.RTS 23 1 0 0 "api-ms-win-crt-convert-l1-1-0" 00007FFDBB890000
14:59:34.420 MF.RTS 23 1 0 0 "api-ms-win-crt-environment-l1-1-0" 00007FFDBB890000
14:59:34.420 MF.RTS 23 1 0 0 "api-ms-win-crt-filesystem-l1-1-0" 00007FFDBB890000
14:59:34.420 MF.RTS 23 1 0 0 "api-ms-win-crt-heap-l1-1-0" 00007FFDBB890000
14:59:34.420 MF.RTS 23 1 0 0 "api-ms-win-crt-locale-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-math-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-multibyte-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-private-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-process-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-runtime-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-stdio-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-string-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-time-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 23 1 0 0 "api-ms-win-crt-utility-l1-1-0" 00007FFDBB890000
14:59:34.421 MF.RTS 129 1
14:59:34.421 MF.RTS 19 1 0 0 "mymain" "" ""
14:59:34.425 MF.RTS 6 1 17 0 "mymain" "MYMAIN"
14:59:34.425 MF.RTS 19 1 0 0 "mysub" "" ""
14:59:34.425 MF.RTS 6 1 17 0 "mysub" "MYSUB"
14:59:34.426 MF.RTS 7 1 "mysub"
14:59:34.426 MF.RTS 6 1 17 0 "mysub" "MYSUB"
14:59:34.427 MF.RTS 7 1 "mysub"
14:59:34.427 MF.RTS 6 1 17 0 "mysub" "MYSUB"
14:59:34.428 MF.RTS 7 1 "mysub"
14:59:34.428 MF.RTS 6 1 17 0 "mysub" "MYSUB"
14:59:34.429 MF.RTS 7 1 "mysub"
14:59:34.429 MF.RTS 6 1 17 0 "mysub" "MYSUB"
14:59:34.429 MF.RTS 7 1 "mysub"
1> 14:59:34.429 MF.RTS 20 1 0 0 "mysub"
14:59:34.429 MF.RTS 140 1 1
14:59:34.429 MF.RTS 141 1 1
14:59:34.434 MF.RTS 255 3 173 1 "myprog"
14:59:34.435 MF.RTS 140 1 2 "
Load error : file 'myprog'
error code: 173, pc=0, call=1, seg=0
173 Called program file not found in drive/directory "
14:59:37.619 MF.RTS 141 1 2
14:59:37.619 MF.RTS 130 1
14:59:37.619 MF.RTS 140 1 0 0 0 127
14:59:37.619 MF.RTS 141 1 0
14:59:37.619 MF.RTS 140 1 3 0
2> 14:59:37.619 MF.RTS 20 1 0 0 "mymain"
14:59:37.619 MF.RTS 140 1 1
14:59:37.619 MF.RTS 141 1 1
14:59:37.619 MF.RTS 21 1 0 0 "mymain"
14:59:37.619 MF.RTS 141 1 3
14:59:37.619 MF.RTS 140 1 0 0 128 255
14:59:37.619 MF.RTS 141 1 0
14:59:37.619 MF.RTS 140 1 4 0
14:59:37.619 MF.RTS 21 1 0 0 "mysub"
14:59:37.619 MF.RTS 141 1 4
14:59:37.620 MF.RTS 131 1
UNIX：
# -MFTRACE Text Emitter-
# CommandLine = /opt/microfocus/VisualCOBOL/bin/rts32 mymain
# ProcessId = 1622058
# Date = 2017/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
1> 11:30:27.513 MF.RTS 20 1 0 0 "mysub"
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
2> 11:30:27.515 MF.RTS 20 1 0 0 "mymain"
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 (論理キャンセル) を示しています。これは、プログラムが開いたファイルを閉じるために、コンパイラがすべてのプログラムにキャンセル ルーチンを埋め込むためです。これらのキャンセル ルーチンは、論理キャンセル操作の一部としてランタイム システムによって暗黙的に呼び出されます。
メモリ管理イベントを除くすべてのランタイム システム イベントのトレースを有効にするには、次の構成ファイル エントリを使用します。
mftrace.level = info mftrace.comp.mf.rts#all=true mftrace.comp.mf.rts#memory=false
mymain を再実行すると、作成されたトレース ファイルに外部データ項目の追加エントリが含まれます。AMODE 指令でプログラムをコンパイルした場合は、各 Mainframe Pointer Manager イベントのエントリも含まれます。このトレース ファイルの内容は次のようになります。
Windows：
UNIX：
# -MFTRACE Text Emitter-
# CommandLine = /opt/microfocus/VisualCOBOL/bin/rts32 mymain
# ProcessId = 1073210
# Date = 2017/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> と記されているエントリは、外部データ項目について追加されたエントリの最初と最後を示しています。