Using the Profiler Utility in Batch Mode

The Natural Profiler is used to monitor the internal process flow of a Natural batch application and to analyze the performance and the code coverage of the application.

The Profiler utility is controlled by JCL input and provides functions for data collection and data processing:

1. The data collection functions control Profiler tracing, select required event types, filter, consolidate (aggregate) or sample data and write the resulting events to the Profiler resource file.

2. The data processing functions read and process the event data from the Profiler resource file. Unconsolidated event data can be consolidated.

   You can output statistics, a program summary, a line summary and a transaction summary, a program trace, an event trace with the most important data, and reports on program and statement coverage. You can export the resulting data in text or CSV (comma-separated values) format.

The Profiler resource file can be read by NaturalONE which displays the full event trace and provides a performance analysis (hot spots) of the Natural batch application. Coverage data can be inspected in the NaturalONE Coverage view and in the NaturalONE source editor. The exported profiling event data can be analyzed with the Natural Profiler MashApp which visualizes the data on an interactive MashZone dashboard.

This section covers the following topics:

• Quick Start for Profiling

• Quick Start for Code Coverage

• Prerequisites

• Invoking and Terminating the Profiler Utility

• Syntax and Keywords

• Events and Data Collected

• Initializing Profiling

• Initializing Code Coverage

• Starting and Pausing Data Collection

• Using Filters to Limit the Data Collected

• Enabling Sampling

• Writing User-Defined Events

• Monitor Session CMPRMIN

• Monitor Session CMSYNIN

• Profiling a Batch Natural RPC Server

• Profiling a Mainframe Session from Natural Studio

• Consolidating Event Data

• Evaluating Event Data

• Exporting Event Data for MashZone

• Maintaining Profiler Resource Files

• Including Profiler Input from Natural Text Objects

• Event Trace

• Tracing Natural Code Coverage

• Internal Trace

• Profiler Statistics

Quick Start for Profiling

This section briefly describes the steps required for profiling Natural batch applications and viewing the results. The instructions provided here may serve as a guideline when starting to use the Natural Profiler. Detailed information regarding the steps is provided in the remainder of this chapter.

The steps to take depend on the evaluation you want to perform for your application as illustrated in the following graphic:

1. Check that the prerequisites are met.

2. Add the Profiler utility INIT, FILTER and START functions to the Natural batch job to start the event data collection. Example for z/OS:

   //CMSYNIN  DD  *
   PROFILER
   FUNCTION=INIT                /* Initialize profiling
     RESOURCE=ON                /* Write to resource
     RESOURCE-NAME='ResNam',REPLACE=YES  /* Resource name
     RESOURCE-LIB=RESLIB        /* Resource library
   FILTER=EVENT                 /* Set event filter
     EVENT=ALL                  /* All events
     STATEMENT=ON               /* Collect statements
   FUNCTION=START               /* Start data collection
   END-PROFILER                 /* End Profiler input 
   LOGON PRFDEMO
   XPROF
   10000
   FIN

   In the example above, the Profiler event data is written to a resource file with the name ResNam.nprf in the library RESLIB. See also Initializing Profiling and Starting and Pausing Data Collection.

3. Open the NPRF resource in NaturalONE to view the hot spots and the event trace.

4. Submit a Natural batch job with the Profiler utility READ function to print an event trace, a program trace and the Profiler statistics. Example:

   FUNCTION=READ           /* Read Profiler data
     RESOURCE-LIB=RESLIB   /* Resource library
     RESOURCE-TYPE=NPRF    /* Use resource type NPRF
     EVENT=ON              /* Print event trace
     PROGRAM=ON            /* Print program trace
     STATISTICS=ON         /* Print statistics

   See also Profiler Utility READ Function. This section also describes how to generate a transaction summary.

5. Submit a Natural batch job with the Profiler utility CONSOLIDATE function to consolidate (aggregate) the event data. Example:

   FUNCTION=CONSOLIDATE    /* Consolidate Profiler data
     RESOURCE-LIB=RESLIB   /* Resource library
     REPLACE=YES           /* Replace resource

   The consolidated Profiler event data is written to the resource ResNam.nprc in the library RESLIB. See Consolidating Event Data.

6. Open the NPRC resource in NaturalONE to view the hot spots.

7. Submit a Natural batch job with the Profiler utility READ function to generate a program summary, a line summary and the Profiler statistics. Example:

   FUNCTION=READ           /* Read Profiler Data
     RESOURCE-LIB=RESLIB   /* Resource library
     RESOURCE-TYPE=NPRC    /* Use resource type NPRC
     PROGRAM=ON            /* Print program summary
     LINE=ON               /* Print line summary
     STATISTICS=ON         /* Print statistics

   See also Profiler Utility READ Function. This section also describes how to generate a transaction summary.

8. Submit a Natural batch job with the Profiler utility MASHZONE function to write the data to Work File 7 in the format expected by the Natural Profiler MashApp. Example:

   FUNCTION=MASHZONE       /* Write MashZone format to Work File 7
     RESOURCE-LIB=RESLIB   /* Resource library

   See also Exporting Event Data for MashZone.

9. Export the data of Work File 7 with any tool (such as FTP) as a CSV (comma-separated values) file to the Natural Profiler data directory in the MashZone environment.

10. Enter a reference to the new file in the Overview.csv file in the resources\Profiler directory.

    Open the Natural Profiler MashApp and select the corresponding input file to evaluate the event data.

Notes:

1. If the resource name is not explicitly specified in the READ, CONSOLIDATE or MASHZONE function of the Profiler utility, the last created NPRF or NPRC resource in the library is used.
2. If you plan to profile a long-running batch application, refer to the section Profiling Long-Running Applications. It covers strategies of how to minimize the number of events to be monitored.
3. The NaturalONE Profiler is described in the NaturalONE documentation.

Quick Start for Code Coverage

This section briefly describes the steps required for performing the code coverage of a Natural batch applications and viewing the results. The instructions provided here may serve as a guideline when starting to use Natural code coverage. Detailed information regarding the steps is provided in the remainder of this chapter.

The steps to take depend on the evaluation you want to perform for your application as illustrated in the following graphic:

1. Check that the prerequisites are met.

2. Add the Profiler utility COVERAGE and START functions to the Natural batch job to start the code coverage data collection.

   Example for z/OS:

   //CMSYNIN  DD  *
   PROFILER
   FUNCTION=COVERAGE            /* Initialize coverage
     RESOURCE=ON                /* Write to resource
     RESOURCE-NAME='ResNam'     /* Resource name
     REPLACE=YES                /* Replace the resource
     RESOURCE-LIB=RESLIB        /* Resource library
   FUNCTION=START               /* Start data collection
   END-PROFILER                 /* End Profiler input 
   LOGON COVDEMO
   TESTCOVP
   FIN

   In the example above, the Profiler coverage data is written to a resource file with the name ResNam.ncvf in the library RESLIB. See also Initializing Code Coverage and Starting and Pausing Data Collection.

3. Open the NCVF resource in NaturalONE to obtain the Code Coverage view.

4. From the NaturalONE Code Coverage view, you can directly edit the source. The editor shows all lines containing covered statements with a green background.

5. Submit a Natural batch job with the Profiler utility READ function to print the program and statement coverage and the Profiler statistics.

   Example:

   FUNCTION=READ           /* Read Profiler data
     RESOURCE-LIB=RESLIB   /* Resource library  
     RESOURCE-TYPE=NCVF    /* Use resource type 
     EVENT=ON              /* Print statement co
     PROGRAM=ON            /* Print program cove
     STATISTICS=ON         /* Print statistics    
     EXPORT=ON             /* write to work 7     
     FORMAT=C              /* Semicolon/Comma/Text

   If the EXPORT keyword of the Profiler utility READ function is switched on, the output is written to Work File 7. If FORMAT is specified as C or S, the result is written as comma-separated values (CSV) where a comma or a semicolon is used as a separator, respectively.

6. Export the data of Work File 7 with any tool (such as FTP) as a CSV-formatted file to a Windows environment if you want to process it further in Microsoft Excel.

Notes:

1. If the resource name is not explicitly specified in the READ function of the Profiler utility, the NCVF resource created last in the library is used.
2. The NaturalONE Code Coverage view and editor are described in the NaturalONE documentation.

Prerequisites

The following prerequisites must be met before you can use the Profiler utility in batch mode:

• Natural Parameter Settings

• Natural Nucleus Linkage

• Display Resource Files in Natural Development Server Environments

• Activate Data Processing

Natural Parameter Settings

For the Natural Profiler data collection functions (INIT, COVERAGE, START, PAUSE and TEXT), you must set the following Natural profile parameters.

• RDCSIZE - Activate the Natural Data Collector (without recording data in the buffer of the Natural Data Collector):

  RDCSIZE=2

• RDCEXIT - Define NATRDC1 as a user exit for the Natural Data Collector:

  RDCEXIT=NATRDC1

• PDPSIZE - Optional parameter you can set additionally to determine the size of the Profiler data pool, for example:

  PDPSIZE=1000

The Profiler utility data processing functions (CONSOLIDATE, READ, MASHZONE, LIST and DELETE) cannot be executed if profiling is active. For performance reasons, we recommend that you also deactivate the Natural Data Collector for these functions with the following (default) parameter setting:

RDCSIZE=0

For details regarding the Natural profile parameters mentioned above, see the relevant sections in the Parameter Reference documentation.

Programs which are compiled with the Natural Optimizer require the following Natural Optimizer option setting:

NODBG=OFF

(See also List of Options in the Natural Optimizer Compiler documentation.)

Natural Nucleus Linkage

The Natural nucleus must be reentrant and reusable. Use the following linkage options:

RENT,REUS

Display Resource Files in Natural Development Server Environments

By default, Natural mainframe resource files are not displayed in Natural Development Server (NDV) environments such as NaturalONE or Natural Studio. For analyzing the Profiler event data, the resource file must be accessed from NaturalONE. Therefore, you have to modify the NDV behavior.

To display resource files in an NDV environment

1. Copy the source code of the NDV user exit NDV-SX03 from the Natural system library SYSLIB into a user library.

2. Edit the member. Adjust the code as described below:

   DISPLAY-RESOURCES := 'Y'   /* Display resources in NaturalONE/Studio

3. Catalog it under the name NDV-UX03.

4. Copy it back into the system library SYSLIB or into the library SYSLIBS or SYSTEM.

Activate Data Processing

If NaturalONE is installed at your site, you can activate the Profiler utility data processing functions (CONSOLIDATE, READ, MASHZONE, LIST and DELETE) with the following steps:

1. Start NaturalONE.

2. In the Natural Server view, map to the environment where the Profiler resources reside.

3. Add the program ACTIVATE contained in the system library SYSPRFLR to a new or existing project in NaturalONE.

4. Profile the program ACTIVATE with the context menu function Profile As > Natural Application.

5. Verify that the user-defined event data on the Event Trace page of the NaturalONE Profiler contains the activation success message.

When the program ACTIVATE is profiled, a NaturalONE Profiler key is generated and written to the Natural resource NaturalONEProfilerKey.nprk in the system library SYSPRFLR. Each Profiler data processing function reads this resource and checks the key. If the key is valid, the function is performed. A newly generated key is valid for one year. It can always be regenerated.

The Profiler data processing function starts issuing a warning 9 days before the key expires, and returns an error message if no key is found or if the key is not valid.

Invoking and Terminating the Profiler Utility

This section provides instructions for invoking and terminating the Profiler utility in batch mode.

To invoke the Profiler utility

• Enter the following system command into the primary command input data set CMSYNIN:

  PROFILER

  Note:
  After the PROFILER system command, the Profiler expects one or more lines with Profiler keyword entries.

To terminate the Profiler utility

• Enter the following Profiler keyword into the primary command input data set CMSYNIN:

  END-PROFILER

  Or:

  END

  Or:

  .

Syntax and Keywords

The Profiler utility in batch mode reads the Profiler keywords that control the profiling from the primary command input data set CMSYNIN. The Profiler reads the input lines until it reaches the END-PROFILER keyword (or END or .).

This section covers the following topics:

• Profiler Utility Syntax

• Profiler Utility Keywords

Profiler Utility Syntax

The symbols used in the syntax diagrams shown in this section are explained in System Command Syntax in the System Commands documentation.

You enter a Profiler utility command using either of the following syntax formats:

Or:

Notes:

1. If a value is associated with a keyword but no equal sign is found, the Profiler expects the value in a separate input line without any other keyword (second syntax format).
2. The first syntax format expects input in delimiter mode (IM=D).
3. The second syntax format can be used if the Profiler is to be executed with the Natural STACK profile parameter or if the data is entered in forms mode (IM=F).

The following rules apply:

• Empty lines and lines starting with an asterisk (*) are ignored.

• All characters in a line from /* to */ or to the end of the line are ignored.

• Some keywords have no associated value.

• Blanks can be added before or after the keyword or value.

• Multiple keywords in a line are separated by commas (applies to the first syntax format only).

• A value can be enclosed in apostrophes ('value').

• A value must not contain a comma.

• Keywords and values can be specified in upper or lower case.

• The maximum input line length is 78 characters.

The Profiler utility can be executed multiple times in one Natural session. For example, it is first executed with the INIT and START functions, and then, after the execution of a user program, it is executed with the PAUSE function.

Example

The following Natural batch example (on z/OS) shows the original JCL which runs the XPROF program on the PRFDEMO library (lines in normal font) and the Profiler utility input lines which are used to profile the XPROF program (lines in bold).

//CMSYNIN  DD  *
PROFILER
FUNCTION=INIT                /* Initialize profiling
  RESOURCE=ON                /* Write to resource
  RESOURCE-NAME='Demo01',REPLACE=YES  /* Resource name
  RESOURCE-LIB=PRFDATA       /* Resource library
FUNCTION=START               /* Start data collection
END-PROFILER                 /* End Profiler input 
LOGON PRFDEMO
XPROF
10000
FIN

The following Natural batch example (on z/OS) demonstrates how the Profiler is to be executed with the Natural STACK profile parameter.

STACK=(
 PROFILER FUNCTION:INIT:
   RESOURCE:ON:
   RESOURCE-LIB:PRFDATA:
   REPLACE:YES:
 FUNCTION:START:
 END-PROFILER;
 LOGON PRFDEMO
 )

Profiler Utility Keywords

The main keywords used in the syntax of the Profiler utility in batch mode are described in the following table. Any additional (subordinate) keywords available for a main keyword are described in the sections referenced in the table. In general, a subordinate keyword value must follow the main keyword value, for example:

FUNCTION=READ
  PRINT=ON

A subordinate keyword specified before the first FUNCTION or FILTER keyword is treated as a subordinate keyword of the first FUNCTION or FILTER keyword.

The following main keywords are available:

Events and Data Collected

This section describes the events and data processed by the Profiler utility in batch mode.

• Events

• Data Collected

Events

During a Natural session, different types of events can occur (for example, a program start) where the Profiler collects data specific to the event in a trace record. Each event is associated with an event type, that is, a one or two letter code. Related event types are combined into an event group which is denoted by a one letter code.

The following events, event types and event groups are available:

With each collected event, a CPU and an event timestamp are recorded. In general, a timestamp is taken at the beginning of an event. The duration of an event therefore equals the time that elapses between the timestamp of the event and the timestamp of the event that follows.

Data Collected

This section describes the data collected by the Profiler utility:

General Data

The following data elements are collected at every event:

• Event counter

• Event type

• Event time in units of microseconds

• Session CPU time in units of microseconds

• Trace session ID

• Natural Security user group ID

• Natural user ID

• Natural application name

• Program library

• Program name

• Program level

• Copycode library

• Copycode name

• Statement line number

• Statement op-code

• Coverage flag (for Natural code coverage)

Notes:

1. The time spent for data collection (Monitor CPU time) is measured separately and extracted from the session CPU time.
2. The events are counted before any filtering or sampling is performed. Therefore, the events receive in general the same counting results regardless of which filtering or sampling is used.
3. Statement events are only counted if the event filter keyword STATEMENT=COUNT is used.
4. Monitor Pause events are not counted.
5. Natural code coverage only collects NS and PI events.
6. Natural code coverage does not collect time values.
7. A PI event is collected for each object accessed and for all copycodes included in the object (recursively).

Event-Specific Data

The following data is only collected at the following events:

Event	Data Elements
Session Initialization	None
Session Termination	Termination return code Natural termination message code NAT99nn Name of back-end program Monitor CPU time in units of microseconds
Program Load	Name of program to be loaded Name of load library Invocation type
Program Resume	None
Program Start/Termination	Program type Database ID of program library File number of program library
Program Information	Program type Number of statements in the program or copycode First statement item INCLUDE line number Parent copycode ID
Database Call	Database type Command code Command ID Database ID File number Response code (event type DA) Error subcode (event type DA) Adabas command time (event type DA)
Terminal I/O	Number of bytes sent Number of bytes read Total session storage allocated Compressed session storage length
External Program Call	Name of program called Calling mode such as dynamic or static mode Program link location Parameter type such as reference or value Response code (event type CA)
Runtime Error	Natural system error message code External abend code Name of error handling program
Natural Statement	Profiling: None Natural code coverage: Statement item identifier (GP offset)
Start of RPC Request Execution	Environment (C = client, S = server) Subprogram name Adabas user ID (ETID) Conversation status Logon indicator (Y = logon performed) Impersonation indicator of RPC request (Y = impersonation performed)
Outbound/Inbound RPC Message / RPC Wait for Client	Environment (C = client, S = server) Transport protocol RPC function Type of client user ID Length of message RPC return code External conversation ID Client user ID Server node (event types RO and RW) Server name (event types RO and RW)
User-Defined Event	Subtype of the user-defined event Up to 249 bytes of user-defined information
Monitor Pause	Type of monitor pause Possible values:
	R	Monitor pause requested. This value is also set when the session is initialized with the Pause option.
	F	Start of a block of filtered-out events. Block filters are: library, program, line, FNAT, event count, or time filter.
	W	Trace session waits because of a data pool full situation.

Initializing Profiling

The Profiler utility INIT function initializes profiling. The INIT function must be performed before any of the Profiler utility functions START, PAUSE or TEXT or any Profiler filter.

Syntax of INIT:

Syntax Description:

Example of INIT

FUNCTION=INIT           /* Initialize Profiling
  RESOURCE=ON           /* Write to resource file
  RESOURCE-NAME='Test'  /* Resource name
  RESOURCE-LIB=PRFDATA  /* Resource library
  REPLACE=YES           /* Replace resource
  SAMPLING=ON           /* Use sampling
  INTERVAL=100          /* Sampling interval
  CONSOLIDATE=OFF       /* Do not consolidate the data
  TRANSACTION=OFF       /* Do not add transaction identifiers 
  WAIT-FULL=60          /* Wait sec if pool full
  WAIT-EMPTY=60         /* Wait sec if pool empty
  CMPRMIN=PRFPARMS      /* CMPRMIN for monitor session
  TRACE-EVENT=ON        /* Trace events
  TRACE-MON=3           /* Trace level monitor session

Initializing Code Coverage

The Profiler utility COVERAGE function initializes the Natural code coverage. The COVERAGE function must be performed before any of the Profiler utility functions START, PAUSE or TEXT or any Profiler filter.

Syntax of COVERAGE:

Syntax Description:

Example of COVERAGE

FUNCTION=COVERAGE       /* Initialize code coverage
  RESOURCE=ON           /* Write to resource file
  RESOURCE-NAME='Test'  /* Resource name
  RESOURCE-LIB=COVDATA  /* Resource library
  REPLACE=YES           /* Replace resource
  WAIT-FULL=60          /* Wait sec if pool full
  WAIT-EMPTY=60         /* Wait sec if pool empty
  CMPRMIN=PRFPARMS      /* CMPRMIN for monitor session
  TRACE-EVENT=ON        /* Trace events
  TRACE-MON=3           /* Trace level of monitor session
  TRACE-COVERAGE=ON     /* Trace coverage data

Starting and Pausing Data Collection

The Profiler must be initialized before the data collection can be started or paused. Because the data collection is paused after the initialization, it has to be started in any way so that event data is recorded.

You can start and pause data collection with the following methods:

• Using Profiler Utility Functions

• Using Profiler Utility Programs

• Using the Application Programming Interface

Using Profiler Utility Functions

The Profiler utility START and PAUSE functions are used to start and pause data collection. The following syntax applies:

Syntax Description:

Using Profiler Utility Programs

The following Natural programs in the system library SYSPRFLR are supplied to perform Profiler utility functions:

To use Profiler utility programs

• Logon to the library SYSPRFLR or copy the programs to the library SYSTEM, to the appropriate steplib library, or to the required library.

  If PRFFCT is used, the application programming interface USR8210N has to be copied as well (see the following section).

  If PRFFCT is used in a client/server environment, copy PRFFCT to the client library and USR8210N to the server library.

  Note:
  PRFFCT expects as input the value START, PAUSE or STATE to perform the corresponding function.

To start the data collection

• Execute the following program:

  PRFSTART

  Or:

  PRFFCT
  START

To pause the data collection

• Execute the following program:

  PRFPAUSE

  Or:

  PRFFCT
  PAUSE

To retrieve the current state of the data collection

• Execute the following program:

  PRFSTATE

  Or:

  PRFFCT
  STATE

Using the Application Programming Interface

The data collection can be started and paused from the profiled Natural application by calling the application programming interface (API) USR8210N. The API can also be used to get the current state of the monitoring process. The API is delivered in the SYSEXT library. For more information, see SYSEXT Utility - Natural Application Programming Interfaces.

To use the API

• Copy the subprogram USR8210N to the library SYSTEM, to the appropriate steplib library, or to the required library.

  Note:
  USR8210N expects as the first parameter the value START, PAUSE or STATE to perform the corresponding function. The parameter values can be specified in uppercase or lowercase. On return, P-RETURN contains the return code and P-MESSAGE the success or error message.

To start the data collection

• Use the interface with the CALLNAT statement:

  CALLNAT 'USR8210N' 'START' P-RETURN P-MESSAGE /* Start Profiler

To pause the data collection

• Use the interface with the CALLNAT statement:

  CALLNAT 'USR8210N' 'PAUSE' P-RETURN P-MESSAGE /* Pause Profiler

To retrieve the current state of the data collection

• Use the interface with the CALLNAT statement:

  CALLNAT 'USR8210N' 'STATE' P-RETURN P-MESSAGE /* Get Profiler state

  The state is coded in the field P-RETURN:

  P-RETURN	Description
  0	Natural Profiler data collection is started.
  1	Natural Profiler data collection is paused.

Using Filters to Limit the Data Collected

Filters play an important role in reducing the amount of collected data. The following filters are available:

• Event Filter

• Program Filter

• Count Filter

• Time Filter

Event Filter

The Profiler event filter specifies which events are collected. Additionally, it determines whether event data is recorded while Natural system programs are executing.

Syntax of Event Filter:

Syntax Description:

EVENT=DB DA PL PS PT PR IB IA E CB CA U RS RI RO

Default Filter Value for Profiling

By default (if the event filter is not specified), all events except Natural statement events are collected and event data of Natural system programs is not recorded:

FILTER=EVENT            /* Set event filter
  EVENT=ALL             /* All events
  STATEMENT=OFF         /* Do not collect statements
  FNAT=OFF              /* No FNAT

Default Filter Value for Code Coverage

By default (if the event filter is not specified), only program start and Natural statement events are collected. Event data of Natural system programs is not recorded:

FILTER=EVENT            /* Set event filter
  EVENT=PS              /* Program start only
  STATEMENT=ON          /* Collect statements
  FNAT=OFF              /* No FNAT

Code coverage will not work correctly if program start or Natural statement events are not collected. If other events are monitored, they will be displayed in the trace but ignored by code coverage.

Example of an Event Filter

FILTER=EVENT            /* Set event filter
  EVENT=D PS PR         /* Database and program start/resume events
  STATEMENT=ON          /* Collect statements (no count)
  FNAT=OFF              /* No FNAT

Program Filter

The Profiler program filter specifies the libraries, programs (Natural objects) and program lines for which event data is collected. By default (if the program filter is not specified), the data of all libraries, programs and lines is collected.

Syntax of Program Filter:

Syntax Description:

Example of a Program Filter

The following example monitors the lines 0500 to 2000 in all Natural objects starting with X on the library PRFDEMO.

FILTER=PROGRAM            /* Set program filter
  LIBRARY=PRFDEMO         /* Monitored library
  PROGRAM=X*              /* Monitored program
  LINE-FROM=500           /* Monitor from line 0500
  LINE-TO=2000            /* Monitor to line 2000

Count Filter

The Profiler count filter specifies the event counters for which data is collected. By default (if the count filter is not specified) the data of any event count is collected.

If the event filter STATEMENT=ON is set, the count filter can only refer to non-statement events because statement events do not get a unique count. The non-statement events have the same count as with STATEMENT=OFF and the same count filter can be used in both cases.

Syntax of Count Filter:

Syntax Description:

Example of a Count Filter

A profiling with STATEMENT=OFF has shown that a lot of CPU time was spent between the events with the counters 1200 to 1400. Now, we want to analyze this range in more detail including the statements. With STATEMENT=COUNT, the statements would be counted as well and the events would receive other counter values. But with STATEMENT=ON the statements are not counted and the counter values can be used to restrict the data collection.

FILTER=COUNT            /* Set count filter
  FROM=1200             /* Monitor from event count 1200
  TO=1400               /* Monitor to event count 1400

Time Filter

The Profiler time filter specifies the CPU times (in units of 1/100 sec) for which data is collected. By default (if the time filter is not specified), the data of any CPU time is collected.

Syntax of Time Filter:

Syntax Description:

Example of a Time Filter

The following example monitors all events which occur after one second for the duration of two seconds.

FILTER=TIME            /* Set time filter
  FROM=100             /* Monitor from CPU second 1.00
  TO=300               /* Monitor to CPU second 3.00

Enabling Sampling

The sampling method uses a statistical approach to collect data. Sampling significantly reduces the amount of data written to the resource file while approximately retaining the same CPU times as without sampling.

Sampling is available for profiling but not for code coverage.

For general information regarding sampling, see Sampling in the section Basic Concepts of the Profiler Utility.

To enable sampling

• Enter the following subordinate keywords associated to the Profiler utility INIT function:

  SAMPLING=ON
  INTERVAL=nnn

  where nnn is the sampling interval in microseconds.

  Note:
  By default (if SAMPLING is not specified), the data is not sampled. If SAMPLING=ON is specified but no INTERVAL, the default sampling interval is 100 microseconds.

Writing User-Defined Events

A user-defined event can be generated from a Natural program by using the Natural statement

CALL 'CMRDC' 'U' USER-DATA

The first character of the USER-DATA is treated as the subtype of the user-defined event. The remaining characters are the text of the user-defined event. For details, see User-defined Events in the SYSRDC Utility documentation.

Notes:

1. The Natural Profiler in batch mode offers a function to generate user-defined events from the JCL input stream. These user-defined events are always recorded regardless of the current filter settings. If profiling is paused, the Profiler utility activates the profiling before it writes the user-defined event and deactivates it afterwards. If sampling is active, it can happen that a user-defined event is sampled away.
2. The Profiler must be initialized before a user-defined event can be written.

The Profiler utility FUNCTION=TEXT function is used to write user-defined events. The following syntax applies:

Syntax Description:

Use the following event filter setting if you only want to monitor the user-defined events written with the TEXT function. In addition to the TEXT function entries, the session and pause events are also monitored. All other events, including user-defined events written by calls to CMRDC are filtered out.

* Monitor only TEXT function entries
FILTER=EVENT/* Set event filter
  EVENT=                /* No events
  STATEMENT=OFF         /* No statements
  FNAT=OFF              /* No FNAT

Example of a User-Defined Event

The following example writes a user-defined event with subtype J and the text Start profiling into the Profiler event trace.

FUNCTION=TEXT            /* Write a user-defined event
  TEXT='Start profiling' /* User-defined event text
  TYPE='J'               /* User-defined event subtype

Monitor Session CMPRMIN

By default, the Profiler monitor session uses the same dynamic Natural parameters as the trace session specified with the CMPRMIN input data set. Exception: the RDCSIZE profile parameter is set to zero (0) for the monitor session. With the CMPRMIN keyword of the Profiler utility INIT or COVERAGE function, a separate dynamic parameter input data set can be defined for the Profiler monitor session. If you use the separate dynamic parameter input data set, consider the following:

• Specify for the monitor session only those Natural parameters which are required. Do not specify parameters required for the application execution (such as RPC).

• Specify the RDCSIZE and RDCEXIT parameters only for the trace session. Specifying these parameters for the monitor session will lead to unnecessary calls to the exit and a poorer performance.

• Specify the PDPSIZE parameter only for the monitor session. Any specification in the trace session dynamic parameter input data set is ignored.

If the default Natural profile parameter ETID setting is used, it can happen that the following error is received by the Profiler monitor session:

NAT3048 Error during Open processing. DB/Subcode nn/8 - ETID=job-name.

In this case, use the following parameters for CMPRMIN:

ETID=' ',DBCLOSE=ON

Alternatively, you can use an ETID value different from the job name in the separate dynamic parameter input data set for the Profiler monitor session.

To define a dynamic parameter input data set for the Profiler monitor session

• Enter the following subordinate keyword associated to the Profiler utility INIT or COVERAGE function:

  CMPRMIN=data-set

  where data-set is the name of the dynamic parameter input data set for the Profiler monitor session.

Example for z/OS

//CMSYNIN  DD  *
PROFILER
FUNCTION=INIT             /* Initialize profiling
  CMPRMIN=PRFPARMS        /* Monitor session parameter
  ...
/*
//* Trace Session Parameters
//CMPRMIN  DD   *
RDCSIZE=2,RDCEXIT=NATRDC1,...
/*
//* Monitor Session Parameters
//PRFPARMS DD   *
ETID=PROFILER,PDPSIZE=10000,...
/*

Monitor Session CMSYNIN

In general, the Profiler monitor session does not need a primary command input data set. With the CMSYNIN keyword of the Profiler utility INIT or COVERAGE function, a separate primary command input data set can be defined for the Profiler monitor session. This is required if your application runs under control of Natural Security and you do not want an automatic logon, that is, the Natural profile parameter AUTO=OFF is set. Specify the desired logon settings in the primary command input data set for the Profiler monitor session followed by the Profiler command which starts the Profiler monitor session.

For profiling, specify the following:

library-name,user-id,password
PROFILER MONITOR

For code coverage, specify the following:

library-name,user-id,password
PROFILER COVMON

To define a primary command input data set for the Profiler monitor session

• Enter the following subordinate keyword associated to the Profiler utility INIT or COVERAGE function:

  CMSYNIN=data-set

  where data-set is the name of the primary command input parameter input data set for the Profiler monitor session.

Example for z/OS (with AUTO=OFF set)

//CMSYNIN  DD  *
library-name,user-id,password
PROFILER
FUNCTION=INIT             /* Initialize profiling
  CMSYNIN=PRFSYNIN        /* Monitor session input data
  ...
/*
//* Monitor Session Input Data
//PRFSYNIN DD   *
library-name,user-id,password
PROFILER MONITOR
/*

Profiling a Batch Natural RPC Server

Profiling or performing code coverage of a batch Natural RPC server requires that the PROFILER system command and the Profiler input data are entered with the Natural STACK profile parameter in the RPC server job. The Profiler input must be entered in the second syntax format (without equal signs and commas). See also Profiler Utility Syntax in Syntax and Keywords.

To start profiling of a batch Natural RPC server

• Enter the following keyword before the Profiler INIT or COVERAGE function is performed:

  RPC

The RPC keyword indicates the Profiler that a Natural RPC server is monitored. The Profiler overwrites the WAIT-EMPTY keyword of the initialization with a value of zero (0) so that profiling always continues when the Profiler data pool is empty and the trace session is still active.

We recommend that you use a separate dynamic parameter input data set (Monitor Session CMPRMIN) for the Profiler monitor session when profiling a batch Natural RPC server. Do not specify the RPC parameter in this data set. See Monitor Session CMPRMIN.

The event data of the batch Natural RPC server is written to a Profiler resource file. The name and library of the resource file can be specified with Profiler keywords (see Initializing Profiling). We recommend that you stop the Natural RPC server before the Profiler further processes the resource file.

If you profile a Natural RPC server, you can start and pause data collection with the programs supplied for the Profiler utility.

To start and pause Profiler data collection in a client/server environment

1. Copy the program PRFFCT from the system library SYSPRFLR to the client library, and the application programming interface USR8210N from the system library SYSEXT to the server library.

2. Execute the program PRFFCT in the client library.

   PRFFCT expects as input the value START or PAUSE to perform the corresponding function. If you enter the value STATE, the current state of the data collection is displayed.

   For more information, see Starting and Pausing Data Collection.

Example of Natural RPC Batch Profiling

The following example for z/OS shows the Profiler input data for a batch Natural RPC server specified with the Natural STACK profile parameter:

STACK=(                
PROFILER RPC:          
TRACE:3:               
FUNCTION:INIT:         
  TRACE-EVENT:OFF:     
  TRACE-MON:3:         
  CMPRMIN:CMPRMINX:    
  RESOURCE:ON:         
  RESOURCE-NAME:RPCTEST:
  RESOURCE-LIB:PRFDATA:
  REPLACE:YES:         
FILTER:EVENT:          
  EVENT:ALL:           
  STATEMENT:ON:        
  FNAT:OFF:            
END-PROFILER;          
LOGON PRFDEMO          
)

Profiling a Mainframe Session from Natural Studio

You can use the Profiler utility in batch mode to profile a mainframe application or run code coverage for a mainframe application that executes remotely from Natural Studio on a Natural Development Server.

This requires that you specify the PROFILER system command and the PROFILER input data with the Natural STACK profile parameter dynamically set when you map your remote mainframe environment. The Profiler input must be entered in the second syntax format (without equal signs and commas). See also Profiler Utility Syntax in Syntax and Keywords.

You can use the Profiler INCLUDE keyword to read the Profiler input from a Natural text object, and thus reduce the amount of data entered with the STACK parameter. For an example, see the XNDV text object delivered in the SYSPRFLR system library. This example initializes the profiling and immediately starts the monitoring.

The Profiler automatically overwrites the WAIT-EMPTY keyword of the initialization with a value of zero (0) so that profiling always continues when the Profiler data pool is empty and the trace session is still active.

The event data of the Natural Studio mainframe session is written to a Profiler resource file. The name and library of the resource file can be specified with Profiler keywords (see Initializing Profiling or Initializing Code Coverage). We recommend that you disconnect the mainframe session before you evaluate the resource file.

If you profile a Natural Studio mainframe session, you can start and pause data collection (see the relevant section) with the programs supplied for the Profiler utility.

To start and pause Profiler data collection in a Natural Studio mainframe session

1. Logon to the library SYSPRFLR.

2. Execute the PRFSTART program to start the collection.

3. Execute the PRFPAUSE program to pause the collection.

Rules and Restrictions

The following rules and restrictions apply when profiling a mainframe session from Natural Studio:

• Profiling with the Profiler utility in batch mode does not work if programs are executed remotely from NaturalONE. Use the NaturalONE Profiler if you want to profile mainframe programs executed in a NaturalONE environment.

• Profiling of a Natural Studio mainframe session with the Profiler utility in batch mode does not work if the Natural Development Server uses a CICS adapter.

• If profiling is started with the STACK parameter, use the TRACE=0 Profiler setting.

• The monitor trace (TRACE-MONITOR) of the Profiler session is written to the Natural Development Server output.

Example of STACK for Mainframe Session Profiling

The following is an example of a STACK parameter specification for Profiler input data set dynamically when mapping to a remote mainframe environment from Natural Studio:

STACK=(PROFILER RESOURCE-LIB:PRFDATA:INCLUDE:XNDV)

The resource is written to the PRFDATA library.

Consolidating Event Data

The Profiler utility CONSOLIDATE function consolidates event data.

For general information regarding data consolidation, see Data Consolidation in the section Basic Concepts of the Profiler Utility.

Syntax of CONSOLIDATE:

Syntax Description:

Example of a Consolidation

The following example consolidates the Profiler resource Test.nprf in the library PRFDATA and writes the consolidated data to the Profiler resource Test.nprc. I/O and Natural RPC client time are included in the consolidated data.

In addition, the consolidated data is written in CSV (semicolon-separated values) format to Work File 7.

The event and consolidation traces are switched off.

FUNCTION=CONSOLIDATE    /* Consolidate Profiler data
  RESOURCE=ON           /* Write to resource
  RESOURCE-NAME='Test'  /* Resource name
  RESOURCE-LIB=PRFDATA  /* Resource library
  REPLACE=YES           /* Replace resource
  TRANSACTION=OFF       /* Do not add transaction identifiers 
  IO-TIME=ON            /* Include I/O and RPC client times
  EXPORT=ON             /* Write to Work File 7       
  FORMAT=S              /* CSV format with semicolon separator 
  TRACE-EVENT=OFF       /* No event trace
  TRACE-CONSOLIDATE=OFF /* No consolidation trace

Evaluating Event Data

When a Natural application is profiled, the Natural Profiler utility writes the event data to an NPRF resource file. Consolidated data is stored in an NPRC resource file and coverage data is stored in an NCVF resource file. The Profiler utility READ function reads and evaluates the Profiler resource data and writes the results to standard output or to a Natural work file. The evaluations performed depend on the type of the resource file read as described in the following table:

This section covers the following topics:

• Profiler Utility READ Function

• Example of READ

• Event Trace

• Consolidation Trace

• Program Trace

• Program Summary

• Line Summary

• Transaction Summary

• Program Coverage

• Statement Coverage

• Using a Microsoft Excel Template to Visualize Coverage Results

• Statistics

Profiler Utility READ Function

The Profiler utility READ function reads and evaluates the resource data.

Syntax of READ:

Syntax Description:

Example of READ

The following example reads the Natural Profiler resource Test.nprf in the library PRFDATA and writes the event trace, program trace and the Profiler statistics to standard output and to Work File 7 in text format.

FUNCTION=READ           /* Read Profiler Data
  RESOURCE-NAME='Test'  /* Resource name
  RESOURCE-LIB=PRFDATA  /* Resource library
  RESOURCE-TYPE=NPRF    /* Use resource type NPRF
  EVENT=ON              /* Print event trace
  PROGRAM=ON            /* Print program trace
  STATISTICS=ON         /* Print statistics
  PRINT=ON              /* Write to standard output
  EXPORT=ON             /* Write to Work File 7
  FORMAT=TEXT           /* Export in text format

Event Trace

If EVENT=ON is specified for an NPRF resource file, the Profiler event trace is generated.

The event trace shows the data of each Natural event which occurred while the application executed. The trace can be referenced if detailed information of an event is required. For example, if a Natural error occurred during application execution, the event trace shows the corresponding error number and message.

If the event trace is written to standard output (PRINT=ON) or exported in text format (EXPORT=ON, FORMAT=TEXT), it is similar to the event trace written by the Profiler monitor session while the application was profiled (see Event Trace). If the data is exported in CSV (comma-separated values) format, it contains all data fields provided by the Profiler (see Data Collected).

Example of an Event Trace

The following example shows an extract of an event trace:

Natural Profiler Event Trace ---------------------------- Count Time CPU-Time (ms) Ev Lev Library Program Line CC-Lib CC-Name Statement Local-Data 0 10:20:58.219911 63.318 MP 003 SYSPRFD PRBINIT 8350 Call Monitor pause requested 102 10:20:58.277586 76.106 PL 000 0000 Execute SYSEDMD/MENU 103 10:20:58.277591 76.139 PS 001 SYSEDMD MENU 0000 PgmStart 00010/02430 Type: P 103 10:20:58.277594 76.151 NS 001 SYSEDMD MENU 0250 Compute Assign/Compute/Move 103 10:20:58.277596 76.155 NS 001 SYSEDMD MENU 0270 Fetch Fetch 104 10:20:58.277598 76.169 DB 001 SYSEDMD MENU 0270 Fetch 00010/02430 S1 ...

Explanations:

• The Count column shows the number of the event. Monitor Pause (MP) events and Natural Statement (NS) events are not counted and receive the number of the previous event.

• The Time and CPU-Time columns show the event time and the CPU timestamp of the event execution, respectively.

• The event with the number 104 is a Database Before (DB) event caused by an Adabas S1 command issued against the file 00010/02430 which was triggered by a FETCH statement in the line 0270 of the Natural object MENU.

For further explanations of the trace columns and event types, see the sections Event Trace and Events and Data Collected.

Consolidation Trace

If EVENT=ON is specified for an NPRC resource file, the Natural Profiler consolidation trace is generated. The consolidation trace is also generated if CONSOLIDATE=ON and TRACE-CONSOLIDATE=ON are set for the Profiler utility INIT function, or if TRACE-CONSOLIDATE=ON is set for the Profiler utility CONSOLIDATE function.

The consolidation trace shows general event data, summarized values of the elapsed time and CPU time and the hit count of the consolidated record. If two trace entries show the same general event data, they have different event-specific data which is not displayed in the consolidation trace.

The consolidated records are used as the basis for further evaluations like the NaturalONE hot spots or the Natural Profiler MashApp. The consolidation trace can be used to validate the consolidated data.

If the consolidation trace is written to standard output (PRINT=ON), it is similar to the consolidation trace written by the Profiler data consolidation (see Consolidating Event Data). If the data is exported, it contains all consolidated data fields provided by the Profiler.

Example of a Consolidation Trace

The following example shows an extract of a consolidation trace:

Natural Profiler Consolidation Trace ------------------------------------ Count Transact Ev User Lev Library Program Line CC-Lib CC-Name Statement Hit-Count Elapsed(ms) CPU(ms) 1 DA PRFO82D 000 0000 1 75.692 0.870 2 DA PRFO82D 000 0000 1 0.002 0.004 3 DA PRFO82D 000 0000 1 0.006 0.025 4 NS PRFO82D 006 SYSLIBS A82CLS 0010 SYSAOSSU C-COPYRT Reset 43 0.043 0.118 5 NS PRFO82D 006 SYSTEM NOMSTCS 4360 End 1 0.000 0.003 6 PL PRFO82D 006 SYSTEM NOMSTCS 0970 Callnat 1 0.008 0.058 7 PL PRFO82D 006 SYSTEM NOMSTCS 1020 Perform 1 0.004 0.017 ...

Explanations:

• The Count column shows the number of the consolidated record.

• The Transact column shows the transaction identifier.

  The transaction identifier starts with 1 and is increased with every IA (after terminal I/O) or RI (inbound RPC message) event. Transaction identifiers are only available if data is consolidated with the option TRANSACTION=ON.

• The consolidated record 4 shows that the RESET statement in the line 0010 of the copycode C-COPYRT (included in the Natural object A82CLS) executed 43 times spending a total elapsed time of 0.043 milliseconds (ms) and a total CPU time of 0.118 ms.

• The application was running on a z/OS machine with zIIP (IBM System z Integrated Information Processor). Under this condition, the CPU time can be higher than the elapsed time.

For further explanations of the trace columns and event types, see the sections Event Trace and Events and Data Collected.

Program Trace

If PROGRAM=ON is specified for an NPRF resource file, the Profiler program trace is generated. The program trace shows the program flow of the profiled application. In general, the program trace exclusively shows program and session events (see Events and Data Collected for a list of possible event types).

If the program trace is written to standard output (PRINT=ON) or exported in text format (EXPORT=ON, FORMAT=TEXT), the program names are indented (see the example below) according to the program level to provide a quick overview of the application calling structure.

If the data is exported in CSV (comma-separated values) format, the program names are not intended. In addition to the output in text format, the exported data contains the CPU timestamp and the summarized Adabas time.

Example of a Program Trace

The following example shows an extract of a program trace and the totals of the application run:

Natural Profiler Program Trace ------------------------------ Time Ev Library CC-Name Line Lev Program Events 10:20:58.309812 PL 0000 000 10:20:58.309817 PS SYSEDMD 0000 001 .OPTTEST D=4 N=2 10:20:58.357694 PL SYSEDMD 5620 001 .OPTTEST 10:20:58.357704 PS SYSEDMD 0000 002 ..CALLMON3 N=3 10:20:58.385263 PL SYSEDMD 0980 002 ..CALLMON3 10:20:58.385274 PS SYSEDMD 0000 003 ...OP3DISC D=3 N=4 10:20:58.412207 PL SYSEDMD 1670 003 ...OP3DISC 10:20:58.412221 PS SYSEDMD 0000 004 ....OPTINFO N=57 10:20:58.443203 PL SYSEDMD 5830 004 ....OPTINFO 10:20:58.443210 PS SYSEDMD 0000 005 ....:OPTPARM1 D=3 N=19 10:20:58.449549 PL SYSEDMD 1960 005 ....:OPTPARM1 10:20:58.449555 PS SYSEDMD 0000 006 ....:.OPTPARM2 D=3 N=10 10:20:58.458286 PL SYSEDMD 0560 006 ....:.OPTPARM2 10:20:58.458300 PS SYSEDMD 0000 007 ....:..OPTPARM3 N=16 10:20:58.458390 PL SYSEDMD 1530 007 ....:..OPTPARM3 10:20:58.458408 PS SYSLIBS 0000 008 ....:...NAT41004 D=10 C=6 N=7345 10:20:58.471017 PT SYSLIBS 5235 008 ....:...NAT41004 10:20:58.471017 PR SYSEDMD 1530 007 ....:..OPTPARM3 N=2898 10:20:58.473293 PL SYSEDMD 1530 007 ....:..OPTPARM3 10:20:58.473297 PS SYSLIBS 0000 008 ....:...NAT41004 D=5 C=6 N=1416 10:20:58.475581 PT SYSLIBS 5235 008 ....:...NAT41004 10:20:58.475581 PR SYSEDMD 1530 007 ....:..OPTPARM3 N=466 10:20:58.475957 PT SYSEDMD 2190 007 ....:..OPTPARM3 10:20:58.475957 PR SYSEDMD 0560 006 ....:.OPTPARM2 N=283 10:20:58.476187 PT SYSEDMD 0860 006 ....:.OPTPARM2 10:20:58.476187 PR SYSEDMD 1960 005 ....:OPTPARM1 N=42 10:20:58.476222 PT SYSEDMD 7510 005 ....:OPTPARM1 10:20:58.476222 PR SYSEDMD 5830 004 ....OPTINFO D=3 N=10 10:20:58.497926 PL SYSEDMD 6080 004 ....OPTINFO 10:20:58.521954 PR SYSEDMD 1670 003 ...OP3DISC N=241 10:21:11.205102 PR SYSEDMD 0980 002 ..CALLMON3 D=7 N=6070 10:21:41.704996 PR SYSEDMD 5620 001 .OPTTEST D=8 I=3 N=26 10:21:41.731229 PT SYSEDMD 7370 001 .OPTTEST 10:21:41.731229 PR 0000 000 D=14 I=1 10:21:42.248348 ST 0000 000 Totals ------ Ev Event Count S Session ................ 1 P Program ................ 5297 D Database Call .......... 2140 I Terminal I/O ........... 12 C External Program Call .. 6510 E Runtime Error .......... 43 N Natural Statement ...... 857384 R RPC Request............. 0 U User-Defined Event ..... 0 M Monitor Pause .......... 2

Explanations:

• For each event listed, the time when the event occurred, the active library, program (Natural object), copycode, line number and program level is displayed.

• The program name is followed by the number of events that occurred from one program event to the next program event.

• Events which belong to one event group are combined into one count using the maximum count of the corresponding event types. Example: One Database Before (DB) and one Database After (DA) event are combined into one Database event (D=1).

• In the example above, the Natural object OPTTEST was started at the level 1. This program calls the subprogram CALLMON3 which calls further subprograms. The highest Level 8 is reached when the subprogram NAT41004 executes. During the first execution, this subprogram performs 10 database calls (D=10), 6 external program calls (C=6) and 7345 Natural statements (N=7345).

• The Totals section at the end of the program trace shows the maximum count of each event group. For example: a total of 2140 database calls corresponds to 2140 Database Before (DB) and 2140 Database After (DA) events.

• The totals of the Session (S) and Program (P) event groups are only listed under Totals; they are not listed next to the program name.

For further explanations of the trace columns, see the section Event Trace.

For explanations of event types and associated event groups, see the section Events.

Program Summary

If PROGRAM=ON is specified for an NPRC resource file, the Profiler program summary is generated.

The program summary shows for each Natural object how many Natural events have occurred, the total CPU time (in milliseconds) and the percentage of the CPU time spent by the Natural object with respect to the total CPU time.

Monitor Pause events and events at Level 0 are not taken into account for the program summary. Events which belong to one event group are combined into one count: see Events.

Program starts and load requests are listed separately.

If the data is exported in CSV (comma-separated values) format, the count of each event type is listed. Additionally, the elapsed time and the Adabas times (absolute and percentage values) are displayed. The exported time values are indicated in microseconds.

Example of a Program Summary

The following example shows the extract of a program summary:

Natural Profiler Program Summary -------------------------------- Library Program Start Load Database I/O External Error Statement User CPU-Time (ms) CPU % SYSEDMD ADA-CL 41 0 40 0 41 0 621 0 3.785 0.14 SYSEDMD ADA-RC 45 0 44 0 45 0 545 0 4.704 0.17 SYSEDMD AOS-CL 115 97 15 0 0 0 2507 0 42.890 1.63 SYSEDMD AOS-OP 169 154 22 0 0 0 6975 0 70.286 2.68 SYSEDMD BYTE 1 0 0 0 0 0 11 0 0.034 0.00 SYSEDMD CALLMON3 1 5 23 0 0 0 7089 0 20.001 0.76 SYSEDMD CALLNOM 6 6 19 0 0 0 18 0 1.342 0.05 SYSEDMD CALLNOPM 2 2 4 0 0 0 16 0 0.395 0.01 SYSEDMD CALLNOPN 1 1 4 0 0 0 8 0 0.244 0.00 SYSEDMD CALLNOPS 3 4 23 0 0 1 31 0 1.841 0.07 SYSEDMD DISNOP 1 7 6 0 0 0 515 0 2.260 0.08 SYSEDMD DISNO4I 1 47 3 0 1 0 8075 0 25.516 0.97 SYSEDMD DISNO4IS 57 0 0 0 624 0 36877 0 105.650 4.03 SYSEDMD DISNRS 1 0 0 0 44 0 511 0 3.343 0.12 SYSEDMD DISNSP 1 18 15 0 0 0 1850 0 6.074 0.23 SYSEDMD DISNTMZ 1 4 11 0 0 0 324 0 2.309 0.08 SYSEDMD MENU 1 1 3 0 0 0 2 0 0.235 0.00 SYSEDMD MONACSH 1 6 6 0 0 0 1217 0 3.470 0.13 SYSEDMD MONADA 1 3176 71 0 0 0 272180 0 680.214 25.98 SYSEDMD MONAREP 1 9 28 0 0 0 1964 0 6.378 0.24 ... Total 5294 5293 2122 7 6510 43 857384 0 2617.326 100.00

Explanations:

• The Natural object MONADA consumed the most CPU time: 680.214 ms which corresponds to 25.98 percent of the total CPU time.

• MONADA was started once, it loaded 3176 other Natural objects, performed 71 database calls and 272180 Natural statements. There was no I/O, no external call and no error in the program.

• At the end of the program summary, the Total counts of the profiling are listed.

Line Summary

If LINE=ON is specified for an NPRC resource file, the Profiler line summary is generated.

The line summary shows for each source line in a Natural object, the number of Natural events that occurred (hit count), the CPU and elapsed time (in milliseconds and percent) spent by the line. The percentage of times is calculated in relation to the total times of the application.

The line summary does not count Monitor Pause events and events at Level 0.

If the data is exported in CSV (comma-separated values) format, the count of each event type is listed. Additionally, the Adabas times (absolute and percentage values) are displayed. The exported time values are indicated in microseconds.

Example of a Line Summary

The following example shows the extract of a line summary:

Natural Profiler Line Summary -------------------------------- Library Program Line CC-Lib CC-Name Hit-Count CPU (ms) CPU % Elapsed (ms) Ela % PRFTEST XINT 0000 1 0.016 0.46 0.003 0.01 PRFTEST XINT 0140 1 0.005 0.14 0.001 0.00 PRFTEST XINT 0150 1 0.006 0.17 0.002 0.01 PRFTEST XINT 0160 1 0.004 0.11 0.001 0.00 PRFTEST XINT 0170 23 0.128 3.75 0.029 0.18 PRFTEST XINT 0180 10 0.049 1.43 0.012 0.07 PRFTEST XINT 0190 10 0.054 1.58 0.010 0.06 ... Total 371 3.408 100.00 15.992 100.00

Explanations:

• Line 0170 in the Natural object XINT consumed 0.128 ms of the CPU time and 0.029 ms of the elapsed time. This corresponds to 3.75 percent of the total CPU time and 0.18 percent of the total elapsed time. 23 events (hit count) were executed in the line.

• At the end of the line summary, the Total counts of the profiling are listed.

Transaction Summary

A transaction is the code executed between two consecutive terminal I/O operations. The elapsed time spent on executing a transaction is called response time.

The transaction summary generated by the Profiler shows how many Natural events have occurred for each transaction, the response time (in milliseconds) and the percentage of the response time spent by the transaction with respect to the total response time.

Prerequisites Required for Transaction Evaluations

The Profiler data must be consolidated with the CONSOLIDATE function set to TRANSACTION=ON so that the consolidated data records in the NPRC resource file contain transaction identifiers required for evaluating the transaction response time.

TRANSACTION=ON is specified for the READ function.

Event Data Evaluated for Transactions

In general, one terminal I/O event relates to one transaction. The number of terminal I/O events is not listed in standard output (for PRINT=ON).

Data exported in CSV (comma-separated values) format contains the count of each event type, including terminal I/O. Additionally, the data list contains the CPU time and the Adabas times (absolute and percentage values). Exported time values are indicated in microseconds.

The transaction summary does not consider Before Terminal I/O (IB) events, RPC Wait for Client (RW) events, Monitor Pause (MP) events and events at Level 0. Events that belong to one event group are combined into one count.

For explanations of event types and associated event groups, see the section Events.

Modified Line and Program Summary

If TRANSACTION=ON is specified for the READ function of an NPRC resource file, the program summary and the line summary also consider the transaction identifier and aggregate the program and line values for each transaction separately. In the transaction line summary, the ID column indicates the program line in which the transaction was started.

Example of a Transaction Summary

The following example shows a transaction summary:

Natural Profiler Transaction Summary ------------------------------------ Transact TA-Lib TA-Prog TA-CC TA-Line Program Database External Error Statement User Elapsed (ms) Time% 1 1 0 1 0 0 0 0.829 0.50 2 SYSPRFLR PRFMENM 0020 9 13 8 0 0 0 17.618 10.65 3 SYSEDM MOPTTEST 0020 4 0 0 0 0 0 6.167 3.72 4 SYSEDM OPTWLS80 0470 0 0 0 0 0 0 1.108 0.66 5 SYSEDM OPTWLS80 0470 2 0 0 0 0 0 1.133 0.68 6 SYSEDM OPTTEST 1750 1 0 0 0 0 0 1.180 0.71 7 SYSEDM MOPTTEST 0020 27 33 30 0 0 0 94.236 56.96 8 SYSEDM OPTTEST 5590 1 0 0 0 0 0 1.185 0.71 9 SYSEDM MOPTTEST 0020 37 33 56 0 0 0 37.311 22.55 10 SYSEDM OPTTEST 5760 1 0 0 0 0 0 1.096 0.66 11 SYSEDM MOPTTEST 0020 6 0 6 0 0 0 2.164 1.30 12 SYSPRFLR PRFMENM 0020 2 0 3 0 0 0 1.394 0.84 Total 86 79 103 0 0 0 165.421 100.00

Explanations using the example of Transaction 7:

• Transaction 7 spent the longest response (elapsed) time: 94.236 milliseconds (ms) which correspond to 56.96 percent of the total response time.

• Transaction 7 started an I/O operation in the library SYSEDM (TA-Lib column), program MOPTTEST (TA-Prog), program line 0020 (TA-Line).

• Transaction 7 accessed 27 programs and issued 33 database calls and 30 external program calls.

• In the example above, all counters for statement events are 0 because statement events were not collected during this Profiler run.

• At the end of the transaction summary, the Total counts of the profiled transactions are listed.

Program Coverage

The program coverage table is generated if PROGRAM=ON is specified for an NCVF resource file.

The program coverage table shows the code coverage results for each accessed Natural object. If the table is given in text format, only the GP coverage results (copycodes included) are displayed. In CSV (comma-separated values) format, the table shows lines containing copycode values, additional columns with source counters (copycodes not included) and information regarding INCLUDE statements.

In text format, the table provides the coverage count for each accessed library and for the whole application.

The table contains the following columns:

Example of Program Coverage

The following example shows the result of program coverage in text format:

Program Coverage                                          
----------------                                          
Library  Object   Ty Coverage%  Covered    Missed    Total
COVDEMO  TESTCOVN N      84.0%       37         7       44
COVDEMO  TESTCOVP P      69.2%        9         4       13
COVDEMO  -------- --     80.7%       46        11       57
Totals   -------- --     80.7%       46        11       57

Explanations:

• The application accesses two objects, the TESTCOVN subprogram (N) and the TESTCOVP program (P).

• In TESTCOVN, there are 44 executable statements (object code instructions) from which 37 were covered (executed) and 7 missed (not executed), giving a total coverage of 84.0%.

• The summarized values of the two objects accessed in the library COVDEMO show coverage of 80.7%.

• Total coverage is also 80.7% because only one library is accessed by the objects.

Statement Coverage

Statement coverage is generated if EVENT=ON is specified for an NCVF resource file.

For statement coverage, the Profiler utility reads the source of the monitored objects. If the source is not found or if the source does not match the collected data, source lines are not printed in the statement coverage report. The Profiler utility resolves INCLUDE statements and merges the source of the corresponding copycode into the including program. If the INCLUDE structure cannot be resolved, the copycodes are printed separately.

We recommend that you perform the READ function soon after the coverage run, as long as the sources correspond to the monitored GPs. As soon as the sources have been modified, the Profiler utility can no longer provide the full information.

Statement coverage shows the percentage of statements covered for each source line of the accessed programs. If the result is written in text format, for each object listed in the statistics, the object coverage values are shown before the statement coverage data. If the result is written in CSV (comma-separated values) format, additional information regarding statement coverage is provided.

The table contains the following columns:

Example of Statement Coverage

The following example assumes that the development has delivered a new version of the TESTCOVN subprogram to the quality engineering. After running the test programs, statement coverage of the subprogram shows the following result (text format):

Statement Coverage
------------------ 
M Cov% CC-Lib   CC-Name  Line Source                         
*                        0010 * Test function Coverage       
*                        0020 * Subprogram TESTCOVN          
+                        0030 DEFINE DATA                    
+                        0040 PARAMETER                      
+                        0050 1 FUNC     (I2)  /* Function   
+                        0060 1 RET-CODE (I4)  /* Return code
+                        0070 END-DEFINE                     
*                        0080 *                              
*                        0090 /* Return 0 by default         
C 100%                   0100 RESET RET-CODE                 
*                        0110 *                              
C 100%                   0120 DECIDE ON FIRST VALUE OF FUNC  
P  50%                   0130   VALUE 0                      
M   0%                   0140     PRINT 'Test function 0'    
P  66%                   0150   VALUE 1                      
C 100%                   0160     PRINT 'Test function 1'    
C 100%                   0170   VALUE 2                      
C 100%                   0180     PRINT 'Test function 2'    
C 100%                   0190   VALUE 3                      
C 100%                   0200     PRINT 'Test function 3'    
C 100%                   0210   VALUE 4                      
C 100%                   0220     PRINT 'Test function 4'    
C 100%                   0230   VALUE 5                                 
C 100%                   0240     PRINT 'Test function 5'               
C 100%                   0250   VALUE 6                                 
C 100%                   0260     PRINT 'Test function 6'               
C 100%                   0270   VALUE 7                                 
C 100%                   0280     PRINT 'Test function 7'               
C 100%                   0290   VALUE 8                                 
C 100%                   0300     PRINT 'Test function 8'               
P  33%                   0310   VALUE 9                                 
M   0%                   0320     PRINT 'New test function 9'           
C 100%                   0330   NONE VALUE                              
M   0%                   0340     RET-CODE := 1 /* Unsupported function
+                        0350 END-DECIDE                                
*                        0360 *                                         
C 100%                   0370 END

Explanations:

• The Mark (M) column shows whether a line is covered (C), missed (M) or partly covered (P).

• No test cases cover the functions Test function 0 and New test function 9 (denoted with M and 0% coverage). The NONE VALUE case is also not covered.

• All other test cases are covered (denoted with C and 100% coverage).

• A Natural VALUE statement corresponds to multiple object code instructions. The coverage of 50% and 60% for VALUE 0 and VALUE 1 statements indicates that only a part of these object code instructions are covered.

  This is because one of the generated object code instructions belongs to the previous statement and the others to the current VALUE statement for technical reasons.

As a consequence of this coverage analysis, the test cases have to be adjusted so that Test function 0 and Test function 9 (and, perhaps, the error case with an unsupported function code) are also covered.

Using a Microsoft Excel Template to Visualize Coverage Results

Prerequisites: Microsoft Excel and Natural for Windows or Natural for UNIX.

If you want to analyze the coverage result with Microsoft Excel, you can use the Microsoft Excel template delivered with Natural for Windows and Natural for UNIX. Perform the following steps:

1. Perform the Profiler READ function and write the output data in CSV (comma-separated values) format to Work File 7. For example:

   FUNCTION=READ           /* Read Profiler Data
     RESOURCE-NAME='Test'  /* Resource name
     RESOURCE-LIB=PRFDATA  /* Resource library
     RESOURCE-TYPE=NCVF    /* Use resource type NCVF
     EVENT=ON              /* Print statement coverage
     PROGRAM=ON            /* Print program coverage
     STATISTICS=ON         /* Print statistics
     PRINT=ON              /* Write to standard output
     EXPORT=ON             /* Write to Work File 7
     FORMAT=COMMA          /* Export in CSV format

2. If your Microsoft Excel requires semicolons as separators, specify the following:

   FORMAT=SEMICOLON      /* Export in CSV format

3. Export the data of Work File 7 with any tool (such as FTP) as a CSV-formatted file to a Windows environment.

4. Open the CSV file with Microsoft Excel.

5. Rearrange the data so that each evaluation type (program, event, statistics) is on its own worksheet in the Microsoft Excel file.

6. Open the delivered template TESTCOV.XLSX with Microsoft Excel. The template is contained in the RES (Resources) subdirectory of the Natural SYSPRFLR system library.

7. For each worksheet, copy the format from the template to your Microsoft Excel:

   • Click on the upper left corner of the table in the template to mark all data in the table.

   • Click on the Microsoft Excel Copy format function.

   • Click on the upper left corner of the table in your worksheet to copy the format.

     Now, all entries are formatted as in the template. The source lines are colored and marked as follows:

     Color	Mark	Description
     Green	C	All statements in the line are covered.
     Yellow	P	The statements in the line are partly covered.
     Pink	M	All statements in the line are missed.
     Gray	*	A comment or an empty line.
     Red	E	Error encountered. For example, if the coverage analysis has collected a line number but the corresponding source line is not found.
     None (white)	+	All other lines such as continuation lines of a statement.

Example of a Microsoft Excel Worksheet

The following example shows a worksheet extract of code coverage for the TESTCOVP program with included TESTCOVC copycode without the columns that contain the object name and library:

Explanations:

• The source lines of the TESTCOVC copycode are included in the source of the TESTCOVP program and placed right after the corresponding INCLUDE statement.

• The lines 40 through 70 (in pink) of the copycode contain missed statements, which means they were not executed in the test run.

• All other lines (in green) containing executable statements are covered.

• A FOR statement corresponds to four object code instructions. All four instructions are covered as indicated by x1111 in the Item Coverage column.

Statistics

If STATISTICS=ON is specified, the Profiler statistics are listed.

If the data is exported in CSV (comma-separated values) format, the properties and values of the Profiler statistics are added as separate columns to the event or consolidation trace. If coverage data is exported in CSV format, the statistics values are added in additional lines indicated by the value Statistics in the Evaluation column.

Example of Statistics

The following example shows an extract of the statistics of an NPRC resource file:

*************************************************************************** * 11:02:39 ***** NATURAL PROFILER UTILITY ***** 2015-08-05 * User SAGTEST1 - Statistics - RESDATA * * General Info * Machine class ...................... MAINFRAME * Environment ........................ Batch ... * Profiler Resource File * Resource name ...................... EDM-MONITOR.nprc * Resource type ...................... Natural Profiler Resource Consolidated * Resource allocation date ........... 2015-07-27 10:36:19.6 * Resource size (bytes) .............. 565160 ... * * Monitor Session * Monitor start time ................. 2015-07-27 10:20:57.2 * Monitor end time ................... 2015-07-27 10:21:42.8 * Monitor elapsed time (sec) ......... 45.519604 * * Trace Session * First library ...................... SYSEDMD * First program ...................... MENU * Highest level ...................... 10 * Trace start time ................... 10:20:58.219911 * Trace end time ..................... 10:21:42.248348 * Trace elapsed time (sec) ........... 44.028437 ... * Data Processing * Number of events ................... 895936 ... * Data Consolidation * Consolidation ...................... ON * Consolidation records .............. 21624 * Consolidation elapsed time (sec) ... 15.643516 * Consolidation factor ............... 41.4 * Consolidation records/block ........ 191.3 * Bytes/consolidation record ......... 25.8 * ... ***************************************************************************

Explanations:

• The EDM-MONITOR.nprc resource was allocated on 2015-07-27 at 10:36:19 a.m. and has a size of 565160 bytes.

• The profiled application was running on the same day at 10:20:58 a.m. for 44.0 seconds and started with the program MENU in the library SYSEDMD.

• The profiled application generated a total of 895936 Natural events. The data consolidation took 15.6 seconds and reduced the number of records to 21624 which corresponds to a consolidation factor of 41.4.

All statistics information provided is explained in the section Profiler Statistics.

Exporting Event Data for MashZone

You can visualize Profiler event data on an interactive MashZone dashboard by using the Natural Profiler MashApp.

The Profiler utility MASHZONE function reads the consolidated data of an NPRC resource file and writes the data to Work File 7 in the format expected by the Natural Profiler MashApp. The data of Work File 7 has to be exported by any tool (like FTP) as CSV (comma-separated values) file to the Natural Profiler directory in the MashZone environment before it can be accessed by the Natural Profiler MashApp.

Syntax of MASHZONE:

Syntax Description:

Alternative Function Specifications

READ

The following Profiler utility READ function is equivalent to the MASHZONE function and generates the same export data:

FUNCTION=READ
  RESOURCE-NAME=resource-name
  RESOURCE-LIB=library-name
  RESOURCE-TYPE=NPRC
  EVENT=ON
  PROGRAM=OFF
  LINE=OFF
  TRANSACTION=OFF   
  STATISTICS=ON
  PRINT=OFF
  EXPORT=ON
  FORMAT=SEMICOLON

CONSOLIDATE

The Natural Profiler MashApp can also process data exported with the Profiler utility CONSOLIDATE function if you specify the following keywords:

FUNCTION=CONSOLIDATE    /* Consolidate Profiler data
  TRANSACTION=ON        /* Add transaction identifiers
  EXPORT=ON             /* Write to Work File 7
  FORMAT=SEMICOLON      /* CVS format with semicolon separator 
  ...

Example of MASHZONE

The following example reads the consolidated Profiler resource Test.nprc in the library PRFDATA. The data is written in CSV (comma-separated values) format to Work File 7 which can be exported to MashZone.

FUNCTION=MASHZONE       /* Export Profiler data for MashZone
  RESOURCE-NAME='Test'  /* Resource name
  RESOURCE-LIB=PRFDATA  /* Resource library

Maintaining Profiler Resource Files

In general, Profiler resources are listed as NPRF, NPRC or NCVF files by using the Natural SYSMAIN utility, NaturalONE or Natural Studio. These tools also provide functions to copy, rename and delete resource files.

In addition, you can use Profiler utility functions to list and delete Profiler resource files.

This section covers the following topics:

• Listing Profiler Resource Files

• Deleting a Resource File

Listing Profiler Resource Files

The Profiler utility LIST function lists the Profiler resource files of a given Natural library and the date and time when the resource files were allocated.

Syntax of LIST:

Syntax Description:

Example of LIST

The following example lists the NPRF Profiler resource files of library PRFDATA. The list is written to standard output and to Work File 7 in text format.

FUNCTION=LIST           /* List Profiler resource files
  RESOURCE-LIB=PRFDATA  /* Resource library
  RESOURCE-TYPE=NPRF    /* List NPRF resource files
  PRINT=ON              /* Write to standard output
  EXPORT=ON             /* Write to Work File 7
  FORMAT=TEXT           /* Export in text format

Output:

Natural Profiler Resources
--------------------------
Library: PRFDATA
Resource type: nprf
 
Count Date       Time     Name
    1 2015-06-15 14:32:18 Hello1.nprf
    2 2015-06-26 18:39:57 QDTest1.nprf
    3 2015-06-24 22:00:35 QETest1.nprf
    4 2015-06-30 14:32:42 Studio.nprf
    5 2015-07-02 15:02:32 Test.nprf
 
Number of nprf resources in library PRFDATA: 5

Deleting a Resource File

If you delete or replace a big resource file, it can happen that you receive the following error message:

Error - NAT3047 Maximum value for Adabas parameter NISNHQ was exceeded.

In this case, you have two options:

1. Contact your database administrator to increase the Adabas parameter NISNHQ.

2. Use the Profiler utility DELETE function to perform a "dirty" delete of the resource. This function does not delete the resource in one big step but in chunks (with an end of transaction after each chunk). If the DELETE function fails by any reason, you need to repeat it to get rid of inconsistent data.

   Syntax of DELETE:

   FUNCTION=DELETE

   [RESOURCE-NAME=resource-name]

   [RESOURCE-TYPE={NPRF|NPRC|NCVF|NPRK|NONE}]

   [RESOURCE-LIB=library-name]

   Syntax Description:

   Keyword for DELETE	Value	Description
   RESOURCE-NAME	resource-name	The name of the Profiler resource file you want to delete. Possible extensions are .nprf (Natural Profiler resource file), .nprc (Natural Profiler resource consolidated), .ncvf (Natural code coverage file) or .nprk (Natural Profiler resource key). If no extension has been specified, the extension specified with the keyword RESOURCE-TYPE is added automatically. Default: none If RESOURCE-TYPE=NPRK is specified and no RESOURCE-NAME, the name of the Profiler resource file containing the NaturalONE Profiler key is used as resource-name.
   RESOURCE-TYPE		The default resource type (extension) to be deleted if no extension is specified with RESOURCE-NAME. Default: NPRF
   	NPRF	The default resource type is NPRF with the extension .nprf.
   	NPRC	The default resource type is NPRC with the extension .nprc.
   	NCVF	The default resource type is NCVF with the extension .ncvf.
   	NPRK	The default resource type is NPRK with the extension .nprk.
   	NONE	The resource with the short name resource-name is deleted.
   RESOURCE-LIB	library-name	The name of the Natural library that contains the resource you want to delete. Default: The name of the current library

Example of DELETE

FUNCTION=DELETE         /* Delete a Profiler resource file
  RESOURCE-NAME='Test'  /* Resource name
  RESOURCE-TYPE=NPRF    /* Resource type
  RESOURCE-LIB=PRFDATA  /* Resource library

Including Profiler Input from Natural Text Objects

The Profiler can read input data from a Natural text object. The syntax of the data in the Natural text object is the same as for the primary command input data set CMSYNIN (see Syntax and Keywords).

To include Profiler input data from a Natural text object

• Enter the following Profiler keywords:

  INCLUDE-LIB=library-name
  INCLUDE=object-name

  The keyword syntax is explained in Profiler Utility Keywords.

The data in the Natural text object is added to the Profiler input data in the line after the INCLUDE keyword. The Profiler input data can contain multiple INCLUDE keywords, and the related Natural text objects can also contain INCLUDE keywords. If a Natural text object contains an END-PROFILER keyword, the Profiler utility terminates and any remaining data in the Natural text object(s) is ignored.

The Natural system library SYSPRFLR supplies text object whose names begin with X which can be used as Profiler input. The individual Profiler functions they perform are described in the sources of these objects.

We recommend that you do not modify any objects in the system library SYSPRFLR because they can be overwritten or removed when a new Natural version is installed. Copy the required object(s) to a user library before you edit it.

Examples of INCLUDE

The following example adds the contents of the Natural MYPROF text object from the library MYLIB to the Profiler input data:

INCLUDE-LIB=MYLIB
INCLUDE=MYPROF

The following example adds the contents of the Natural text object XINIT from the library SYSPRFLR to the Profiler input data. The object initializes and starts profiling without consolidation and without statement event collection. Additionally, it terminates the Profiler utility so that no further Profiler input is expected after the INCLUDE keyword.

INCLUDE=XINIT

Event Trace

The Natural Profiler collects detailed information of each Natural event that occurs while a Natural application executes. This data can be viewed in the event trace.

The traces written for Natural code coverage are described in the section Tracing Natural Code Coverage.

The Profiler utility provides the following options to write a Profiler event trace:

• Write the trace to standard output of the Profiler monitor session (MONPRINT data set) while the application is profiled.

• Write the trace to standard output while the NPRF data is consolidated. In this case, the event trace shows the delta values of the elapsed time and the CPU time instead of event-specific data.

• Write the trace when reading a Profiler NPRF resource file with the Profiler utility READ function.

To enable the event trace

• Enter the following subordinate keyword of the Profiler utility INIT function:

  TRACE-EVENT=ON

  Enter the following subordinate keyword of the Profiler utility CONSOLIDATE function:

  TRACE-EVENT=ON

  Enter the following subordinate keyword of the Profiler utility READ function:

  EVENT=ON

The Profiler event trace contains the following columns:

Example of an Event Trace

In the following example, the Profiler utility READ function prints the event trace:

FUNCTION=READ               /* Read event data
  EVENT=ON                  /* Write event trace

The event trace is written to standard output:

Count Time              CPU-Time (ms) Ev Lev Library  Program  Line CC-Lib   CC-Name  Statement  Local-Data
    0 17:38:17.200951          42.324 MP 003 SYSPRFLR PRBINIT  8370                   Call       Monitor pause requested
    0 17:38:17.204508          43.471 MP 003 SYSPRFLR PRBSTART 1760                   Call       Start of block filter
   11 17:38:17.218379          48.874 DB 000                   0000                              00010/00032 S1
   12 17:38:17.218941          48.897 DA 000                   0000                              00010/00032 S1   Rsp: 0
   13 17:38:17.218944          48.910 PL 000                   0000                              Execute PRFDEMO/XPROF
   14 17:38:17.218945          48.916 PS 001 PRFDEMO  XPROF    0000                   PgmStart   00010/00032 Type: P
   15 17:38:17.218956          48.979 IB 001 PRFDEMO  XPROF    0300                   Input      Out: 133 In: 0
   16 17:38:17.219235          49.046 IA 001 PRFDEMO  XPROF    0300                   Input      Out: 133 In: 80
   17 17:38:17.219258          49.182 DB 001 PRFDEMO  XPROF    0370                   Callnat    00010/00032 S1
   18 17:38:17.220426          49.211 DA 001 PRFDEMO  XPROF    0370                   Callnat    00010/00032 S1   Rsp: 0
   19 17:38:17.220427          49.216 DB 001 PRFDEMO  XPROF    0370                   Callnat    00010/00032 S1
   ...

Tracing Natural Code Coverage

When Natural code coverage is performed, two trace options are available:

• The event trace lists all monitored events. These are the program start (PS) and Natural statement (NS) events by default. Additionally, when the Profiler reads the GP, the Profiler writes an event trace entry for each statement found in the GP. These entries are indicated by the pseudo-event type GP.

• The coverage trace lists all records which are written to the Natural coverage resource file.

When the coverage resource is read with the Profiler utility READ function, the following trace option is available:

• The internal data trace lists all records which are read from the Natural coverage resource file.

To enable tracing for code coverage

1. Enable the event trace by specifying the following subordinate keyword of the Profiler utility COVERAGE function:

   TRACE-EVENT=ON

2. Enable the coverage trace by specifying the following subordinate keyword of the Profiler utility COVERAGE function:

   TRACE-COVERAGE=ON

3. Enable the internal trace by specifying the following subordinate keyword of the Profiler utility READ function:

   TRACE=9

The table below describes the properties listed in the traces and indicates with (X) for which type of trace the data is provided:

Example of a Coverage Trace

In the following example, the Profiler utility COVERAGE function writes the coverage trace:

FUNCTION=COVERAGE           /* Initialize code coverage
  TRACE-COVERAGE=ON         /* Write coverage trace

The coverage trace is written to the standard output of the Profiler monitor session (MONPRINT data set):

                        Natural Coverage Trace                                                                
                        ----------------------                                                                
Count Ev Library  Program  Ty CC-Lib   CC-Name  Line Statement  CC-ID Par-CC INCL  FirstS  Stmts    Item Cover
    1 PI COVDEMO  TESTCOVN N                                        0      0 0000       1     44         1    
    2 NS COVDEMO  TESTCOVN                      0130 Compute        0                                  4 0    
    3 NS COVDEMO  TESTCOVN                      0140 Print          0                                  5 0    
    4 NS COVDEMO  TESTCOVN                      0150 Goto           0                                  6 0    
    5 NS COVDEMO  TESTCOVN                      0310 If             0                                 39 0    
    6 NS COVDEMO  TESTCOVN                      0310 Compute        0                                 40 0    
    7 NS COVDEMO  TESTCOVN                      0320 Print          0                                 41 0    
    8 NS COVDEMO  TESTCOVN                      0340 Compute        0                                 43 0    
    9 NS COVDEMO  TESTCOVN                      0100 Reset          0                                  1 1    
   10 NS COVDEMO  TESTCOVN                      0120 Reset          0                                  2 1    
   11 NS COVDEMO  TESTCOVN                      0130 If             0                                  3 1    
   12 NS COVDEMO  TESTCOVN                      0150 If             0                                  7 1    
...

Internal Trace

The Profiler internal trace writes Profiler messages such as errors or warnings.

The internal trace can be activated for the following:

• The Profiler monitor sessions (data collection). The data is written to the standard output of the monitor session.

• The Profiler data processing functions. The data is written to standard output.

To activate the internal trace for the Profiler trace session or the data processing functions

• Enter the following Profiler keyword:

  TRACE=n

  where n is the trace level (see Trace Levels).

  Notes:

  1. By default (if TRACE is not specified), Trace Level 2 (warnings) is used.
  2. The trace is activated as soon as the TRACE keyword is specified. It is therefore recommended to specify the TRACE keyword as soon as possible.
  3. If you execute the Profiler utility multiple times in the job, you need to specify the TRACE keyword with each execution.

To activate the internal trace for the Profiler monitor session

• Enter the following subordinate keyword of the Profiler utility INIT or COVERAGE function:

  TRACE-MONITOR=n

  where n is the trace level (see Trace Levels).

  Note:
  By default (if TRACE-MONITOR is not specified), Trace Level 3 (statistics) is used.

Trace Levels

The trace levels used by the Profiler trace and monitor sessions and by the Profiler data processing functions are listed in the following table. In general, a higher trace level also contains the information of the lower trace levels. For example, if you select Trace Level 3 (statistics), error messages and warnings are also logged.

We recommend that you use at least Trace Level 2 (warnings) so that error messages and warnings are logged. For the Profiler monitor session, Trace Level 3 (statistics) is a good choice. It prints the statistics of the Profiler run (see Profiler Statistics). Higher trace levels for the monitor session can be extremely verbose and the output can be mixed up with the event trace (if activated).

Example

In the following example, the Profiler internal trace is set to 4 (function) for the trace session:

* Set Profiler internal trace
TRACE=4                     /* Trace level

Output of the Profiler trace session for Trace Level 4:

PRBMAIN : Profiler trace level: 4
PRBMAIN : Profiler On-Error: Terminate
***************************************************************************
* 15:45:14          ***** NATURAL PROFILER UTILITY *****         2014-12-17
* User SAGPRFD1               - Function INIT -                     PRBINIT
*
* Keyword              Value
* -------------------- ----------------------------------------------------
* Resource             ON
* Resource-Lib         SAGPROF
* Resource-Name        Test01.nprf
* Replace              Y
* Wait-Full            60
* Wait-Empty           60
* Sampling             OFF
* Consolidate          OFF
* Trace-Monitor        5
* Trace-Event          OFF
* Trace-Consolidate    OFF
* -------------------- ----------------------------------------------------
***************************************************************************
PRBINIT : Profiler INIT function - Start monitor session.
PRBINIT : Profiler INIT function - Monitor session started. Time: 1.0 sec.
PRBINIT : Set trace session Id ...: 0000000000000001
PRBINIT : Set monitor session Id .: 0000000100000000
PRBINIT : Trace session successfully initialized.
PRBFEVEN: Event filter: SI ST DB DA PL PS PT PR IB IA E CB CA U RS RI RO NS
PRBSTART: Profiling started.
PRBMAIN : Profiler - End of input.
***************************************************************************
...
Output of the application
...

Profiler Statistics

In addition to event data, the Profiler collects statistical data which is written to the Profiler resource file.

The Profiler utility provides the following options to write and view Profiler statistics:

• Write the statistics to the standard output of the Profiler monitor session (MONPRINT data set) while the application is profiled or code coverage is performed.

• Write the statistics to standard output while the data is consolidated.

• Write the statistics when reading a Profiler resource file with the Profiler utility READ function.

• View the statistics with the Natural Profiler MashApp.

To write Profiler statistics, perform one of the following steps

• Enter the following subordinate keyword of the Profiler utility INIT or COVERAGE function:

  TRACE-MONITOR=3

  or a higher trace level (see Trace Levels). Trace Level 3 is also the default level for the Profiler monitor session.

• Enter the following keyword before you start the Profiler utility CONSOLIDATE function:

  TRACE=3

  or a higher trace level (see Trace Levels).

• Enter the following subordinate keyword of the Profiler utility READ function:

  STATISTICS=ON

The Profiler statistical data is displayed in categories combining properties of a similar type. The following categories are available:

• General Information

• Profiler Resource File

• Monitor Session

• Trace Session

• Data Processing

• Event Type Statistics

• Monitor Pause Statistics

• Data Consolidation

• Coverage

• Transaction

General Information

Display environment and Natural Profiler related information.

Profiler Resource File

Display Profiler resource file related information.

Monitor Session

Display statistics of the Profiler monitor session.

Trace Session

Display statistics of the Profiler trace session. The Profiler trace session includes also the application execution.

Data Processing

Display statistics of the data processing, compression and transfer.

The compression rate is calculated by the following formula:

Event Type Statistics

Display statistics of the event types.

Monitor Pause Statistics

Display statistics of the types of Monitor Pause events.

Data Consolidation

Display statistics of the data consolidation.

ConsolidationFactor := NumberOfEvents / ConsolidationRecords

Coverage

Display statistics of Natural code coverage.

Transaction

Display statistics of executed transactions.

For more information on evaluating transactions, see Transaction Summary.