The bear traps when using enclaves

I hit several problems when trying to use the enclave support.

In summary

  1. The functions to set up and use an enclave are available from C, but the functions to query and display usage are not available from C (and so not available from Java).
  2. Some functions caused an infinite loop because they overwrote the save area.
  3. Not all classify functions are available in C.  For example ClientIPAddr
  4. I had problems in 64 bit mode.
  5. Various documentation problems
  6. It is not documented that you need to pass the connection token to __server_classify(_SERVER_CLASSIFY_CONNTKN, (char * ) connToken. You get errno2 errno2=0x0330083B.  Home address space does not own the connect token
    from the input parameter list.
  7. You can query the CPU used by your enclave using the IWMQTME macro (in supervisor state!). I had to specify CURRENT_DISP=YES to cause the dispatcher to be called to update the CPU figures.  By default the CPU usage figures are updated at the end of a dispatch cycle.  On my low use system, my transactions were running without being redispatched, and so the CPU “used” was reported as 0.

In more detail…

Minimum functionality for C programs.

You cannot obtain the CPU used by the enclaves from a C program, as the functions are not defined.  I had to write my own assembler code to called the assembler macros to obtain the information.  Some of these macros require supervisor state.

Many macros clobber the save area

Many macros, use a program call to execute a function.  Other functions such as  IWMEQTME use a BASR instruction.  This function then does a standard save of the registers.  This means that you need to have a standard function save area.  Without this, the callers save area was used, and this overwrote the register, and Branch back… just branched to after the macro.

Instead of a function like

EDEL     RMODE  ANY 
EDEL     AMODE  31 
EDEL     CSECT 
          USING *,12 
          STM  14,12,12(13) 
          LR   12,15 
          L    6 0(1)  the work area  
          L    2,4(1)  ADDRESS OF THE passed data              
          IWM4EDEL ETOKEN=0(2),MF=(E,0(6),COMPLETE),                   XX 
                CPUTIME=8(2),ZAAPTIME=16(2),ZIIPTIME=24(2),            XX 
                RSNCODE=32(2),RETCODE=36(2) 
          LM   14,12,12(13) 
          SR   15,15 
          BR   14

I needed to add in code to create a save area, for example with a different macro

QCPU     RMODE  ANY 
QCPU     AMODE  31 
QCPU     CSECT 
** CAUTION THE IWMEQTME CORRUPTS SAVE AREA SO PROGRAM NEEDS ITS OWN
** SAVE AREA 
      USING *,12 
      STM  14,12,12(13) 
      LR   2,1 
      LR   12,15 
      LA    0,WORKLEN 
      STORAGE OBTAIN,LENGTH=(0) 
      ST     1,8(,13) FORWARD CHAIN IN PREV SAVE AREA 
      ST     13,4(,1) BACKWARD CHAIN IN NEXT SAVE AREA 
      LR     13,1     SET UP NEW SAVE AREA/REENTRANT WORKAREA 
      L    2,0(2)  ADDRESS OF THE CPUTIME 
      IWMEQTME CPUTIME=8(2),ZAAPTIME=16(2),ZIIPTIME=24(2),          X 
            CURRENT_DISP=YES,                                       X 
            RSNCODE=4(2),RETCODE=0(2),MF=(E,32(2),COMPLETE) 
      LR   3,15 
* free the resgister save area
      LR     1,13               ADDRESS TO BE RELEASED 
      L     13,4(,13)          ADDRESS OF PRIOR SAVE AREA 
      LA    0,WORKLEN           LENGTH OF STORAGE TO RELEASE 
      STORAGE RELEASE,           RELEASE REENTRANT WORK AREA        X 
            ADDR=(1),            ..ADDRESS IN R1                    X 
            LENGTH=(0)           ..LENGTH IN R0 
      L    14,12(13) 
      LR  15,3 
      LM   0,12,20(13) 
 SR   15,15 
      BR   14

Problems using a 64 bit program

I initially had my C program in 64 bit mode. This caused when I wrote some stub code to use the assembler interface, as the assembler macros are supported in AMODE 31, but my program, and storage areas were 64 bit, and the assembler code had problems.

Various documentation problems

  1. It is not documented that you need to pass the connection token to __server_classify(_SERVER_CLASSIFY_CONNTKN, (char * ) connToken. You get errno2 errno2=0x0330083B.  Home address space does not own the connect token
    from the input parameter list
  2. _SERVER_CLASSIFY_SUBSYSTEM_PARM Set the transaction subsystem parameter. When specified, value contains a NULL-terminated character string of up to 255 characters containing the subsystem parameter being used for the __server_pwu() call.  This applies to _Server_classify_ as well as __server_pwu().   The sample applies for  _SERVER_CLASSIFY_TRANSACTION_CLASS , _SERVER_CLASSIFY_TRANSACTION_NAME, _SERVER_CLASSIFY_USERID.
  3. Getting report and server class back from __server-classify
    1. It is  _SERVER_CLASSIFY_SRVCLSNM not _SERVER_CLASSIFY_SERVCLSNM.
    2. You use _SERVER_CLASSIFY_RPTCLSNM@, _SERVER_CLASSIFY_SERVCLS@, _SERVER_CLASSIFY_SERVCLSNM@ without the @ at the end.   I think this is meant to imply these are pointers.
    3. They did not work for me.  I could not see when the fields are available.   The classify work is only done during the CreateWorkUnit() request.  I request it before this function, and after this function and only got back a string of hex 0s.

Using enclaves in a Java program – capturing elapsed and CPU time used by a Java transaction.

Ive blogged about using enclaves from a C program.  There is an interface from Java which uses this C interface.

Is is relatively easy to use enclave services from a java program, as there are java classes for most of the functions, available from JZOS toolkit.  For example the WorkloadManager class is defined here.

Below is a program I used to get the Work Load Manager(WLM) services working.

import java.util.concurrent.TimeUnit;
import com.ibm.jzos.wlm.ServerClassification;
import com.ibm.jzos.wlm.WorkUnit;
import com.ibm.jzos.wlm.WorkloadManager;
public class main
{
  // run it with /usr/lpp/java/J8.0_64/bin/java main
  public static void main(String[] args) throws Exception  
  {
    WorkloadManager wlmToken = new WorkloadManager("JES", "SM3");
    ServerClassification serverC = wlmToken.createServerClassification();   
    serverC.setTransactionName("TCI3");
    for ( int j = 0;j<1000;j++)
    {
      WorkUnit wU = new WorkUnit(serverC, "MAINCP");
      wU.join();
      float f;
      for (int i = 0;i<1000000;i++) 
      {       
          f=ii2;
         TimeUnit.MICROSECONDS.sleep(20*1000); // 200 milliseconds
      }
      wU.leave();
      wU.delete(); // end the workload
   }
  wlmToken.disconnect();
  }
}

The WLM statements are explained below.

WorkloadManager wlmToken = new WorkloadManager(“JES”, “SM3”);

This connects to the Work Load Manager and returns a connection token.    This needs to be done once per JVM.  You can use any relevant subsystem type, I used JES, and a SubsystemInstance (SI) of SM3. As a test, I created a new  subsystem category in WLM called DOG, and used that.  I defined ServerInstance SI with a value of SM3 within DOG and it worked.

z/OS uses uses subsystems such as JES for jobs submitted into JES2, and STC for Started task.

ServerClassification serverC = m.createServerClassification();

If your application is going to classify the transaction to determine the WLM service class and reporting  class you need this.  You create it, then add the classification criteria to it, see the following section.

Internally this passes the connection token wlmToken to the createServerClassification function.

serverC.setTransactionName(“TCI3”);

This passes information to WLM to determine the best service class and reporting class.  Within Subsystem CAT, Subsystem Instance SM1, I had a sub rule TransactionName (TN) with a value TCI3.  I defined the service class and a reporting class.

WorkUnit wU = new WorkUnit(serverC, “MAINCP”);

This creates the Independent (business transaction) enclave.  I have not see the value MAINCP reported in any reports.   This invokes the C run time function CreateWorkUnit(). The CreateWorkUnit function requires a STCK value of when the work unit started.  The Java code does this for you and passes the STCK through.

wU.join();

This connect the current task to the enclave, and any CPU it uses will be recorded against the enclave. 

wU.leave();

Disconnect the current task from the enclave.  After this call any CPU used by the thread will be recorded against the address space.

wU.delete();

The Independent enclave(Business transaction) has finished. WLM records the elapsed time and resources used for the business transaction.

m.disconnect();

The program disconnects from WLM.

Reporting class output.

I used RMF to print the SMF 72 records for this program.   The Reporting class for this program had

-TRANSACTIONS--  TRANS-TIME HHH.MM.SS.FFFFFF 
AVG        0.29  ACTUAL                36320 
MPL        0.29  EXECUTION             35291 
ENDED       998  QUEUED                 1028 
END/S      8.31  R/S AFFIN                 0 
#SWAPS        0  INELIGIBLE                0 
EXCTD         0  CONVERSION                0 
                 STD DEV               18368 
                                             
----SERVICE----   SERVICE TIME  ---APPL %--- 
IOC           0   CPU   12.543  CP      0.01 
CPU       10747   SRB    0.000  IIPCP   0.01 
MSO           0   RCT    0.000  IIP    10.44 
SRB           0   IIT    0.000  AAPCP   0.00 
TOT       10747   HST    0.000  AAP      N/A

From this we can see that for the interval

  1. 998 transactions ended.  (Another report interval had 2 transactions ending)
  2. the response time was an average of 36.3 milliseconds
  3. a total of 12.543 seconds of CPU was used.
  4. it spent 10.44 % of the time on a ZIIP.
  5. 0.01 % of the time it was executing ZIIP eligible work on a CP as there was no available ZIIP.

Additional functions.

The functions below

  • ContinueWorkUnit – for dependent enclave
  • JoinWorkUnit – as before
  • LeaveWorkUnit – as before
  • DeleteWorkUnit – as before

can be used to record CPU against the dependent (Address space) enclave.  There is no WLM classify for a dependent enclave.

Java threads and WLM

A common application pattern is to use connection pooling.  For example the connect/disconnect to a database or MQ is expensive.  If you have a pool of threads, which connect, and start connected, an application can request a thread and get a thread which has already been connected to the resource manager.

It should be a simple matter of changing the interface from

connectionPool.getConnection()

to

connectionPool.getConnection(WorkUnit wU)
{ connection = connectionPool.getConnection()
 connection.join(wU)
}

and add a connection.leave(wU) to the releaseConnection.

Using enclaves in a C program -capturing elapsed and CPU time used by a transaction.

On z/OS enclaves allow you to set the priority of business transactions within your program, and to record the CPU used by the threads involved in the transaction – even if they are in a different address space.

Many of the WLM functions are assembler macros which require supervisor state. There are C run time functions which do some of the WLM functions. There are also Java methods which invoke the C run time functions.

Not all of the WLM functions are available in the C run time environment. You can set up enclaves, but the application cannot query information about the enclave, such as total CPU used, or the WLM parameters.

Minimal C program

The minimal program is below, and the key WLM functions are explained afterwards.

#include <sys/__wlm.h>
int main(void) { 
  wlmetok_t  enclavetoken; 
  server_classify_t   classify; 
  long rc; 
  // 
  //  Connect to work manager 
  // 
  unsigned int  connectToken = ConnectWorkMgr("JES","SM3");
  classify = __server_classify_create( ); 
  // pass the connection token to the classify
  //  This is needed but not documented 
  rc = __server_classify(classify, 
                 _SERVER_CLASSIFY_CONNTKN, 
                (char *) connectToken 
       ); 
  rc = __server_classify(classify, 
                         _SERVER_CLASSIFY_TRANSACTION_NAME, 
                         "TCI2" 
  for ( int loop=0;loop < 1000 ;loop++) 
  { 
    rc= CreateWorkUnit(&enclavetoken, 
                       classify, 
                       NULL, 
                       "COLINS"   ); 
    rc = JoinWorkUnit(& enclavetoken); 
 
    // do some work to burn some CPU 
    for ( int i = 0;i< 100000 ;i++) 
    { 
      double xx = i/0.5; 
      double yy = xx * xx; 
    } 
    rc = LeaveWorkUnit(&enclavetoken); 
    rc = DeleteWorkUnit(&enclavetoken);   
    rc = DisconnectServer(&connectToken);
}

What are they key functions?

unsigned int connectToken = ConnectWorkMgr(“JES”,”SM3″); 

This creates a connection to WLM, and uses the subsystem JES, and subsystem name of SM3.  Note: On my system it is JES, not JES2.   The WLM dialogs, option 6. Classification Rules list the subsystems available.  You can browse a subsystem type and see the available definitions.  I had

         -------Qualifier--------                 -------Class--------  
Action   Type Name     Start        Service     Report   
 ____  1 SI   SM3      ___          TCI1SC      THRU
 ____  2   TN  TCI3    ___          TCI1SC      TCI3
 ____  2   TN  TCI2    ___          TCI1SC      TCI2

server_classify_t  classify = __server_classify_create( );

CreateWorkUnit, the function used  to create an independent enclave (business transaction), needs to be able to classify the transaction to determine what service class (priority) to give the enclave.  This request sets up the classify control block.

rc = __server_classify(classify, _SERVER_CLASSIFY_CONNTKN, (char *)&connectToken );

The documentation does not tell you to pass the connection token.  If you omit this step the CreateWorkUnit fails with error code errno2=0x0330083B.

The __server_classify expects a char * as the value, so you have to use (char *) & connectionToken.

rc = __server_classify(classify, _SERVER_CLASSIFY_TRANSACTION_NAME, “TCI2” );

This tells WLM about the transaction we want to use.  TRANSACTION_NAME matches up with TN above in the WLM definitions.  This says the business transaction is called TCI2.  There are other criteria such as userid, plan or LU. See here for the list.   The list is incomplete, as it does not support classifiers like Client IP address which is available with the assembler macros.

rc= CreateWorkUnit(&enclavetoken, classify,  NULL, “COLINS” );

This uses the classification parameter defined above, to create the independent enclave, and return the enclave token. 

The documentation for CreateWorkUnit says you need to pass the arrival time,  Address of a doubleword (unsigned long long) field that contains the arrival time of the work request  in STCK format.  I created a small assembler function which just returned a STCK value to my C program.  However I passed NULL and it seemed to produce the correct values  – I think CreateWorkUnit does a STCK for you.

You pass in the name of the function(“COLIN”).  The only place I had seen this is if you use the QueryWorkUnitClassification() to extract the classify information.  For example QueryWorkUnitClassification gave a control block with non empty fields   _ecdtrxn[8]=TCI2 , _ecdsubt[4]=JES , _ecdfcn[8]=COLIN  , _ecdsubn[8]=SM3 . This function does not return the report class or service class.

rc = JoinWorkUnit(& enclavetoken);

This cause any work this TCB does to be recorded against the enclave.

rc =LeaveWorkUnit(&enclavetoken);

This stop work being be recorded against the enclave.  Subsequent work gets charged to the home address space.

rc= DeleteWorkUnit(& enclavetoken);

The business transaction has finished.  Information about the response time and CPU used are stored.

rc =  DisconnectServer(&connectToken);

This disconnects from WLM.

Using a subtask

I had a different thread n the program which did some work for the transaction. Using the enclave token, this work can be recorded against the transaction using

// The enclave token is passed with the request
rc = JoinWorkUnit(&enclaveToken); 
do some work...
rc = LeaveWorkUnit(&enclaveToken);

This would be useful if you are using a connect pool to connect to MQ or DB2 subsystem. You have a pool of threads which have done the expensive connect with a particular userid, and the thread is used to execute the MQ or DB2 subsystem as that userid.

Other function available

Other functions available

Dependent (address space) enclave

The above discussion was for an business transaction, know in the publications as an Independent enclave.   An address space can have a Dependent enclave where the CPU is recorded as “Dependent Enclave” within the address space.  You use the function ContinueWorkUnit(&enclave) to return the enclave token.    You then use JoinWorkUnit and LeaveWorkUnit as before.  I can not see why you might want to use this.

Display the classification

You can use the QueryWorkUnitClassification to return a structure for the classification.

Reset the classification.

If you want to classify a different transaction, you can use server_classify_init() to reset the structure.

Set up a server

You can set up a server where your application puts work onto WLM queues, and other threads can get work.   This is an advanced topic which I have not looked into.

Make your enclave visible across the sysplex

You can use ExportWorkUnit  and ImportWorkUnit to have your enclave be visible in the sysplex.

Query what systems in the sysplex are running in goal mode.

You can use QueryMetrics() to obtain the systems in the sysplex that are in goal mode. This includes  available CPU capacity and resource constraint status. 

What is not available to the C interface

One reason why I was investigating enclaves was to understand the enclave data in the SMF 30 records.  There is an assembler macro IWMEQTME which returns the CPU, ZIIP and ZAPP times, used by the independent enclaves.  Unfortunately this requires supervisor state.    I wrote some assembler code to extract this and display the data.  Another complication is that the IWLM macros are AMODE 31 – so it did not work with my 64 bit C program.

Enclaves in practice. How to capture all the CPU your application uses, and knowing where to look for it.

Z/OS has enclaves to manage work.  

  1. When an enclave is used, a transaction can issue a DB2 request, then DB2 uses some TCBs in the DB2 address spaces on behalf of the original request.  The CPU used used by these DB2 TCBs can be charged back to the original  application. 
  2. When an enclave is not used, the CPU used by the original TCB is charged to its address space, and the DB2 TCBs are charged to the DB2 address space.  You do not get a complete picture of the CPU used by the application.
  3. A transaction can be defined to Work Load Managed(WLM) to set the priority of the transaction, so online transactions have high priority, and background work gets low priority.    With an enclave, the DB2 TCBs have the same priority as the original request.  With no enclave the TCBs have the priority as determined by DB2.

When an application sets up an enclave

  1. Threads can join the enclave, so any CPU the thread uses while in the enclave, is recorded against the enclave.
  2. These threads can be in the same address space, a different address space on the same LPAR, or even in a different LPAR in the SYSPLEX.
  3. Enclaves are closely integrated with Work Load Manager(WLM).   When you create an enclave you can give information about the business transaction, (such as transaction name and  userid).   You classify the application against different factors. 
  4. The classification maps to a service class.   This service class determines the appropriate priority profile.  Any threads using the enclave will get this priority.
  5. WLM reports on the elapsed time of the business transaction, and the CPU used.

What enclave types are there?

In this simple explanation there are two enclave types

  1. Independent enclave – what I think of as Business Transaction, where work can span multiple address spaces.  You pass transaction information (transaction, userid, etc) to WLM so it can set the priority for the enclave. You can get reports on the enclave showing elapsed time, and CPU used.  There can be many independent enclaves in the lifetime of a job.  You can have these enclaves running in parallel within a job.
  2. Dependent enclave or Address space enclave.   I cannot see the reason for this.  This is for tasks running within an address space which are not doing work for an independent enclave.  It could be used for work related to transactions in general.   In the SMF 30 job information records you get information on CPU used in the dependent enclave.  
  3. Work not in an enclave.  Threads by default run with the priority assigned to the address space.  CPU is charged to the address space.

To help me understand enclave reports, I set up two jobs

  1. The parent job,
    1. Creates an independent (transactional) enclave with “subsystem=JES, definition=SM3” and “TRANSACTION NAME=TCI2”.  It displays the enclave token.
    2. Sets up a dependent enclave.
    3. Joins the dependent enclave.
    4. Does some CPU intensive work.
    5. Sleeps for 30 seconds.
    6. Leaves the dependent enclave.
    7. Deletes the dependent enclave.
    8. Deletes the independent enclave.
    9. Ends.
  2. The child, or subtask, job.
    1. This reads the enclave token as a parameter.
    2. Joins the enclave,if the enclave does not exist, use the dependent enclave.
    3. Does some CPU intensive work.
    4. Leaves the enclave.
    5. Ends.

Where is information reported?

  1. Information about a job and the resources used by the job is in SMF 30 records. It reports total CPU used,  CPU used by independent enclaves, CPU used by the dependant enclave.  In JCL output where it reports the CPU etc used by the job step, this comes from the SMF 30 record.
  2. Information about the independent enclave is summarised in an SMF 72 record over a period(typically 15 minutes) and tells you information about the response time distribution, and the CPU used.

I used three scenarios

  1. Run the parent job – but not not the child.  This shows the costs of the just parent – when there is no child running the workload for it.
  2. Run the child but not the parent.   This shows the cost of the expensive workload.
  3. Both parent and child active.   This shows the costs of running the independent enclave  in the child are charged to the parent. 

SMF job resource used report

From the SMF 30 record we get the CPU for the Independent enclave.

Parent CPUChild CPU
Parent, no child
Total              : 0.070
Dependent enclave  : 0.020
Not applicable
Child,no parentNot applicable 
Total CPU         : 2.930
Dependent Enclave : 2.900
Non Enclave       : 0.030
Parent and child 
Total               : 2.860 
Independent enclave : 2.820 
Dependent enclave   : 0.010 
Non enclave         : 0.030
Total            : 0.020
No enclave CPU reported

From the parent and child we can see that the CPU used by the enclave work in the child job has been recorded against the parent’s job under “Independent enclave CPU”.

The SMF type 30 record shows the Parent job had CPU under Independent enclave, Dependent enclave, and a small amount (0.03) which was not enclave.

SMF WLM reports

From the SMF 72 data displayed by RMF (see below for an example) you get the number of transactions and CPU usage for the report class, and service class. I had a report class for each of the parent, and the child job, and for the Independent enclave transaction.

Total CPUElapsed timeEnded
Parent2.81834.971
Child2.6366.761
Business transaction2.81930.041

It is clear there is some double accounting. The CPU used for the child doing enclave processing, is also recorded in the Parent’s cost. The CPU used for the Business transaction is another view of the data from the parent and child address spaces.

For charging based on address spaces you should use the SMF 30 records.

You can use the SMF 72 records for reporting on the transaction costs.

RMF workload reports

When processing the SMF data using RMF you get out workload reports

//POST EXEC PGM=ERBRMFPP 
//MFPINPUT DD DISP=SHR,DSN=smfinput.dataset  
//SYSIN DD * 
SYSRPTS(WLMGL(SCPER,RCLASS,RCPER,SCLASS)) 
/*

For the child address space report class RMF reported

-TRANSACTIONS--  TRANS-TIME HHH.MM.SS.FFFFFF
 AVG        0.05  ACTUAL             6.760380
 MPL        0.05  EXECUTION          6.254239
 ENDED         1  QUEUED               506141
 ...
 ----SERVICE----   SERVICE TIME  ---APPL %---
 IOC        2152   CPU    2.348  CP      2.20
 CPU        2012   SRB    0.085  IIPCP   0.00
 MSO         502   RCT    0.004  IIP     0.00
 SRB          73   IIT    0.197  AAPCP   0.00
 TOT        4739   HST    0.002  AAP      N/A

There was 1 occurrence of the child job, it ran for 6.76 seconds on average, and used a total of 2.636 seconds of CPU (if you add up the service time).

For a more typical job using many short duration independent enclaves the report looked like

-TRANSACTIONS--  TRANS-TIME HHH.MM.SS.FFFFFF 
 AVG        0.11  ACTUAL                13395 
 MPL        0.11  EXECUTION             13395 
 ENDED      1000  QUEUED                    0 
 END/S      8.33  R/S AFFIN                 0 
 SWAPS         0  INELIGIBLE                0
 EXCTD         0  CONVERSION                0 
                  STD DEV                1325 
 ----SERVICE----   SERVICE TIME  
 IOC           0   CPU    1.448   
 CPU        1241   SRB    0.000   
 MSO           0   RCT    0.000  
 SRB           0   IIT    0.000  
 TOT        1241   HST    0.000

This shows 1000 transaction ended in the period and the average transaction response time was 13.395 milliseconds. The total CPU time used was 1.448 seconds, or an average of 1.448 milliseconds of CPU per transaction.

For the service class with a response time definition, you get a response time profile. The data below shows the most most response times were between 15 and 20 ms. The service class was defined with “Average response time of 00:00:00.010”. This drives the range of response times reported. If this data was for a production system you may want to adjust the “Average response time” to 00:00:00.015 to get the peak in the middle of the range.

-----TIME--- -% TRANSACTIONS-    0  10   20   30   40   50 
    HH.MM.SS.FFF CUM TOTAL BUCKET|...|....|....|....|....|
 <= 00.00.00.005       0.0  0.0   >                           
 <= 00.00.00.006       0.0  0.0  >                           
 <= 00.00.00.007       0.0  0.0  >                           
 <= 00.00.00.008       0.0  0.0  >                           
 <= 00.00.00.009       0.0  0.0  >                           
 <= 00.00.00.010       0.0  0.0  >                           
 <= 00.00.00.011       0.3  0.3  >                           
 <= 00.00.00.012      10.6 10.3  >>>>>>                      
 <= 00.00.00.013      24.9 14.3  >>>>>>>>                    
 <= 00.00.00.014      52.3 27.4  >>>>>>>>>>>>>>              
 <= 00.00.00.015      96.7 44.4  >>>>>>>>>>>>>>>>>>>>>>>     
 <= 00.00.00.020     100.0  3.2  >>                          
 <= 00.00.00.040     100.0  0.1  >                           
    00.00.00.040     100.0  0.0  >

Take care.

The field ENDED is the number of transactions that ended in the interval. If you have a measurement that spans an interval, you will get CPU usage in both intervals, but “ENDED” only when the transaction ends. With a large number of transactions this effect is small. With few transactions it could cause divide by zero exceptions!

Understanding OSGI data

My original problem was to find the MQ configuration data used by applications running under Liberty on z/OS. I eventually found I could display all the configuration data from Liberty. This provided me with more data than I wanted to know. However this uses an interface with no authentication on authorization, and it can stop parts of Liberty.

I used the bundles command, collected the information in a file, and wrote a python script to process this file. This put each jar’s information in its own file, so it is readable.

This post describes what I see in it – It is not documented, so I may be wrong.

Within the data are

Within the file are two section

  • Registered services – services this jar provides
  • Services in use – services which this jar uses.

These contain dictionaries of  service properties. For example

{javax.jms.Queue
javax.jms.Destination
}=
{
component.id=416
config.displayId=jmsQueue[default-0]
config.id=com.ibm.ws.jca.adminObject.supertype[extends-0]
osgi.jndi.service.name=jms/stockRequestQueue
properties.0.CCSID=1208
properties.0.baseQueueManagerName=
properties.0.baseQueueName=STOCK_REQUEST
...
service.id=795
}

and

{javax.jms.Queue
javax.jms.Destination
}=
{osgi.jndi.service.name=jms/stockResponseQueue
properties.0.baseQueueManagerName=
properties.0.baseQueueName=STOCK_RESPONSE
...
service.id=796
}

This shows there are multiple object of type javax.jms.Queue/javax.jms.Destination.  One for  a queue called STOCK_REQUEST, the other for STOCK_RESPONSE

The object type com.ibm.ws.jca.service.AdminObjectService has almost the same information as the javax.jms.Queue object.    They have a different service.id, so they are different services.

I used grep to find all instances of STOCK_REQUEST.  There were 3 entries in 2 jar files

  • jar com.ibm.ws.app.manager_1.1.41 cl200620200528-0414:
    • {com.ibm.wsspi.application.lifecycle.ApplicationRecycleComponent,
      com.ibm.wsspi.resource.ResourceFactory,
      com.ibm.ws.jca.service.AdminObjectService
      }=
    • config.displayId=jmsQueue[default-0],
      jndiName=jms/stockRequestQueue,
      properties.0.baseQueueName=STOCK_REQUEST
  • jar com.ibm.ws.jca_1.0.41 cl200620200528-0414:
    • {com.ibm.wsspi.application.lifecycle.ApplicationRecycleComponent
      com.ibm.wsspi.resource.ResourceFactory
      com.ibm.ws.jca.service.AdminObjectService
      }=
    •  config.displayId=jmsQueue[default-0]
      jndiName=jms/stockRequestQueue
      properties.0.baseQueueName=STOCK_REQUEST
      service.id=795
  • jar com.ibm.ws.jca_1.0.41 cl200620200528-0414:
    • {javax.jms.Queue
      javax.jms.Destination
      }=
    •  config.displayId=jmsQueue[default-0]
      osgi.jndi.service.name=jms/stockRequestQueue
      properties.0.baseQueueName=STOCK_REQUEST
      service.id=796

We can see the same data is in multiple places – it should all be similar.

MQ pool size

I was interested in the information about MQ connection pools.  I found this in com.ibm.ws.jca.cm_1.1.41.cl200620200528-0414.

  • agedTimeout=-1
  • component.id=491
  • component.name=com.ibm.ws.jca.connectionManager
  • config.displayId=connectionManager[ConMgr1]
  • config.id=com.ibm.ws.jca.connectionManager[ConMgr1]
  • config.overrides=true
  • config.source=file
  • connectionTimeout=30
  • enableSharingForDirectLookups=true
  • id=ConMgr1
  • maxIdleTime=1800
  • maxPoolSize=5
  • purgePolicy=EntirePool
  • reapTime=180

See here for what they mean.

My python code for taking the output from “bundles” and create individual files

import sys
 fIn = open("/home/colinpaice/Documents/osgi.log", "r")
 for x in range(4): # ignore the top 4 lines
    line = fIn.readline()
    if not line: break
 outputFile = 0
 for x in range(100000): # 
    line = fIn.readline()
    if not line: break
    if line[0:5] == "osgi>": break 
    if line[0] != ' ': # new file 
      if outputFile != 0: 
         outputFile.close()
      line1 = line.split();
      fn = 'output/' + line1[0]
      outputFile = open(fn,'w')
      outputFile.write(line) 
    elif line[0:5] == "  Id=": 
        v = line.split('"')
        outputFile.write(v[0] +"\n" ) 
        if len(v) > 1 :
            outputFile.write("  "+ '"'+v[1] +'"\n')  # services
    elif line[0:5] == '    {':
        p = line[5:-2].split("}={")
        p0 = p[0].split(", ")
        pad = "     {"        
        for ip0 in p0:
            outputFile.write(pad + ip0 +"\n")
            pad = "      "  
        outputFile.write("     }="+"\n")        
        p1 = p[1].split(", ")
        c = {}  # dictionary of the keyword=values
        for ip1 in p1:
             v = ip1.split("=")
             if ( len(v) ==1  ):  # no k=value, just value
                value = value + " " + v[0] # append it to the previous one
                if value.endswith("]"): # if it is the last one 
                                        # update the dict
                   c[kw] = value
             else: 
                 kw = v[0]
                 value = v[1]              
                 c[kw] = value 
        pad = "     {"  # only the first one has  {...          
        for key in sorted(c.keys()): # print alphabetically                
           outputFile.write(pad + key+"="+c[key] +"\n")
           pad = "      "
        outputFile.write("     }" +"\n")              
    else:       
        outputFile.write(line  )

Using OSGI to display information about the Liberty configurations. Useful commands

This post gives some of the commands you can issue to OSGI in Liberty.

I set up access to Liberty OSGi using 

<featureManager>
 <feature>osgiConsole-1.0</feature> 
</featureManager>

osgi.console=10.1.3.10:5471. in bootstrap.properties file, and restarted Liberty.

Once it was active I used

telnet 10.1.3.10 5471 |tee -i osgi.log

to issue commands to OSGI and save the output in the osgi.log file.

A subset of the display commands

help
list the available commands (there are many)
help lb
explain the lb command
disconnect
you have to type out the complete command
lb
list the bundles. This produces a list with

  • ID – a number
  • State – Active
  • Name JMS Connection Factory
lb jca
list bundles with jca in the description.
bundles
list all information about all bundles.
bundles 99
Give more information on the bundle with id 99
headers 99
lists the information from the manifest about the specified bundle id.
jndilist
list the high level jndi tree elements.
jndilist com/ibm
List the element under this tree.
jndilist jms
The JMS definitions

  • cf1: com.ibm.mq.connector.outbound.ConnectionFactoryImpl: com.ibm.mq.connector.outbound.ConnectionFactoryImpl…
  • stockRequestQueue: com.ibm.mq.connector.outbound.MQQueueProxy: com.ibm.mq.connector.outbound.MQQueueProxy…
  • stockResponseQueue: com.ibm.mq.connector.outbound.MQQueueProxy: com.ibm.mq.connector.outbound.MQQueueProxy…
ls
lists the files in the directory on disk.
cat name
lists the contents of the named file from disk – see I said this was a dangerous command.

More than you ever wanted to know about your Liberty configuration – overview

It all started with wanting to look at the MQ configuration within MQWEB and z/OS Connect. I could not find a way of displaying the Liberty configuration information. I could look at the *.xml files, but this did not give me the information which is not in the configuration files. I thought about writing a Liberty feature which printed out the configuration, but then I stumbled across OSGI and the ability to query configuration information from outside of Liberty.

What is OSGI ?

The OSGi specification describes a modular system and a service platform for the Java programming language that implements a complete and dynamic component model, something that does not exist in standalone Java/VM environments. Applications or components, coming in the form of bundles for deployment, can be remotely installed, started, stopped, updated, and uninstalled without requiring a reboot; management of Java packages/classes is specified in great detail. Application life cycle management is implemented via APIs that allow for remote downloading of management policies. The service registry allows bundles to detect the addition of new services, or the removal of services, and adapt accordingly.

Wikipedia

OSGI uses the term “bundle”. It looks like a bundle is a jar file, and the facilities within it. Listing one bundle had com.ibm.ws.ssl_1.3.41.cl200620200528-0414 [72] in it.

  • com.ibm.ws.ssl_1.3.41 is a jar file com.ibm.ws.ssl_1.3.41.jar
  • many files had cl200620200528-0414
  • [72] this was for bundle 72.

How does it work?

Each program package(jar file) contains a manifest.mf file. For example

Manifest-Version: 1.0
Bundle-ManifestVersion: 2
Bundle-Name: MyService bundle
Bundle-SymbolicName: com.sample.myservice
Bundle-Version: 1.0.0
Bundle-Activator: com.sample.myservice.Activator
Import-Package:  org.apache.commons.logging;version="1.0.4"
Export-Package:  com.sample.myservice.api;version="1.0.0"

This gives information on

  • Information about your package (including its version number).
  • The entry point for the bundle.
  • What services it provide to other packages (com.sample.myservice.api).
  • What services it needs from other packages in order for it to work (com.sample.myservice.api).

OSGI sorts out all of these dependencies, provides access to the configuration in the *.xml files and additional configuration data hidden within the packages.

How can I use it to display configuration?

This is not very well documented. I think it is dangerous, as the osgi port allows unauthenticated access to start and stop services. I have not been able to restrict it to authorised users, or control what users have access to.

I found the following….

You need to specify in your Liberty *.xml files

<featureManager> 
   <feature>osgiConsole-1.0</feature> 
</featureManager>

and put

osgi.console=ip:port

in the bootstrap.properties file. For example osgi.console=10.1.3.10:5471 . I found a reference to osgi.console.ssh=ip:port, but this port was not opened during liberty startup.

If you specify osgi.console=5471, this uses the localhost 127.0.0.1, so you can only access it from the local machine. For example TSO TELNET 127.0.0.1 5471. Telnet from TSO is not very usable – it is better to use a telnet session from off z/OS, for example Linux.

From Linux I used: 

telnet 10.1.3.10 5471 |tee -i osgi.log

This allowed me to issue interactive commands, and have the output written to the osgi.log file.

There are a variety of commands to display, start stop etc.

The list bundle command lb gave over 200 entries like

177|Active | 12|com.ibm.ws.messaging.jmsspec.common... 
178|Active | 12|com.ibm.websphere.javaee.jms.2.0 ... 
179|Active | 12|WMQ Resource Adapter ...

The command bundle 179 gave information about the WMQ Resource Adapter above.

I used the bundles command to list all information about all bundles. I then used some python script to process the log file and write information about each bundle to its own file. From the jca file I could see com.ibm.ws.jca.service.ConnectionFactoryService has properties

jndiName=jms/cf1
properties.0.CCSID=819
properties.0.cleanupLevel=SAFE
properties.0.cloneSupport=DISABLED
properties.0.config.referenceType=com.ibm.ws.jca.properties.wmqJms.jmsConnectionFactory
properties.0.connectionfactory-interface=javax.jms.ConnectionFactory
properties.0.failIfQuiesce=true
properties.0.headerCompression=NONE
properties.0.managedconnectionfactory-class=com.ibm.mq.connector.outbound.ManagedConnectionFactoryImpl
properties.0.messageCompression=NONE
properties.0.messageSelection=CLIENT
properties.0.port=1414
properties.0.providerVersion=unspecified
properties.0.pubAckInterval=25
properties.0.queueManager=CSQ9
properties.0.rescanInterval=5000
properties.0.resourceAdapterConfig.id=wmqJms
properties.0.shareConvAllowed=true
properties.0.sparseSubscriptions=false
properties.0.sslResetCount=0
properties.0.statusRefreshInterval=60000
properties.0.subscriptionStore=BROKER
properties.0.targetClientMatching=true
properties.0.transportType=BINDINGS
properties.0.wildcardFormat=TOPIC

and I could see the key properties for the queue manager connection.

For my MQ queue I could see

jndiName=jms/stockRequestQueue
properties.0.CCSID=1208
properties.0.adminobject-class=com.ibm.mq.connector.outbound.MQQueueProxy
properties.0.adminobject-interface=javax.jms.Queue
properties.0.arbitraryProperties=
properties.0.baseQueueManagerName=
properties.0.baseQueueName=STOCK_REQUEST
properties.0.config.referenceType=com.ibm.ws.jca.properties.wmqJms.jmsQueue
properties.0.encoding=NATIVE
properties.0.expiry=APP
properties.0.failIfQuiesce=true
properties.0.persistence=APP
properties.0.priority=APP
properties.0.putAsyncAllowed=DESTINATION
properties.0.readAheadAllowed=DESTINATION
properties.0.readAheadClosePolicy=ALL
properties.0.receiveConversion=CLIENT_MSG
properties.0.resourceAdapterConfig.id=wmqJms
properties.0.targetClient=MQ

and finally I found the connection pool information I was looking for:

connectionTimeout=30
id=ConMgr1
maxIdleTime=1800
maxPoolSize=5
purgePolicy=EntirePool
reapTime=180

Phew – what a lot of work to get this information.

Do performance measurements need to be accurate and precise?

Like many performance questions the answer is “it depends”.

This question is one of the “simple” questions – which most people get wrong. For example you can have a very precise answer which is inaccurate.

Precision

People often give the wrong precision. For example

  • What is the difference between 1 and 1.0?
  • What is the difference between 999 and 1000, and 1000.0?

What is the difference between 1 and 1.0?

With decimal points you can tell the precision from the number of digits after the decimal point.

  • The value 1 is a number between 0.5 and 1.49, with a range of almost 1
  • the number 1.0 is between 0.95 and 1.049. with a range of almost 0.1

What is the difference between 999 and 1000, and 1000.0?

With numbers without a decimal point, the convention is the number of significant non zero digits.

  • 999 is in the range 998.5 to 999.49 a range of almost 1
  • 1000 has one significant digit – so this can represent a number in the range 500 to 1490, a range of almost 1000!
  • 1000.0 represents a number in the range 999.5 to 1000.49 a range of almost 1

Is precision important ?

If you have a set of measurements with values 9.6 9.8,9.9, 10.0, 10.1, 10.2 10.4 the average is 10.0. Saying the average is 10.0 is misleading as it implies the value is between 0.995 and 10.049. The value have a spread – and in this case, saying the value is 10, is better than saying 10.0. You could say 10.0 ± 0.4 to give an even better answer.

Is accuracy important?

Depending on what you want to deliver from your measurements, the CPU figures you collect may not be accurate enough – or they may be good enough not to worry about.

Why are the CPU used figures inaccurate?

There is a gap between what is reported and what is actually used. For a high proportion of measurements the reported CPU is accurate enough. For some measurements you have to factor in this missing usage.

Below is a simplistic view of work being dispatched on an operating system.

  • The dispatcher scans the list of work to find the next work to dispatch
  • Get “Before – clock time”
  • Get “Before – processor CPU time”
  • Invoke the work. It does calculations, starts an I/O request and waits for the response, by returning control to the dispatcher
  • Get “After – processor CPU time”
  • Get “After – clock time”
  • Calculate the difference in clock times and accumulate this in the “work – active time”
  • Calculate the different in the processor CPU times to determine how much CPU time was used for the work, and accumulate this in the “work – CPU time”
  • The dispatcher scans the list of work to find the next work to dispatch
  • etc

The elapsed time figures, and the CPU time used are both accurate, but they do not include the elapsed time or the CPU time the dispatcher took to initiate the work and update the statistics. We can give a better estimate of the true costs.

When running a measurement z/OS can report the CPU used by each engine across the duration of the measurement. We might have

  • Total CPU used across the duration 50 seconds
  • Total CPU used for job A 40 seconds
  • Total CPU used for job B 9.5 seconds
  • Difference in CPU 0.5 seconds

A common way of allocating this “missing CPU” is to allocate it to the jobs depending on the amount of CPU the jobs used in the period. Job A would have 40 + (0.5 *40/50) = 40.4, and job B would have 9.5 + (0.5 * 9.5/50) = 9.6, a total of 50.

Is this completely accurate? – no but it is more accurate than before!

Is this important?

If you want to see the effects of defining an index on an SQL table, a throughput improvement of 100 times or two time, it is good enough to say yes – it improved performance. This does not need to be precise or very accurate.

If you have enhanced your program to remove bottlenecks and can show the CPU per transaction has dropped from 1.2 to 1.1 units then this relative comparison is valid – even if the cost is not entirely accurate.

If you want to give numbers for other people to use, such as the cost of 1000 transactions a second is 1.2 seconds of CPU on this configuration, you need to ensure the figures are accurate.

Do performance measurements need to be accurate and precise?

For many measurements the numbers do not need to be very precise, and the accuracy may be good enough.

Understanding Z/OS Connect SMF 123 subtype 2 record

Introduction to the z/OS Connect SMF records

z/OS Connect can provide two types of SMF record

  1. SMF 120 subtype 11, provided by the base Liberty support. This gives information on the URL used to access Liberty, and the CPU used to perform requests. This is enabled at the Server level – so you can have records for all request, or no requests. There is one SMF record for each web server request.
  2. SMF 123 provides information about API and the service used, and the “pass through” services. It provides elapsed time of the request, and of the the “pass through” requests. It does not provide CPU usage figures. This can be configured to produce records depending on the http host and port used to access z/OS Connect. One SMF record can have data for multiple web server requests. The SMF records are produced when the SMF record is full – or the server is shut down.

The SMF 120-11 and SMF 123 records are produced independently, and there is no correlating field between them. They both have a URI field, and time stamps, so at low volumes it may be possible to correlate the SMF data.

I’ll document the fields which I think are interesting. If you think other fields are useful please let me know and I’ll update this document.

I have written an SMF formatter in C which prints out interesting data, and summarises it.

SMF 123 subtype 2 fields

  • You get the standard date and time the record was produced, and with the LPAR. You can use PGM=IFASMFDP with the following to filter which records are copied
DATE(2020282,2020282)
START(1000)
START(2359)
  • There is server version (3), system(SOW1), SYSPLEX(ADCDPLEX) and job id(STC04774) which are not very interesting
  • Server job name(SM3) is more interesting. I started the server with s baqstrt,parms=’MQTEST’,jobname=sm3
  • The config dir (/var/zosconnect/servers/MQTEST/) is boring – as is server level (open beta)
  • The HTTP code, for example 200 OK, 403 Forbidden. You may want to report requests with errors in a separate file
    1. So you know you have errors and can fix them
    2. Your statistics, such as average response time do not have dirty data in them.
  • An HTTP 1 character flag – this has always been 00 for me. I cannot find it documented.
  • The Client IP address. 10.1.1.1
  • You get userid information.
    • I used a certificate to authenticate. The DN from the certificate is not available. You only get the userid from the RACF mapping of DN to userid. This mapped userid was in the 64 byte field. The 8 byte userid field was empty for me. The lack of certificate DN, and having the userid in the wrong field feels like a couple of buglets. If you use LDAP, I think the long ID is stored in the long field, and the z/OS userid stored in the short field – so inconsistent.
  • You get the URL(URI) used /stockmanager/stock/items/999999. I treat this as a main key for processing and summarising data. You may need to process this value as the partnumber (999999) will be different for each query. You may want to have standards which say the first two elements (/stockmanager/stock) are useful for reporting. The remaining elements should be ignored when summarising records.
  • The start and stop times (2020/10/08 09:18:19.852360 and 2020/10/08 09:18:22.073946) are interesting. You can calculate the duration – which is the difference between them.
  • Request type API, Service, Admin. An Admin request is like using an URL like /zosConnect/services/stockQuery to get information about the stockQuery service.
  • The API name and version – stockmanager 1.0.0
  • The service name and version – stockQuery 1.0.0. You get the version information. If you do an online display of the service the version is not available.
  • Method GET/POST etc
  • The service provider. This is the code which does the real work of connection to CICS, MQ, or passing the request through. IBM MQ for z/OS, restclient-1.0
  • Request id starts at 1 and increments for the life of the server. If you restart the server it will restart from 1. I do not think this is very useful.
  • For “pass through” requests, z/OS Connect confusingly calls the back end service the Statement of Record or (SOR). (MQ is a transport, not a Statement of Record.) The “pass through” service definition is built from a parameter file and zconbt program. The reported data is
    • SOR ID the host and port 10.1.3.10:19443. These are from the <zosconnect_zosConnectServiceRestClientConnection host and port values.
    • SOR Reference restClientServiceY This is from the connectionRef=in the parameter file and the <zosconnect_zosConnectServiceRestClientConnection…> definition
    • SOR Resource zosConnect/apis/through. This is from the uri= in the parameter file.
    • Time of entry and time of return of the SOR service.
    • From the times calculate the difference to get the duration of the remote request.
  • It would be useful to have this “pass through time” for services calling MQ, CICS etc, so we could get a true picture of the time spent processing the requests.
  • The size of the data payload (0) , and the size of the response(94) excluding any headers.
  • A tracking token. The hex 64 byte string is passed to the some called servers. It is passed to some backends (CICS and “pass through”) to be able to correlate the request across systems. It is not passed to MQ. See X-Correlation-ID below for an example. This field is nulls for Admin request. When a request was “passed through” to another z/OS Connect server which processed the request, the tracking token was not reported in the SMF data of the second system. I dont know if the CICS SMF data records this token, but it is of little use for MQ, or for “pass through”.
  • You get 4 request header, and 4 response header fields. They were blank in my measurements, even though headers were passed to the pass through service. Looking a the http traffic, the request coming in had a header “Content-Type:application/json”. The request passed through to the back end included
    • User-Agent: IBM_zOS_Connect_REST_SP/open beta/20200803-0918
    • X-Correlation-ID: BAQ1wsHYAQAYwcTDxNfTQEDi8ObxQEBAQNikjpk+1klAAA==

What can you do with the data?

Do I need to use the SMF data?

From a performance perspective these records do not provide much information, as they are lacking information about CPU usage. From an audit perspective they have some useful information – but the records are missing information which would provide useful audit information. There is an overlap between the information in the SMF 123 records and the …/servers/…logs/http_access.log file which provides, date time, userid, URI, HTTP code.

What do I want to report on?

Decide what elements of the URI you want to report on. For example the URI /stockmanager/stock/items/999999 includes the stock part number, which may be different for each request. You might decide to summarise API usage on just the first two elements /stockmanager/stock/. You may have to treat each API individually to extract the key information.

I’ll use the term key for the interesting part of the URI – for example /stockmanager/stock.

What reports are interesting?

I think typical questions are:

  1. Which is the most popular API key?
  2. Is the usage of an API key increasing?
  3. How many API key requests were unsuccessful? This can show set-up problems, or penetration attempts.
  4. What is the response time profile of the requests? Are you meeting the business response time criteria?
  5. Which sites are sending in most of the requests. You cannot charge back on CPU used, as you do not know the CPU usage. You could do charge back at a fixed cost per API request, with each API having a different rate.
  6. Which userids are sending in most of the requests. You may want to provide more granular certificate to userid mapping to give you more detailed information

Understanding z/OS Connect SMF 120 subtype 11 data

z/OS Connect can provide two types of SMF record

  1. SMF 120 subtype 11, provided by the base Liberty support. This gives information on the URL used to access Liberty, and the CPU used to perform requests. This is enabled at the Server level – so you can have records for all request, or no requests. There is one SMF record for each web server request. Would I use this to report CPU used ? No – see the bottom of this blog.
  2. SMF 123 provides information about API and the service used, and the “pass through” services. It provides elapsed time of the request, and of the the “pass through” requests. It does not provide CPU usage figures. This can be configured to produce records depending on the http host and port used to access z/OS Connect. One SMF record can have data for multiple web server requests. The SMF records are produced when the SMF record is full – or the server is shut down.

The SMF 120-11 and SMF 123 records are produced independently, and there is no correlating field between them. They both have a URI field, and time stamps, so at low volumes it may be possible to correlate the SMF data.

I’ll document the fields which I think are interesting. If you think other fields are useful please let me know and I’ll update this document.

I have written an SMF formatter in C which prints out interesting data, and summarises it.

SMF 120-11

  • You get the standard date and time the record was produced, and with the LPAR. You can use PGM=IFASMFDP with the following to filter which records are copied
DATE(2020282,2020282)
START(1000)
START(2359)
  • There is server version (3), system(SOW1), and job id(STC04774) which are not very interesting
  • Server job name(SM3) is more interesting. I started the server with s baqstrt,parms=’MQTEST’,jobname=sm3
  • The config dir (/var/zosconnect/servers/MQTEST/) is boring – as is code level (20.0.0.6)
  • The start and stop times (2020/10/08 09:18:19.852360 and 2020/10/08 09:18:22.073946) are interesting as is the duration – which is the difference between them.
  • You get userid information.
    • I used a certificate to authenticate. The DN from the certificate is not available. You only get the userid from the RACF mapping of DN to userid. This mapped userid was in the 64 byte field. The 8 byte userid field was empty for me. The lack of certificate DN, and having the userid in the wrong field feels like a couple of buglets.
  • You get the URL used /stockmanager/stock/items/999999 I treat this as a main key for processing and summarising data. If you want to summarise the data, you may want so summarise it just on /stockmanager/stock/. The full URI contains the part number – and so I would expect a large number of parts.
  • You can configure your requests to WLM. For example 
<wlmClassification>
<httpClassification transactionClass="TCI1" method="GET" 
    resource="/zosConnect/services/stockQuery"/>
</wlmClassification>

This produced in the SMF record

WLMTRan :TCI1
WLM Classify type :URI :/zosConnect/services/stockQuery
WLM Classify type :Target Host :10.1.3.10
WLM Classify type :Target Port :19443

This means that the URL, the host, and the port were passed to WLM to classify.

If you get the WLM classification you also get CPU figures when the enclave request ended (was deleted).

  • You get the ports associated with the request.
    • Which port was used on the server – Target Port :9443
    • Where did the request come from? Origin :10.1.1.1 and port :36786
  • The number of bytes in the response Response bytes :791
  • CPU figures for the CPU used on the TCB. See discussion below on the usefulness of this number. You get the CPU figures before the request, and after the request – so you have to calculate the difference yourself! The values come from the timeused facility. You can calculate the delta and get
    • CPU Used Total : 0.967417
    • CPU Used on CP : 0.026327
    • and calculate these to to get CPU Delta. on Z**P : 0.941090 This is the CPU offloaded to ZIIP or ZAAP.
  • If you had the URI classified with WLM, you get Enclave data, see below for a discussion on what the numbers mean.
    • Enclave CPU time : 0.148803
    • Enclave CPU service : 0.000000
    • Enclave ZIIP time : 0.148803
    • Enclave ZIIP Service : 0.000000

What do the CPU numbers mean?

Typically a transaction flow is as follows

  1. A listening thread listens on the HTTP(s) host and port.
  2. When a request arrives, it passes the request to a worker thread, and goes back to listening
    1. The worker thread may do some work and send the response back
    2. The worker thread may need to call another thread to do some work. For example to issue an MQ request,
      1. the MQ code looks for a thread in a pool for a matching queue manager and userid. If it find one it uses it the thread and issues the MQ request.
      2. If it does not find a matching thing thread it may allocate a new thread, and issue an MQCONN to connect to MQ. These are both expensive operations, which is why having a pool of threads with queue manager and userid is a good way of saving CPU
      3. The work is done
      4. The thread is put back into the MQ pool, and the application returns to the worker thread
      5. The worker thread sends the response back to the originator

A thread can ask the operating system, how much CPU time it(the thread) has used. What usually happens is

  1. the thread requests how much CPU it has used
  2. the thread does some work
  3. the thread requests how much CPU it has used,
  4. the thread calculates the difference between the two CPU values and reports this delta.

I the SMF 120 record records the CPU from just the worker thread – and no other thread.

Enclaves

When there are more than one thread involved it gets more complex, as you could have a CICS transaction issuing an MQ request, then a DB2 request, and then an IMS request. You can set up z/OS WorkLoad Manager(WLM) to say “these CICS transactions in this CICS region are high priority”.

With some subsystems you can pass a WLM token into a request. The thread being invoked call tell WLM that the thread is now working on behalf of this token. The thread does some work, and tells WLM that it has finished doing the work. WLM can manage the priority of the threads to achieve the best throughput, for example making the thread high or low priority. WLM can manage a thread doing work in multiple LPARs across a sysplex!

WLM records the CPU used by the thread while performing the work, accumulates and reports this.

This use of multiple threads for a business transaction across one or more address spaces is known as an enclave.

What happens with enclaves?

  1. A request arrives at the listener thread.
  2. The Liberty looks up the URI in the <wlmClassification httpClassification…. It compare the server’s host, server’s port, the URI resource /stockmanager… method ( GET) and finds the best match for the transactionClass.
    1. If there is a transactionClass,
      1. the server calls WLM with the Subsystem type of CB, the specified collectionName, and the transactionClass.
      2. WLM looks for these parameters and if WLM has a matching definition then WLM will manage the priority of the work,
      3. WLM returns a WLM token.
      4. This WLM token is passed to threads which are set up for enclaves.
    2. If there is no transaction class specified in Liberty, or WLM does not have the subsystem, collectionname, transactionClass then there is no token or a null WLM token
    3. The work continue as before.
    4. If another thread is used then pass the WLM token. If the code is set up for WLM token then report “work started”, when it has finished report “work ended”

What happens if the request is not known to WLM.

The worker thread calculates the CPU used for just its work, and reports this. The CPU used by any other thread is not report. The figures reported are the CPUTotal timeused values. You have to calculate the difference yourself

What happens if the request is known to WLM.

You get the timeused CPU for the worker thread – as with the case where the request is not known to WLM.

From RMF (or other products) you get out reports for an interval with

  1. The number of requests in the interval
  2. The rate of requests in the interval
  3. The amount of time on a CP engine in seconds
  4. The amount of time on a ZIIP engine is seconds
  5. The amount of time on a ZAAP in seconds.
  6. Over the interval, what percentage of time was CP on CP engines, zAAP on zAAP engines, zAAP on CP engines, zIIP on zIIP engines.

From the SMF 120 records you get

Enclave CPU time
Enclave ZAAP time
Enclave ZIIP time

Example Enclave figures.

For 100 API requests, the figures as reported by SMF 120-11, and I averaged the values.

  1. Average CPU(1) 0.023
  2. Average CPU(2) 0.0008
  3. Enclave CPU 0.029
  4. Enclave ZAAP 0
  5. Enclave ZIIP 0.028

The figures reported by RMF per request

  1. CPU 0.031
  2. ZIIP 0.039
  3. ZAAP 0.000
  4. Total 0.070 seconds of CPU per transaction

These figures tie up – the Enclave CPU, ZIIP, and ZAAP are similar.

The CPU used by the server address space was

  1. CPU 30.1 seconds
  2. ZIIP 28.7 seconds
  3. ZAPP 0 seconds.
  4. Total 58.8.

Each request took 0.070, and there were 100 requests – so reported 7 second of CPU.

The difference(51) seconds is not reported in the transaction costs. It looks like the “timeused” value is less than 1% of the CPU value, and the enclave figures are under 2% of the grand total.

Looking at the trace in a dump, I can see many hot TCBs using much more CPU that is reported by WLM and RMF. I expect that many TCBs used in a request, but they do not have the enclave support in them. Overall – pretty useless for charge back and understanding the cost per transaction.