If the facts do not match your view – do not ignore the facts.

It is easy to ignore facts if you do not like them, sometimes this can have major consequences.    I recently heard two similar experiences of this.

We were driving along in dense fog trying to visit someone who lived out in the country.  We had been there in the daylight and thought we knew the way.  The conversation went a bit like the following

  • It is along here on the right somewhere – there should be a big gate
  • There’s a gate.  Oh they must have painted it white since last time we were here
  • The track is a bit rough, I thought it was better than this.
  • Ah here’s another gate.   They must have installed it since we were here last.
  • Round the corner and here we – oh where’s the house gone?

Of course we we had taken the wrong side road.  We had noticed that the facts didn’t match our picture and so we changed the facts. Instead of thinking “that gate is the wrong colour” we thought “they must have painted the gate”.  Instead of “we were not expecting that gate” we thought “they must have installed a new gate”.  It was “interesting” backing the car up the track to the main road in the dark.

I was trying to install a product and having problems.  I had already experienced a few problems where the messages were a bit vague.  I had another message which implied I had mis-specified something.  I checked the 6 characters in a file and thought “The data is correct, the message must be wrong, I’ll ignore it”.   I gave up for the day.  Next day I looked at the problem, and found I had been editing the wrong file.  The message was correct and I had wasted 3 hours.

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.

Is “how many fruit do I get per kilogram” a better metric than MIPS?

I was reading an article about the cost of a transaction and how many MIPS (Millions of Instructions Per Second) it used.  This annoyed me as it is wrong at so many levels.

  1. MIPS depends on how long the transaction ran for. Millions of Instructions used (MINU?) would be a better metric
  2. Instructions are different sizes, and the CPU used by an instruction varies depending on many things.
  3. If I was to talk about “How many fruit I can get per kilogram”, you would rightly say that  apples weigh more than grapes. You get different sorts of apples of different sizes, so you might get 12 cox’s apples per kilogram, but 10 Granny Smiths.  I’m sure you are thinking number of fruit per kilogram is a stupid measurement.   I agree – but this is the same discussion as MIPS.
  1. Obvious statement : The duration of an instruction depends on the instruction.   Instructions that access memory are often slower than instructions that just access registers.
  2. Not so obvious statement.    The same instruction (for example load register) can have different durations
  3. Not at all obvious:  The same physical instruction – for example in a loop – can have different durations
  4. Not at all obvious: A register to register instruction can be slower than a memory to register instruction.

Let’s take the covers off and get our hands under the covers.

  1. The z machines have the processors in “books”; in reality these are big cards.
  2. There can be multiple chips per book.
  3. There is memory in each book
  4. The length of the wire between two books might be 1 metre.
  5. Inside each chip are the processors.
  6. Each processor has cache for instructions, and cache for data.  This memory is within a few millimetres of the processors
  7. There is cache on the chip independent of the processors, it is within 1 cm of the processors.

Just a few more observations

  1. The Load instruction – is not an instruction – it is actually a microprogram using the underlying chip technology
  2. Some instructions were written in millicode – and then a release or so later were written in microcode.   The MVCL instruction is a good example of this.  It can move Megabytes of data in one instruction.

For the instruction L R4,20(R3).   This says load register 4 with the contents of  20 bytes off what register 3 point to.   I’ll look at how long this instruction takes to execute.

Put this load instruction in a little loop and go round the loop twice.

JUMPHERE SR    R1,R1    clear register 1
LOOP   LTR   R1,R1    test register 1
     BNZ   PAST    If it is non zero go to PAST
      L     R4,20(R3) Load register 4 from storage
      AFI   R1,1 Add 1 to register 1
    B LOOP 
PAST   DS   0H

What are the differences in the duration of the L R4,20(R3) instruction, first time and second time around the loop?

  1. If the application issued goto/jump to JUMPHERE, this block of code may not be in the processor’s instruction cache.  It may be in the chips’ cache.  If so – there will be a delay while the block of instructions are loaded into the proccessor’s cache.
  2. When the Load instruction is executed – both times it is in the processor’s cache, so there is no time difference.
  3. The first time, the instruction has to be parsed into  “Load”, “register 4″,”20 bytes from what register 3 points to”.   The second time, it can reuse this information – so it will be quicker.
  4. “Go and access the storage from what register 3 points to”.  You have convert register 3 to a real page. There are lots of calculations to Translate a virtual address to its “real address”.  For example each address space has an address 2000. It needs to use the look up tables for that address space to map 2000 to the real page.  Once it has calculated the “real” page – it keeps it in a Translation Lookaside Buffer (TLB). (LPAR#.ASID#.2000 -> 39945000).   The second time, this information is already in the TLB.
  5.  The “real” storage may be in the same chip as you are executing, or it may be on a different chip.  It could be on a chip on a different book.  There is about 1 meter of cabling between where the real storage is, and the instruction requesting it.  The speed of light determines how long it will take to access the data – 0.000001 of a meter or 1 meter.    The second time the load instruction is executed, it is already in the processors’ cache.

In this contrived example I would expect the second load to be much faster than the first load – perhaps 1000 times faster.  Apples and grapes…

The z Hardware can report where time is being spent, and allows IBM to tune the programs to reduced delays.

There was one z/OS product which had a pointer to the next free buffer in the trace table.   The code would get the buffer and update the pointer to the next free buffer.  This worked fine when there was only one thread running.  On a big box with 16 engines every processor was trying to grab and update this pointer.   Sometime it had to grab it from a different book, sometimes it had to grab it from another processor in the same chip.  From the hardware instrumentation it was obvious that a lot of time was spent waiting for this “latch”.   By giving each processor its own trace table – totally removed this contention, and the trace buffers were close to the processors – so a win win situation.

I said that a register to register could be slower than a memory to register – how?

The processors can process multiple instructions in parallel.  While it is waiting for some storage to arrive from 1 metre away, it can be decoding the next 10 instructions.  There is what I like to think of as a “commit” in all processing, and the commit processing has to be done in strict order. 

So if we had

    L  R1,20(R3)      
SR  R4,R4
  SR  R6,R6 

The two Subtract Registers may be very quick and almost completed before the Load instruction has finished. They cannot “commit” until the Load has committed.   Picture trying to debug this if the instructions had been executed out of order!

Now consider

 L    R1,20(R3)      
LTR R1,R1 Test if register 1 is zero
LH R6,100(R7)

The Load and Test Register(LTR) is using register 1 – which is being used by the Load instruction.  The LTR has to wait until  the previous Load has “Committed” before it can access the register.  In effect the LTR is having to wait until the Load’s data is retrieved from 1 metre away – so very slow.

The data for the Load Halfword R6,100(R7) may be in the data cache – and so be very fast.   We therefore have the situation that the register, register instruction LTR takes a “long” time, and the memory register Load Halfword – is blazingly fast.

Things ain’t what they used to be.

I remember when IBM changed from Silicon processors to CMOS.  We went from a machine with one engine delivering 50 MIPS to a machine with 5 processors each delivering 11 MIPS.   The bean counters said “be happy – you have more MIPS”.    The transactions were now 5 times slower, but you could now have 5 transactions  running in parallel, and so overall throughput was very similar.  I wonder if these bean counters are the ones who think that if the average family has 2.5 children, there must be a lot of half brothers and half sisters.

For those people who have to compare one box with another box, or want to know how much CPU is needed for a transaction use CPU seconds.  There are tables giving a benchmark of the same workload on different machines, and so you can make comparisons between the machines.

What’s the difference between RACDCERT MAP and RACMAP?

I was trying to set up digital certificate authentication into RACF and was having problems.  I had used a command

RACDCERT MAP ID(ADCDC ) - 
   SDNFILTER('CN=colinpaicesECp256r1.O=cpwebuser.C=GB') - 
   WITHLABEL('colinpaicesECp256r2') 

but it was hard to find out why I could not connect.  I started looking into this and got confused because the MQWEB liberty trace talked about userid in realms, but I did not have a realm.

I took a couple of days to write a program to use the RACF callable service to query the userid given a DN, but it kept reporting the certificate was not found.

Eventually I found that RACF has two ways of mapping a DN string to a userid

  • RACDCERT MAP ID(ADCDC ) SDNFILTER(‘CN=colinpaicesECp256r1.O=cpwebuser.C=GB’) WITHLABEL(‘colinpaicesECp256r2’)
  • RACMAP MAP ID(ADCDC ) USERDIDFILTER( NAME(‘CN=colinpaicesECp256r1.O=cpwebuser.C=GB’)) REGISTRY(NAME(‘ADCDPL’))
    WITHLABEL(‘COLIN5’)

RACDCERT MAP

This is used so that when someone logs on using a certificate, the certificate DN is looked up in the RACDCERT MAP, and if found, the matching userid is returned.

This command is not very usable.

  • You can map a DN string to  a user.
  • You can list the DN string associated with a userid
  • You cannot query to see if a DN string exists, and which userid it is mapped to
  • If you try to add it, and it already exists, it just reports that  it exists, and does not tell you which userid it is mapped to. So you cannot easily delete it
  • For an application to query the userid, you need to use the initACEE interface which is complex and requires  your code to run authorised.

If the system is unable to map a certificate to a userid you get a message…

ICH408I USER(START1 ) GROUP(SYS1 ) NAME(####################)
DIGITAL CERTIFICATE IS NOT DEFINED. CERTIFICATE SERIAL NUMBER(0162)
SUBJECT(CN=colinpaicesECp256r1.O=cpwebuser.C=GB) ISSUER(CN=SSCA8.OU=CA.O=SSS.C=GB).

RACMAP MAP

This has been designed for enterprise identity propagation.  You can have userid information in different realms, for example in RACF or in one oe more LDAPs.

  • You can map a DN string to  a userid
  • You can list the DN strings associated with a userid
  • You can query a DN string and get the associated userid
  • You can use the r_usermap (IRRSIM00) callable service to map a DN string to a user.   You need access to some RACF profiles.

They are not interchangable

You cannot define a mapping using RACDCERT MAP and use the r_usermap interface, or the other way around.

How to use RACF callable services from C

Trying to use the RACF callable services was like trying to find treasure with an incomplete map.  I found it hard to create a C program to query a repository for ID information.   This post is mainly about using the RACF callable services.

I was trying to understand the mapping of a digital certificate to a z/OS userid, but with little success.  I found a RACF callable service which appeared to do what I wanted – but it did not give the answers – because,  like many treasure maps, I was looking in the wrong place.

RACF has two repositories for mapping identities to userid.

  • RACDCERT MAP which was the original way of mapping names.  As far as I can tell, the only way of getting the certificate to userid mapping programmatically, is to use the certificate to logon, and then find the userid!   This is used by Liberty Web Server.
  • RACMAP MAP which is part of Enterprise wide identification.   It maps identity strings, as you may get from LDAP,  to a userid. You can use the r_usermap callable service to get this information.

It took me some time to realise that these are different entities, and explains why there was no documentation on getting Liberty to work with RACMAP to handle certificates.  I found out RACMAP does not map certificate, after I got my program working.

The r_usermap service documentation is accurate – but incomplete, so I’ll document some of the things I learned in getting this to work.

The callable service to extract the userid  from identity information is documented here.  In essence you call the assembler routine r_usermap or IRRSIM00.

Building it

When you compile it, you need to provide the stub IRRSIM00 at bind time.  I used JCL

//S1 JCLLIB ORDER=CBC.SCCNPRC 
//DOCLG EXEC PROC=EDCCBG,INFILE='ADCD.C.SOURCE(C)', 
// CPARM='OPTF(DD:COPTS)' 
//COMPILE.COPTS DD * 
LIST,SSCOMM,SOURCE,LANGLVL(EXTENDED) 
TEST 
/* 
//COMPILE.SYSIN DD * 
  Source program goes here
//BIND.CSS DD DISP=SHR,DSN=SYS1.CSSLIB 
//BIND.SYSIN DD * 
INCLUDE CSS(IRRSIM00) 
/*

You need code like

#pragma linkage(IRRSIM00, OS) 
int main(){...
...
char * workarea ; 
workarea = (char *) malloc(1024)   ; 
long ALET1= 0; 
...
long SAF_RC,RACF_RC,RACF_RS; 
...
rc=  IRRSIM00(workarea, // WORKAREA 
             &ALET1  , // ALET 
             &SAF_RC, // SAF RC 
...

Some fields are in UTF-8.

To covert from EBCDIC to UTF-8, (it looks like ASCII )  I used

cd = iconv_open("UTF-8", "IBM-1047"); 
...
struct 
{ 
  short length ; // length of string following or 0 if ommitted 
  char value[248]; 
} DN; 
char * sDN= "CN=COLIN.C=GB"; 
size_t llinput= strlen(sDN); 
size_t lloutput= sizeof(DN.value); 
char * pOutValue= &DN.value[0]; 
rc = iconv(cd,        // from  iconv_open
           &sDN,      // input string
           &llinput,  // length of input 
           &pOutValue,// output 
           &lloutput);// length of output 
if (rc == -1) // problem
{ 
  perror("iconv"); 
  exit(99); 
} 
DN.length  =sizeof(DN.value) - ll2; // calculate true length

What access do I need?

You need

permit IRR.RUSERMAP class(FACILITY) access(READ) ID(....)
SETROPTS RACLIST(facility ) REFRESH

Output

Once I had got the program to compile and bind, and got the authorisation it worked great.

It only works with the RACFMAP …  command, not the RACFDCERT command, obvious now I know!  To get the information from the RACDCERT MAP, you need to use initACEE.

Why is MQWEB not accepting my certificate ? An end to head banging

I found there were many reasons why a browser’s or curl application’s digital certificate did not work with MQWEB, from an option missing, to unsupported handshake option.  Often there the messages were the vague “A problem has occurred”.

I tried to cause as many problems as possible, and blogged what you get, and the resolution; but event then I found there were even more ways of it failing.

 

I’ve written some java programs called checkTLS which act as a client or a server.

  • You can use your web browser into the server application and see information about what is being used, and if it can detect any problems (such as expired CA)
  • You can extract your certificates from the browser, and then talk to MQWEB, and see what happens in the handshake

This is alpha code.   I would be interested in any comments

  • Is this useful?
  • Does it work for you?
  • Is it too verbose?

I can’t get my web browser talking to mqweb on z/OS

I was trying to get my Linux machine talking to MQWeb browser on z/OS, but I was getting

curl .. Failed to connect to 10.1.1.2 port 9443: Connection refused.

For this to work you have to edit the mqwebuser.xml file and uncomment

<variable name="httpHost" value="*"/> 
<!-- 
-->

It then worked a treat.  Like most things it is easy when you know how to fix it.

Using firefox browser then gave me

Web sites prove their identity via certificates. Firefox does not trust this site because it uses a certificate that is not valid for 10.1.1.2:9443.
Error code: MOZILLA_PKIX_ERROR_SELF_SIGNED_CERT

Which proves I was accessing the site. That is a certificate set up issue, and a whole different ball game.