z/TPF - Group home

Additional trace information (PJ46309)

By Michael Shershin posted Tue November 30, 2021 03:13 PM

  

APAR PJ46309 includes several enhancements that enrich the data in ECB trace.  This enriched data provides a foundation to improve the understanding of the flow and processing that is done by an application running on the z/TPF system.  All of the enriched data is available in z/TPF dumps as well as in trace log output.

 

Copy-on-write trace

 

A copy-on-write event happens when a z/TPF program updates a static variable.  The static variable is in the program rather than on the ECB stack.  Because z/TPF programs must be reentrant and because the static variable is in the program, a copy of the 4 KB page where the static variable resides is made when the variable is updated.  The copy of the 4 KB page is used by the ECB and the actual contents of the program are not changed.

 

Before PJ46309, it is easy to know that copy-on-write events are happening.  Data collection has copy-on-write rates.  The owner names that start with ICOW for extended system work blocks (XWBs) indicate that copy-on-write events are currently being used.  However, it is difficult to know exactly where the copy-on-write events are happening.

 

With PJ46309, copy-on-write trace is available.  When copy-on-write trace is active, copy-on-write events will be reported in ECB trace in dumps, in the trace log, and in ZDECB TR command displays.  The trace shows the address of the instruction that caused the copy-on-write to happen.  Also, the trace shows the address of the 4 KB page that was copied. 

 

The following example is taken from a trace log output.  The PG value is the address of the page that was copied.  The A value is the address of the instruction that caused the copy-on-write event.

IBM_DEFT    QZZ5YZ LOADSET-DRIVER01 OBJECT-qzz5
 64PU1  1       A0 QZZ5 C-O-W          PG-000000009EB19000   DAA8C230 1320E86A
                                 A-000000009EB16A58

The ZSTRC command is used to manage copy-on-write trace.  To display the current status, enter the ZSTRC DISPLAY command:

==> ZSTRC DISPLAY
CSMP0097I 17.03.12 CPU-B SS-BSS  SSU-HPN  IS-01
STRC0013I 17.03.12 SYSTEM TRACE OPTIONS
TYPE OF SYSTEM TRACE          KEYWORD  STATUS
 ECB TRACE                    TRACE      ON
 FUNCTION TRACE               FUNCTR     ON
 EXTENDED FUNCTION            FUNCEXT    ON  _
 SKIP FUNCTION                FUNCSKIP   OFF
 TPF ENTER/BACK TRACE         ENTER      ON
 TPFDF ENTER/BACK TRACE       DFENTER    ON
 IO TRACE                     IO         ON
 CCW TRACE                    CCW        OFF
 SYSTEM LOG                   SYSLOG     ON
 BRANCH TRACE                 BRANCH     ON  _
 ECB HEAP TRACE               EHEAP      ON
 HEAP CHECK                   HEAPCHECK  ON
 SOCKET TRACE                 SOCTRACE   OFF
 REGISTERS                    REGS       ON
 BLOCK CHECK                  BLKCHK     ON
 IBM DEBUGC TEST              DEBUGIT    OFF
 IBM DEBUGC LOG               DEBUGIL    OFF _
 USER DEBUGC TEST             DEBUGUT    OFF
 USER DEBUGC LOG              DEBUGUL    OFF
 BRANCH RELATIVE TARGET CHECK BRCHECK    OFF
 IDLE TIMER                   IDLETMR    OFF
 STACK VALIDATION             STACKVAL   ON
 MYMALLOC API PROCESSING      MYMALLOC   ON
 I-STREAM COLLAPSE TEST MODE  TESTCLPS   OFF _
 TEST AUTOMATION              TESTAUTO   ON
 COPY-ON-WRITE TRACE          COPYWRT    OFF
END OF DISPLAY+


To activate copy-on-write trace, ECB TRACE must be on and enter the ZSTRC ALTER COPYWRT command:

==> ZSTRC ALTER COPYWRT
CSMP0097I 17.03.19 CPU-B SS-BSS  SSU-HPN  IS-01
STRC0013I 17.03.19 SYSTEM TRACE OPTIONS
TYPE OF SYSTEM TRACE          KEYWORD  STATUS
 ECB TRACE                    TRACE      ON
 FUNCTION TRACE               FUNCTR     ON
 EXTENDED FUNCTION            FUNCEXT    ON  _
 SKIP FUNCTION                FUNCSKIP   OFF
 TPF ENTER/BACK TRACE         ENTER      ON
 TPFDF ENTER/BACK TRACE       DFENTER    ON
 IO TRACE                     IO         ON
 CCW TRACE                    CCW        OFF
 SYSTEM LOG                   SYSLOG     ON
 BRANCH TRACE                 BRANCH     ON  _
 ECB HEAP TRACE               EHEAP      ON
 HEAP CHECK                   HEAPCHECK  ON
 SOCKET TRACE                 SOCTRACE   OFF
 REGISTERS                    REGS       ON
 BLOCK CHECK                  BLKCHK     ON
 IBM DEBUGC TEST              DEBUGIT    OFF
 IBM DEBUGC LOG               DEBUGIL    OFF _
 USER DEBUGC TEST             DEBUGUT    OFF
 USER DEBUGC LOG              DEBUGUL    OFF
 BRANCH RELATIVE TARGET CHECK BRCHECK    OFF
 IDLE TIMER                   IDLETMR    OFF
 STACK VALIDATION             STACKVAL   ON
 MYMALLOC API PROCESSING      MYMALLOC   ON
 I-STREAM COLLAPSE TEST MODE  TESTCLPS   OFF _
 TEST AUTOMATION              TESTAUTO   ON
 COPY-ON-WRITE TRACE          COPYWRT    ON
END OF DISPLAY+


Copy-on-write trace uses trace entries in macro trace.

 

ECB time slice

 

Before PJ46309, if time slice is enabled for an ECB, it is difficult to determine whether an ECB has been time sliced and how frequently an ECB has been time sliced.

 

With PJ46309, when an ECB is time sliced, a trace entry is added to macro trace.  ECB time slice tracing is managed through ECB macro trace.  If ECB macro trace is enabled, ECB time slice trace entries are available in dumps, in the trace log, and in ZDECB TR command displays.

 

The following example is taken from a trace log output:

IBM_DEFT    QZZ5YZ LOADSET-DRIVER01 OBJECT-qzz5
 64PU1  1       B0 QZZ5 SUSPND  ECB SUSPENDED BY TIME SLICE  DAA8C230 135B00A4
 64PU1  1       AC QZZ5 SUSPND  ECB SUSPENDED BY TIME SLICE  DAA8C230 13D88898


Enrich variable macro parameters of various TPF macros

 

In ECB macro trace, most macros have variable information that provides details about the specific macro call.  With PJ46309, the additional information is available for the following macros:

  • CEBIC: The resultant subsystem (SS) name and subsystem user (SSU) name are included.
  • CINFC: the type of request such as R, W, or K and the name of the CINFC label are included.
  • CORHC: An indicator is included that reports whether the resource was held by another ECB when the CORHC macro was called. In addition, the amount of time in microseconds that the ECB waited before holding the resource is provided.
  • ENQC: An indicator is included that reports whether the resource was held by another ECB when the ENQC was called. In addition, the amount of time in microseconds that the ECB waited before holding the resource is provided.
  • EOWNRC: The owner name that was set is included.
  • File type macros: An indicator is included that reports whether the record was only put into VFA (e.g. delay file) or whether the record was written to DASD.
  • Find type macros: An indicator is included that reports whether the record was retrieved from VFA or DASD.
  • SANQC: An indicator is included that reports whether the resource was held by another ECB when the SANQC macro was called. In addition, the amount of time in microseconds that the ECB waited before holding the resource is provided.

 

The example, which is taken from a trace log output, shows a few of the macros.

IBM_DEFT    QZZ0YZ LOADSET-DRIVER01 OBJECT-qzz0
 31PU1  1      24E QZZ0 EOWNRC                               DAA8D08B 5EEE768A
 31PU1  1      250 QZZ0  OWNER  CHANGE ITEST   QZZ5    CHILD DAA8D08B 5EEE7F76
                                ECB                         
 31PU1  1      25A QZZ0 CEBIC  SS-BSS  SSU-HPN               DAA8D08B 5EEEA028
 31PU1  1      268 QZZ0 EVNTC  CORHC N-000000000FC2EE78      DAA8D08B 5EEEA400
                                HELD-Y T-2011189            
 31PU1  1      274 QZZ0 POSTC  CORUC N-000000000FC2EE78      DAA8D08D 49F21F98
 31PU1  1      29C QZZ0 FIWHC  F-00000000D4030000 L-D2       DAA8D08D 49F25D22
                                ID-C1C1 VFA                 
 31PU1  1      2A4 QZZ0 FILUC  F-00000000D4030000 L-D2       DAA8D08D 49F32308
                                ID-C1C1 DASD

 

For more information about PJ46309, see the APEDIT.

0 comments
9 views