Tracing Sink Machine Processing

In this section:

Using the Server Trace Facility

Using APPL-level Traces

In addition to logging, two types of tracing can be invoked. The sink machine trace facility captures communication and and data exchange between the server and its clients and writes them to DDNAME FSTRACE. APPL-level traces display messages about server operation on the terminal.

Note: Turning on a trace generates huge amount of trace data. Therefore, it is only practical to turn on traces in order to find problems, and it is essential to reduce the problem to the minimal size before running the application with traces on.


Top of page

Using the Server Trace Facility

How to:

Turn the Trace Facility On or Off

Example:

Sample Trace File

You can use the TRACEON server command to generate a trace of commands and data exchange between the sink machine and its clients.


Top of page

Procedure: How to Turn the Trace Facility On or Off

  1. Before you can generate the trace, you must issue a FILEDEF for DDNAME FSTRACE. You can define it as a sequential file (RECFM F, LRECL 80) or to the terminal. For example, you can issue the following FILEDEF command prior to starting the sink machine if you want to write trace records to a file named FSTRACE DATA A:

    FILEDEF FSTRACE DISK FSTRACE DATA A
  1. Start the sink machine.

  2. Issue the following server command to write trace records to the trace file.

    TRACEON
  3. To stop writing trace records, issue the following server command:

    TRACEOFF

Top of page

Example: Sample Trace File

When the server is stopped, you can view or edit the trace file. The following shows sample trace commands captured in the trace file:

>>>                                                      
FSTRACE
<<<
10.40.05 AP ihsRecv: waiting for events (acpt)
10.40.05 AS r1fdrma: Entered
10.40.05 AS r1fdadd: adding fd 0xd670c8(0) to slot 0
10.40.05 AS r1fdadd: fdh=0Xc6f8d8 fdh->type=0
10.40.05 AS r1fdadd: r1fdadd returning 1
10.40.05 AS r1fdadd: adding fd 0xd71418(0) to slot 1
10.40.05 AS r1fdadd: fdh=0Xc6f8e8 fdh->type=0
10.40.05 AS r1fdadd: r1fdadd returning 2
10.40.05 AS r1fdadd: adding fd 0xcd3f10(0) to slot 2
10.40.05 AS r1fdadd: fdh=0Xc6f8f8 fdh->type=0
10.40.05 AS r1fdadd: r1fdadd returning 3
10.40.05 AS r1fdwait: entered with seconds = -1
10.40.05 AS r1fdwait: calling iucv_select on 3 selectors
10.40.05 AS r1fdwait: Wait for the request or connection
10.40.14 AS r1fdwait: POST on socket index: 3
10.40.14 AS r1fdwait: select returned 1 active fds
10.40.14 AS xxsrv_se: Session Index = 2
10.40.14 AS iRecv: recv: called
10.40.14 AS iRecv: Received recv=312
10.40.14 AS ngsRecvB: received 312 bytes
10.40.14 AS ngsRecvS: set buf to internal buffer, len=4 , 308 left
10.40.14 AS ngsRecvS: set buf to internal buffer, len=308 , 0 left
10.40.14 AS NGodinGe: NG_OPFEOT received
10.40.14 AS NGodinGe: len=308, OPFMESSAGE - "
10.40.14 AP ihsRecv: event 0x01 received by 0xCD3F68
10.40.14 AP ihsRecv: successfully read 308 bytes
10.40.14 HO hlisnk: received msg ' '
10.40.14 HO hlisnk: unpacked 2 args
10.40.14 HO hlidead: entered (keys='USER1 '.0x5dfe9520 0x0164c64c)
10.40.14 HO hlidead: exiting
10.40.14 HO hlisnk: command='CLO '
10.40.14 HO hlia2_find: entered (keys='USER1 '.0x5dfe9520 0x0164c64c)
10.40.14 HO hlia2_find: using dad slot 0
10.40.14 HO hlia2_find: found mom slot 3, fcb=0x1DA5990
10.40.14 HO hlia2_find: exiting
10.40.14 HO hlictl: entered
10.40.14 HO hlictl: numargs=2, command='CLO ', fcb=0x01da5990
10.40.14 HO hlictl: fcb.filename='FOCUSSU FOCUS   * ', fcb.procname='SUWE
DGE1'
10.40.14 HO hlictl: 5 known fcbs (looking for 0x1DA5990)
10.40.14 HO hlictl: fcb00001: 0x1DA5708
10.40.14 HO hlictl: fcb00002: 0x1DA57E0
10.40.14 HO hlictl: fcb00003: 0x1DA58B8
10.40.14 HO hlictl: fcb00004: 0x1DA5990
10.40.14 HO hlictl: fcb00005: 0x1DA5A68
10.40.14 HO hlictl: fcb found at index 4
10.40.14 HO hlictl: processing CLOSE command
10.40.14 HO hlictl: CLOSE done
10.40.14 HO hlictl: exiting
10.40.14 AS NGodinPu: entered
10.40.14 AS NGtrEvnt: len=304, FLUSH & OPFMESSAGE - "
10.40.14 AS NGodinPu: compression is not set
10.40.14 AS NGodinPu: encryption is not set
10.40.14 AS ngsSendS: copied 308 to internal buffer
10.40.14 AS iSend: len=308 addr= & HELS
10.40.14 AS iSend: leaving send: rc=0 rlen 308
10.40.14 AS ngsSendB: sent 308 bytes
10.40.14 AP ihsSend: successfully sent 304 bytes
10.40.14 AP ihsSend: implicit unlock
10.40.14 AP ihsRecv: waiting for events (acpt)
10.40.14 AS r1fdrma: Entered
10.40.14 AS r1fdadd: adding fd 0xd670c8(0) to slot 0
10.40.14 AS r1fdadd: fdh=0Xc6f8d8 fdh->type=0
10.40.14 AS r1fdadd: r1fdadd returning 1
10.40.14 AS r1fdadd: adding fd 0xd71418(0) to slot 1
10.40.14 AS r1fdadd: fdh=0Xc6f8e8 fdh->type=0
10.40.14 AS r1fdadd: r1fdadd returning 2
10.40.14 AS r1fdadd: adding fd 0xcd3f10(1073741833) to slot 2
10.40.14 AS r1fdadd: fdh=0Xc6f8f8 fdh->type=0
10.40.14 AS r1fdadd: r1fdadd returning 3
10.40.14 AS r1fdwait: entered with seconds = -1

Top of page

Using APPL-level Traces

How to:

Turn APPL-level Traces On or Off

Example:

Sample APPL-level Trace Messages

APPL-level traces display messages on the screen that trace server processing.


Top of page

Syntax: How to Turn APPL-level Traces On or Off

To turn on APPL-level traces, issue the following server command:

APPLON

To turn OFF APPL-level traces, issue the following server command:

APPLOFF

Top of page

Example: Sample APPL-level Trace Messages

11:49:23  * MSG FROM SINK001 : AEXIT1: 00D58820 HANDLE IUCV INTERRUPT, ITYPE=0
0000001
11:49:23 * MSG FROM SINK001 : AEXIT1: IPARML 00000001 000A0000 D7D4E2E2 C1C54
040 C9E4C3E5
11:49:23 * MSG FROM SINK001 : C9C2C9C3 D7D4E2E2 C1C54040 00000
000 80000000
11:49:23 * MSG FROM SINK001 : R1INIUAG: WAITING SEND
11:49:23 * MSG FROM SINK001 : AEXIT: 00CD3F10 SOCKET IUCV INTERRUPT, ITYPE=00
000009
11:49:23 * MSG FROM SINK001 : AEXIT: IPARML 00000709 03725215 00000000 000000
00 000000C1
11:49:23 * MSG FROM SINK001 : 00000000 00000000 00000000 00008
000 80000000
11:49:23 * MSG FROM SINK001 : R1INIUAG: GOT SEND ITYPE=00000009
11:49:23 * MSG FROM SINK001 : R1INIUAG: LENGTH OF RECV BUF 000000C1
11:49:23 * MSG FROM SINK001 : IUTCPAL SENT BUFFER=00245013 FACECAFE 20020000
00000000 LN=00000024
11:49:23 * MSG FROM SINK001 : AEXIT: 00CD3F10 SOCKET IUCV INTERRUPT, ITYPE=00
000009
11:49:23 * MSG FROM SINK001 : AEXIT: IPARML 00000709 03725216 00000000 000000
00 00000138
11:49:23 * MSG FROM SINK001 : 00000000 00000000 00000000 00008
000 80000000
11:49:23 * MSG FROM SINK001 : R1INIUAG: WAITING SEND
11:49:23 * MSG FROM SINK001 : R1INIUAG: GOT SEND ITYPE=00000009
11:49:23 * MSG FROM SINK001 : R1INIUAG: LENGTH OF RECV BUF 00000138
11:49:23 * MSG FROM SINK001 : IUTCPAL SENT BUFFER=01345013 C8C5D3E2 00000004
00000000 LN=00000134
11:49:23 * MSG FROM SINK001 : AEXIT: 00CD3F10 SOCKET IUCV INTERRUPT, ITYPE=00
000009
11:49:23 * MSG FROM SINK001 : AEXIT: IPARML 00000709 0372521B 00000000 000000
00 0000013C
11:49:23 * MSG FROM SINK001 : 00000000 00000000 00000000 0000

Information Builders