z/TPF - Group home

Trace log enhancements (PJ46309)

  

APAR PJ46309 includes various enhancements to trace log support.  These enhancements collect additional data and improve the consistency of the data that is collected.  In addition, changes to trace log controls are included.  The use of trace logging with PJ46309 installed can help you improve your understanding of the flow and resource usage within an application.

 

Infrastructure

 

To support enhancements that are provided in PJ46309, additional information needs to be specified when a trace log session is started.  To provide this added information, the TLOGC assembler macro was updated to support the ability to pass data in a parameter block.  The PARMS parameter was added to the TLOGC macro in order to provide a pointer to the parameter block.  Previously existing TLOGC options as well as new options are supported in the parameter block.

 

A new C function, tpf_tracelog_ext(), is provided as the C equivalent to the TLOGC PARMS parameter in assembler.

 

A new request type called program-directed post processing is provided.  This request type specifies where to put the trace log output and how the output is formatted.  The output for program-directed post processing is given to a program that is specified in the PARMS block when the trace log session is started.  The output is a JSON document.  However, the output is given in pieces.  Typically, a piece is about 1 MB in size.  It is the responsibility of the program to decide what to do with the JSON document.  One option is to transmit the data to another system.  After the program processed one piece, the program must return to trace logging to get subsequent 1 MB pieces of the JSON document.

 

Enhancements to collected data – consistent set of traces

 

Before PJ46309, when trace logging is run for an ECB, only currently active traces are collected.  For example, if ECB macro trace is active in the system and C function trace is not active, trace logging only collects ECB macro trace.

 

With PJ46309, when trace logging is run for an ECB, a predefined set of traces are collected regardless of whether the traces are active in the system.  Using a predefined set of traces ensures that a consistent set of data is collected for every trace log session.  The set of traces that are collected include the following trace types:

  • ECB macro trace
  • C function trace
  • Extended C function trace
  • Enter/back trace
  • z/TPFDF enter/back trace

 

Skip C function trace is not active for an ECB with trace logging active.

 

ECBs that do not have active trace logging activities use the traces that are currently active in the system.

 

Enhancements to collected data – support for child ECBs

 

Before PJ46309, when trace logging is started for an ECB, only the trace entries for that ECB are collected.

 

With PJ46309, an option is provided to automatically start trace logging for child ECBs.  If the child ECB option is selected when trace logging is started, any request to create a child ECB while trace logging is active will  cause trace logging to be started for that child ECB.  In addition, if the child ECB requests to create an ECB (grandchild ECB) while trace logging is active, trace logging will be started when the grandchild ECB is created.  The same behavior happens if  any grandchild ECB requests to create an ECB while trace logging is on.  Therefore, you must use this option carefully.

 

When the option to automatically start trace logging for child ECBs is specified, the following APIs will automatically start trace logging when a child ECB is created:

  • CREMC or cremc()
  • CREDC or credc()
  • CREXC or crexc()
  • CREEC or creec()
  • SWISC TYPE=CREATE or swisc_create()
  • fork()
  • tpf_fork()
  • pthread_create()

 

If a child ECB is created before the trace log session is started, trace logging is not automatically started for the child ECB.  Also, if the trace log session is stopped for an ECB and a request to create a child ECB is made, trace logging is not automatically started for the child ECB.

 

Enhancements to collected data – collect resource counts

 

With PJ46309, resource counts are collected at the following points during a trace log session: 

  • When the trace log session is started
  • When an ECB owner name is changed
  • When the trace log session ends

 

Information for 65 different metrics is collected.  The information that is collected for trace logging is the same information data that is collected for runtime metrics collection database metrics.

 

When a .report file is created for the trace log output, the resource counts are presented at the end of the report.  In this case, the following information is presented:

  • Resource counts that are used over the trace log session
  • Resource counts at the start of the trace log session
  • Resource counts at the end of the trace log session

 

When program-directed post processing is used, the JSON document includes all the collected resource counts.

 

Controls

 

Before PJ46309, trace logging has two controls.  One control is the number of trace log sessions.  Trace logging does not allow more than the user specified number of trace log sessions to be active at one point in time.  The ZASER TRLOG command is used to set this control.

 

The second control is the maximum amount of data that is allowed on the trace log queue.  Internally, trace log collects raw trace data in a system heap buffer and the buffer is put on a queue.  If the number of bytes on the queue is more than the maximum amount of data allowed, the trace log session is stopped.  The ZASER TRLOGTH command is used to set this control.

 

The purpose of these controls is to limit the amount of 64-bit system heap that is used for trace logging.  When trace logging collects raw trace data, it copies the trace information into 64-bit system heap buffers.  These buffers are put on a queue.  Eventually the CTLG program takes the data from the queue and processes it.  The controls limit the amount of system heap that is put on the queue.

 

With PJ46309, the method for controlling the amount of system heap on the queue changes.  Both the ZASER TRLOG and ZASER TRLOGTH commands are removed.  PJ46309 changes the control to use a LODIC CHECK that checks for 1 MB frames (FRM1MB) by using the LODIC class IBMBATCH.

 

Before PJ46309, 64-bit system heap is allocated in 4 KB units.  There is no method to determine the amount of available system heap.  Hopefully, the 64-bit system heap is allocated from pre-allocated 64-bit system heap.  However, if the 64-bit system heap is allocated from the virtual area, a FRM1MB is needed to back the system heap.  Because the buffers are in 4 KB units, the FRM1MB is associated with 64-bit system heap until the next IPL.

 

With PJ46309, 64-bit system heap is allocated in 1 MB units.  Also, the system heap logic is changed so that trace log requests that are in 1 MB units are always allocated from the virtual area, which means that a FRM1MB is allocated.  When the system heap that is in 1 MB units is returned, the FRM1MB is returned to the FRM1MB available pool.   With these changes, the use of LODIC to check for FRM1MB availability is an effective method to limit and control the use of resources by trace logging.

 

When trace logging is run on an IBM z15 processor, compression is used for the data that is put on queue and that is in the 1 MB system heap buffers.  Testing in the IBM TPF lab shows that 1 MB trace log data can be compressed to about  150 KB.  If the amount of data that is collected for trace logging is large, the use of compression can reduce the number of blocks on queue by roughly 6 fold.

 

Controls – Timeout option

 

When trace logging is started, the ECB trace data is collected until the ECB exits or trace logging is stopped.  Before PJ46309, if an ECB is long running, trace log will continue to collect data as long as the number of bytes on the queue is not too large.  In this case, there is no method to stop trace log collection.

 

With PJ46309, an optional timeout value in seconds is supported.    The clock starts as soon as the trace log session is started.  The timeout will happen the exact number of seconds after the trace log session starts.  When a timeout happens, the trace log session is stopped for the ECB.

 

If the child ECB option is used, all child ECBs inherit the exact same timeout.

 

For example, a trace log session is started at 10.38.17.220, which is 220 milliseconds after the start of second number 17.  The trace log request has a timeout of 2 seconds and it includes the optional child ECB option.  The trace log session will timeout at 10.38.19.220.  If the parent ECB or any child ECB have trace logging active at 10.38.19.220, the trace log sessions will be stopped.  Also, if any child ECB is created after the timeout is reached, trace logging will not be started for the child ECB.

 

The timeout option limits the amount of data that is collected for the ECB.  It also limits the number of child ECBs that trace logging is started for.

 

Controls – IUOWID management

 

When a trace log session is started, the IBM unit of work ID (IUOWID) is associated with the trace log session.  Trace logging will only collect data for the specific IUOWID.  If an ECB changes its IUOWID, the trace log session is stopped for that ECB.

 

When a child ECB is created, it inherits the IUOWID from the parent ECB.  Trace logging remains active as long as the IUOWID does not change in the child ECB.  If the IUOWID changes in the child ECB, trace logging is stopped in that child ECB.

 

Additional information

 

In the .report output file, additional information is included in the header.  Some of the information includes complex name, CPU-ID, subsystem name, and subsystem user name.  The environment such as VM, PR/SM-D (dedicated LPAR), or PR/SM-SH (shared LPAR) is included.  If trace logging is run on VM, the VM guest is included.  Otherwise, the name of the LPAR is included.  Other additional information is also included.

 

For more information about PJ46309, see the APEDIT.