One Minute MVS – tuning stack and heap pools

These days many applications use a stack and heap to manage storage used by an application. For C and Cobol programs on z/OS these use the C run time facilities. As Java uses the C run time facilities, it also uses the stack and heap.

If the stack and heap are not configured appropriately it can lead to an increase in CPU. With the introduction of 64 bit storage, tuning the heap pools and stack is no longer critical. You used to have to carefully manage the stack and heap pool sizes so you didn’t run out of storage.

The 5 second information on what to check, is the number of segments freed for the stack and heap should be zero. If the value is large then a lot of CPU is being used to manage the storage.

The topics are

Kinder garden background to stack.

When a C (main) program starts, it needs storage for the variables uses in the program. For example

int i;
for (ii=0;ii<3:ii++)
{}

char * p = malloc(1024);

The variables ii and p are variables within the function, and will be on the functions stack. p is a pointer.

The block of storage from the malloc(1024) will be obtained from the heap, and its address stored in p.

When the main program calls a function the function needs storage for the variables it uses. This can be done in several ways

  1. Each function uses a z/OS GETMAIN request on entry, to allocate storage, and a z/OS FREEMAIN request on exit. These storage requests are expensive.
  2. The main program has a block of storage which functions can use. For the main program uses bytes 0 to 1500 of this block, and the first function needs 500 bytes, so uses bytes 1501 to 2000. If this function calls another function, the lower level function uses storage from 2001 on wards. This is what usually happens, it is very efficient, and is known as a “stack”.

Intermediate level for stack

It starts to get interesting when initial block of storage allocated in the main program is not big enough.

There are several approaches to take when this occurs

  1. Each function does a storage GETMAIN on entry, and FREEMAIN on exit. This is expensive.
  2. Allocate another big block of storage, so successive functions now use this block, just like in the kinder garden case. When functions return to the one that caused a new block to be allocated,
    1. this new block is freed. This is not as expensive as the previous case.
    2. this block is retained, and stored for future requests. This is the cheapest case. However a large block has been allocated, and may never be used again.

How big a block should it allocate?

When using a stack, the size of the block to allocate is the larger of the user specified size, and the size required for the function. If the specified secondary size was 16KB, and a function needs 20KB of storage, then it will allocate at least 20KB.

How do I get the statistics?

For your C programs you can specify options in the #PRAGMA statement or, the easier way, is to specify it through JCL. You specify C run time options through //CEEOPTS … For example

//CEEOPTS DD *
STACK(2K,12K,ANYWHERE,FREE,2K,2K)
RPTSTG(ON)

Where

  • STACK(…) is the size of the stack
  • RPTSTG(ON) says collect and display statistics.

There is a small overhead in collecting the data.

The output is like:

STACK statistics:                                                
  Initial size:                                2048     
  Increment size:                             12288     
  Maximum used by all concurrent threads:  16218808     
  Largest used by any thread:              16218808     
  Number of segments allocated:                2004     
  Number of segments freed:                    2002     

Interpreting the stack statistics

From the above data

  • This shows the initial stack size was 2KB and an increment of 12KB.
  • The stack was extended 2004 times.
  • Because the statement had STACK(2K,12K,ANYWHERE,FREE,2K,2K), when the secondary extension became free it was FREEMAINed back to z/OS.

When KEEP was used instead of FREE, the storage was not returned back to z/OS.

The statistics looked like

STACK statistics:                                                
  Initial size:                               2048     
  Increment size:                            12288     
  Maximum used by all concurrent thread:  16218808     
  Largest used by any thread:             16218808     
  Number of segments allocated:               1003     
  Number of segments freed:                      0     

What to check for and what to set

For most systems, the key setting is KEEP, so that freed blocks are not released. You can see this a) from the definition b) Number of segments freed is 0.

If a request to allocate a new segment fails, then the C run time can try releasing segments that are not in use. If this happens the “”segments freed” will be incremented.

Check that the “segments freed” is zero, and if not, investigate why not.

When a program is running for a long time, a small number of “segments allocated” is not a problem.

Make the initial size larger, closer to the “Largest used of any thread” may improve the storage utilisation. With smaller segments there is likely to be unused space, which was too small for a functions request, causing the next segment to be used. So a better definition would be

STACK(16M,12K,ANYWHERE,KEEP,2K,2K)

Which gave

STACK statistics:                                                          
  Initial size:                                     16777216               
  Increment size:                                      12288               
  Maximum used by all concurrent threads:           16193752               
  Largest used by any thread:                       16193752               
  Number of segments allocated:                            1               
  Number of segments freed:                                0               

Which shows that just one segment was allocated.


Kinder garden background to heap

When there is a malloc() request in C, or a new … in Java, the storage may exist outside of the function. The storage is obtained from the heap.

The heap has blocks of storage which can be reused. The blocks may all be of the same size, or or different sizes. It uses CPU time to scan free blocks looking for the best one to reuse. With more blocks it can use increasing amounts of CPU.

There are heap pools which avoids the costs of searching for the “right” block. It uses a pools of blocks. For example:

  1. there is a heap pool with 1KB fixed size blocks
  2. there is another heap pool with 16KB blocks
  3. there is another heap pool with 256 KB blocks.

If there is a malloc request for 600 bytes, a block will be taken from the 1KB heap pool.

If there is a malloc request for 32KB, a block would be used from the 256KB pool.

If there is a malloc request for 512KB, it will issue a GETMAIN request.

Intermediate level for heap

If there is a request for a block of heap storage, and there is no free storage, a large segment of storage can be obtained, and divided up into blocks for the stack. If the heap has 1KB blocks, and a request for another block fails, it may issue a GETMAIN request for 100 * 1KB and then add 100 blocks of 1KB to the heap. As storage is freed, the blocks are added to the free list in the heap pool.

There is the same logic as for the stack, about returning storage.

  1. If KEEP is specified, then any storage that is released, stays in the thread pool. This is the cheapest solution.
  2. If FREE is specified, then when all the blocks in an additional segment have been freed, then free the segment back to the z/OS. This is more expensive than KEEP, as you may get frequent GETMAIN and FREEMAIN requests.

How many heap pools do I need and of what size blocks?

There is usually a range of block sizes used in a heap. The C run time supports up to 12 cell sizes. Using a Liberty Web server, there was a range of storage requests, from under 8 bytes to 64KB.

With most requests there will frequently be space wasted. If you want a block which is 16 bytes long, but the pool with the smallest block size is 1KB – most of the storage is wasted.
The C run time gives you suggestions on the configuration of the heap pools, the initial size of the pool and the size of the blocks in the pool.

Defining a heap pool

How to define a heap pool is defined here.

You specify the size of overall size of storage in the heap using the HEAP statement. For example for a 16MB total heap size.

HEAP(16M,32768,ANYWHERE,FREE,8192,4096)

You then specify the pool sizes


HEAPPOOL(ON,32,1,64,2,128,4,256,1,1024,7,4096,1,0)

The figures in bold are the size of the blocks in the pool.

  • 32,1 says maximum size of blocks in the pool is 32 bytes, allocate 1% of the heap size to this pool
  • 64,2 says maximum size of blocks in the pool is 64 bytes, allocate 2% of the heap size to this pool
  • 128,4 says maximum size of blocks in the pool is 128 bytes, allocate 4% of the heap size to this pool
  • 256,1 says maximum size of blocks in the pool is 256 bytes, allocate 1% of the heap size to this pool
  • 1024,7 says maximum size of blocks in the pool is 1024 bytes, allocate 7% of the heap size to this pool
  • 4096,1 says maximum size of blocks in the pool is 4096 bytes, allocate 1% of the heap size to this pool
  • 0 says end of definition.

Note, the percentages do not have to add up to 100%.

For example, with the CEEOPTS

HEAP(16M,32768,ANYWHERE,FREE,8192,4096)
HEAPPOOLS(ON,32,50,64,1,128,1,256,1,1024,7,4096,1,0)

After running my application, the data in //SYSOUT is


HEAPPOOLS Summary:                                                         
  Specified Element   Extent   Cells Per  Extents    Maximum      Cells In 
  Cell Size Size      Percent  Extent     Allocated  Cells Used   Use      
  ------------------------------------------------------------------------ 
       32        40    50      209715           0           0           0 
       64        72      1        2330           1        1002           2 
      128       136      1        1233           0           0           0 
      256       264      1         635           0           0           0 
     1024      1032      7        1137           1           2           0 
     4096      4104      1          40           1           1           1 
  ------------------------------------------------------------------------ 

For the cell size of 32, 50% of the pool was allocated to it,

Each block has a header, and the total size of the 32 byte block is 40 bytes. The number of 40 bytes units in 50% of 16 MB is 8MB/40 = 209715, so these figures match up.

(Note with 64 bit heap pools, you just specify the absolute number you want – not a percentage of anything).

Within the program there was a loop doing malloc(50). This uses cell pool with size 64 bytes. 1002 blocks(cells) were used.

The output also has

Suggested Percentages for current Cell Sizes:
HEAPP(ON,32,1,64,1,128,1,256,1,1024,1,4096,1,0)


Suggested Cell Sizes:
HEAPP(ON,56,,280,,848,,2080,,4096,,0)

I found this confusing and not well documented. It is another of the topics that once you understand it it make sense.

Suggested Percentages for current Cell Sizes

The first “suggested… ” values are the suggestions for the size of the pools if you do not change the size of the cells.

I had specified 50% for the 32 byte cell pool. As this cell pool was not used ( 0 allocated cells) then it suggests making this as 1%, so the suggestion is HEAPP(ON,32,1

You could cut and paste this into you //CEEOPTS statement.

Suggested Cell Sizes

The C run times has a profile of all the sizes of blocks used, and has suggested some better cell sizes. For example as I had no requests for storage less than 32 bytes, making it bigger makes sense. For optimum storage usage, it suggests of using sizes of 56, 280,848,2080,4096 bytes.

Note it does not give suggested number of blocks. I think this is poor design. Because it knows the profile it could have an attempt at specifying the numbers.

If you want to try this definition, you need to add some values such as

HEAPP(ON,56,1,280,1,848,1,2080,1,4096,1,0)

Then rerun your program, and see what percentage figures it recommends, update the figures, and test again. Not the easiest way of working.

What to check for and what to set

There can be two heap pools. One for 64 bit storage ( HEAPPOOL64) the other for 31 bit storage (HEAPPOOL).

The default configuration should be “KEEP”, so any storage obtained is kept and not freed. This saves the cost of expensive GETMAINS and FREEMAINs.

If the address space is constrained for storage, the C run time can go round each heap pool and free up segments which are in use.

The value “Number of segments freed” for each heap should be 0. If not, find out why (has the pool been specified incorrectly, or was there a storage shortage).

You can specify how big each pool is

  • for HEAPPOOL the HEAP size, and the percentage to be allocated to each pool – so two numbers to change
  • for HEAPPOOL64 you specify the size of each pool directly.

The sizes you specify are not that sensitive, as the pools will grow to meet the demand. Allocating one large block is cheaper that allocating 50 smaller blocks – but for a server, this different can be ignored.

With a 4MB heap specified

HEAP(4M,32768,ANYWHERE,FREE,8192,4096)
HEAPP(ON,56,1,280,1,848,1,2080,1,4096,1,0)

the heap report was

 HEAPPOOLS Summary: 
   Specified Element   Extent   Cells Per  Extents    Maximum      Cells In 
   Cell Size Size      Percent  Extent     Allocated  Cells Used   Use 
   ------------------------------------------------------------------------ 
        56        64      1         655           2        1002           2 
       280       288      1         145           1           1           0 
       848       856      1          48           1           1           0 
      2080      2088      1          20           1           1           1 
      4096      4104      1          10           0           0           0 
   ------------------------------------------------------------------------ 
   Suggested Percentages for current Cell Sizes: 
     HEAPP(ON,56,2,280,1,848,1,2080,1,4096,1,0) 

With a small(16KB) heap specified

HEAP(16K,32768,ANYWHERE,FREE,8192,4096)
HEAPP(ON,56,1,280,1,848,1,2080,1,4096,1,0)

The output was

HEAPPOOLS Summary:                                                            
  Specified Element   Extent   Cells Per  Extents    Maximum      Cells In    
  Cell Size Size      Percent  Extent     Allocated  Cells Used   Use         
  ------------------------------------------------------------------------    
       56        64      1           4         251        1002           2    
      280       288      1           4           1           1           0    
      848       856      1           4           1           1           0    
     2080      2088      1           4           1           1           1    
     4096      4104      1           4           0           0           0    
  ------------------------------------------------------------------------    
  Suggested Percentages for current Cell Sizes:                               
    HEAPP(ON,56,90,280,2,848,6,2080,13,4096,1,0)                             

and we can see it had to allocate 251 extents for all the request.

Once the system has “warmed up” there should not be a major difference in performance. I would allocate the heap to be big enough to start with, and avoid extensions.

With the C run time there are heaps as well as heap pools. My C run time report gave

64bit User HEAP statistics:
31bit User HEAP statistics:
24bit User HEAP statistics:
64bit Library HEAP statistics:
31bit Library HEAP statistics:
24bit Library HEAP statistics:
64bit I/O HEAP statistics:
31bit I/O HEAP statistics:
24bit I/O HEAP statistics:

You should check all of these and make the initial size the same as the suggested recommended size. This way the storage will be allocated at startup, and you avoid problems of a request to expand the heap failing due to lack of storage during a buys period.

Advanced level for heap

While the above discussion is suitable for many workloads, especially if they are single threaded. It can get more complex when there are multiple thread using the heappools.

If you have a “hot” or highly active pool you can get contention when obtaining and releasing blocks from the heap pool. You can define multiple pools for an element size. For example

HEAPP(ON,(56,4),1,280,1,848,1,2080,1,4096,1,0)

The (56,4) says make 4 pools with block size of 56 bytes.

The output has

HEAPPOOLS Summary:                                                          
  Specified Element   Extent   Cells Per  Extents    Maximum      Cells In  
  Cell Size Size      Percent  Extent     Allocated  Cells Used   Use       
  ------------------------------------------------------------------------  
       56       64     1           4         251        1002           2  
       56       64     1           4           0           0           0  
       56       64     1           4           0           0           0  
       56       64     1           4           0           0           0  
      280       288      1           4           1           1           0  
      848       856      1           4           1           1           0  
     2080      2088      1           4           1           1           1  
     4096      4104      1           4           0           0           0  
  ------------------------------------------------------------------------  

We can see there are now 4 pools with cell size of 56 bytes. The documentation says Multiple pools are allocated with the same cell size and a portion of the threads are assigned to allocate cells out of each of the pools.

If you have 16 threads you might expect 4 threads to be allocated to each pool.

How do you know if you have a “hot” pool.

You cannot tell from the summary, as you just get the maximum cells used.

In the report is the count of requests for different storage ranges.

Pool  2     size:   160 Get Requests:           777707 
  Successful Get Heap requests:    81-   88                 77934 
  Successful Get Heap requests:    89-   96                 59912 
  Successful Get Heap requests:    97-  104                 47233 
  Successful Get Heap requests:   105-  112                 60263 
  Successful Get Heap requests:   113-  120                 80064 
  Successful Get Heap requests:   121-  128                302815 
  Successful Get Heap requests:   129-  136                 59762 
  Successful Get Heap requests:   137-  144                 43744 
  Successful Get Heap requests:   145-  152                 17307 
  Successful Get Heap requests:   153-  160                 28673
Pool  3     size:   288 Get Requests:            65642  

I used ISPF edit, to process the report.

By extracting the records with size: you get the count of requests per pool.

Pool  1     size:    80 Get Requests:           462187 
Pool  2     size:   160 Get Requests:           777707 
Pool  3     size:   288 Get Requests:            65642 
Pool  4     size:   792 Get Requests:            18293 
Pool  5     size:  1520 Get Requests:            23861 
Pool  6     size:  2728 Get Requests:            11677 
Pool  7     size:  4400 Get Requests:            48943 
Pool  8     size:  8360 Get Requests:            18646 
Pool  9     size: 14376 Get Requests:             1916 
Pool 10     size: 24120 Get Requests:             1961 
Pool 11     size: 37880 Get Requests:             4833 
Pool 12     size: 65536 Get Requests:              716 
Requests greater than the largest cell size:               1652 

It might be worth splitting Pool 2 and seeing if makes a difference in CPU usage at peak time. If it has a benefit, try Pool 1.

You can also sort the “Successful Heap requests” count, and see what range has the most requests. I don’t know what you would use this information for, unless you were investigating why so much storage was being used.

Ph D level for heap

For high use application on boxes with many CPUs you can get contention for storage at the hardware cache level.

Before a CPU can use storage, it has to get the 256 byte cache line into the processor cache. If two CPU’s are fighting for storage in the same 256 bytes the throughput goes down.

By specifying

HEAPP(ALIGN….

It ensures each block is isolated in its own cache line. This can lead to an increase in virtual storage, but you should get improved throughput at the high end. It may make very little difference when there is little load, or on an LPAR with few engines.

What they don’t tell you about using a REST interface.

After I stumbled on a change to my Python program which gave 10 times the throughput to a Web Server, I realised that I knew only a little about using REST. It is the difference between the knowledge to get a Proof Of Concept working, and the knowledge to run properly in production; it is the difference between one request a minute to 100 requests a second.

This blog post compares REST and traditional client server and suggests ways of using REST in production. The same arguments also apply to long running classical client server applications.

A REST request is a stateless, self contained request which you send to the back-end server, and get one response back. It is also known as a one shot request. Traditional client server applications can send several requests to the back-end as part of a unit of work.

In the table below I compare an extreme REST transaction, and an extreme traditional Client Server

AttributeRESTClient Server
ConnectionCreate a new connection for every request.Connect once, stay connected all day, reuse the session, disconnect at end of day.
Workload BalancingThe request can select from any available server, and so on average, requests will be spread across all connections. If a new server is added, then it will get used.The application connects to a server and stays connected. If the session ends and restarts, it may select a different server.
If a new server is added, it may not be used.
AuthenticationEach request needs authentication. If the userid is invalidated, the request will fail. Note that servers cache userid information, so it may take minutes before the request is
re-authenticated.
Authentication is done as part of the connection. If the userid is invalidated during the day, the application will carry on working until it restarts.
IdentificationBoth userid+password, and client certificate can be used to give the userid.Both userid+password, and client certificate can be used to give the userid. If you want to change which identity is used, you should disconnect and reconnect.
CostIt is very expensive to create a new connection. It is even more expensive when using TLS, because of the generation of the secret key. As a result it is very very expensive to use REST requests.The expensive create connection is done once, at start of day. Successive request do not have this overhead, so are much cheaper
Renew TLS session keyBecause there is only one transfer per connection you do not need to renew the encryption key.Using the same session key for a whole day is weak, as it makes it easier to break it. Renewing the session key after an amount of data has been processed, or after a time period is good practice.
RequestSome requests are suitable for packaging in one request, for example where just one server is involved.This can support more complex requests, for example DB2 on system A, and MQ on system B.
Number of connectionsThe connection is active only when it is used.The connection is active even though it has not been used for a long time. This can waste resources, and prevent other connections from being made to the server.
StatisticsYou get an SMF record for every request. Creating an SMF record costs CPU.You get one SMF record for collection of work, so reducing the overall costs. The worst case is one SMF record for the whole day.

What are good practices for using REST (and Client Server) in production?

Do not have a new connection for every request. Create a session which can be reused for perhaps 50 requests or ten minutes, depending on workload. This has the advantages :

  • You reduce the costs of creating the new connection for every request, by reusing the session.
  • You get workload balancing. With the connection ending and being recreated periodically, you will get the connections spread across all available connections. You should randomise the time a connection is active for, so you do not get a lot of time-out activity occurring at the same time
  • You get the re-authentication regularly.
  • The TLS key is renewed periodically.
  • You avoid the long running connections doing nothing.
  • For a REST request you may get fewer SMF records, for a Client-Server you get more SMF requests, and so more granular data.

How can I do this?

With Java you can open a connection, and have the client control how long it is open for.

With Python and the requests package, you can use

s = requests.Session()
res = s.get(geturl,headers=my_header,verify=v,cookies=jar,cert=cpcert)

res = s.get(geturl,headers=my_header,verify=v,cookies=jar,cert=cpcert)
etc

With Curl you can reuse the session.

Do I need to worry if my throughput is low?

No, If you are likely to have only one request to a server, and so cannot benefit from having multiple requests per connection you might just as well stay with a “one shot” and not use any of the tuning suggestions.

What’s going on? – getting performance data from a z/OS systrace

On my little z/OS system, one address space was using a lot of CPU – but doing nothing. What was going on? The address space was a z/OSMF based on the Liberty Web server.

The blog post tells you how to take a dump, and use IPCS to display useful information from the system trace. The system trace contains deep down information like

  • Task A was dispatched on this processor at this time.
  • It issued a request MVS to get a block of storage, and time.
  • The request completed, with this return code, at this time.
  • Task A was interupted at this time
  • Task B was dispatched

There is a lot of detailed information, and it is overwhelming when you first look at it. This blog post shows how you can get summary information from the trace – while ignoring all of the detailed, scary stuff. It does not require any prior knowledge of IPCS or dumps.

Take your dump

DUMP COMM=(COLINS DUMP)
R xx,jobname=IZUSVR1

This gives output like

IEE600I REPLY TO 01 IS;JOBNAME=IZUSVR1
IEA045I AN SVC DUMP HAS STARTED AT TIME=16.24.56 DATE=06/21/2021 044
FOR ASID (0044) QUIESCE = YES

IEA611I COMPLETE DUMP ON SYS1.S0W1.Z24A.DMP00004

Go into IPCS

I find it easier to use a wide(132) screen for IPCS.

This may be in your ISPF panels, or you might need to issue a command before starting ISPF. You might need to talk to your system programmer.

You get the primary menu

 ------------------- z/OS 02.04.00 IPCS PRIMARY OPTION MENU
 OPTION  ===>                                              
                                                           
    0  DEFAULTS    - Specify default dump and options      
    1  BROWSE      - Browse dump data set                  
    2  ANALYSIS    - Analyze dump contents                 
    3  UTILITY     - Perform utility functions             
    4  INVENTORY   - Inventory of problem data             
    5  SUBMIT      - Submit problem analysis job to batch  
    6  COMMAND     - Enter subcommand, CLIST or REXX exec  
    T  TUTORIAL    - Learn how to use the IPCS dialog      
    X  EXIT        - Terminate using log and list defaults

Select option 0

------------------------- IPCS Default Values ---------------------------------
 Command ===>                                                                   
                                                                                
   You may change any of the defaults listed below.  The defaults shown before  
   any changes are LOCAL.  Change scope to GLOBAL to display global defaults.   
                                                                                
   Scope   ==> LOCAL   (LOCAL, GLOBAL, or BOTH)                                 
                                                                                
   If you change the Source default, IPCS will display the current default      
   Address Space for the new source and will ignore any data entered in         
   the Address Space field.                                                     
                                                                                
   Source  ==> DSNAME('SYS1.CTRACE1')
   Address Space   ==> RBA
   Message Routing ==> NOPRINT TERMINAL NOPDS
   Message Control ==> CONFIRM VERIFY FLAG(WARNING)
   Display Content ==> NOMACHINE REMARK REQUEST NOSTORAGE SYMBOL ALIGN
                                                                                
 Press ENTER to update defaults.                                                
                                                                                
 Use the END command to exit without an update.                                 

Replace the source with DSN(‘your dumpname’).

Change Scope from LOCAL to BOTH

Press enter to update. Use =6 on the command line to get to the IPCS command window.

Enter a free-form IPCS subcommand or a CLIST or REXX exec invocation below: 
                                                                            
===>                                                                        
                                                                            
                                                                            
----------------------- IPCS Subcommands and Abbreviations -----------------
ADDDUMP           | DROPDUMP, DROPD   | LISTDUMP, LDMP    | RENUM,    REN   
ANALYZE           | DROPMAP,  DROPM   | LISTMAP,  LMAP    | RUNCHAIN, RUNC  
ARCHECK           | DROPSYM,  DROPS   | LISTSYM,  LSYM    | SCAN            
ASCBEXIT, ASCBX   | EPTRACE           | LISTUCB,  LISTU   | SELECT          
ASMCHECK, ASMK    | EQUATE,   EQU, EQ | LITERAL           | SETDEF,   SETD  
CBFORMAT, CBF     | FIND,     F       | LPAMAP            | STACK           
CBSTAT            | FINDMOD,  FMOD    | MERGE             | STATUS,   ST    
CLOSE             | FINDUCB,  FINDU   | NAME              | SUMMARY,  SUMM  
COPYDDIR          | GTFTRACE, GTF     | NAMETOKN          | SYSTRACE        
COPYDUMP          | INTEGER           | NOTE,     N       | TCBEXIT,  TCBX  
COPYTRC           | IPCS HELP, H      | OPEN              | VERBEXIT, VERBX 
CTRACE            | LIST,     L       | PROFILE,  PROF    | WHERE,    W     

If you use the command “systrace” you will see the scary internal trace. PF3 out of it.
Use the command

systrace jobname(IZUSVR1) PERFDATA(DOWHERE) time(LOCAL)

Go to the bottom of the report ( type m and press PF8) and type

REPORT VIEW

This gives you the report in an editor session, so you can exclude, delete, sort count etc.

This gives a lot of data. It is in sections, the sections are…FLocal

Summary of the dump

Analysis from 06/21/2021 16:24:46.391102 to 16:24:56.042146 9.651044 seconds 

This gives the time of day, and the interval of the trace is 9.65 seconds.

Summary of CPU usage by engine

CPU  Type Pol  Park   SRB Time              TCB Time             Idle Time           
---- ---- ---- ---- --------------------- --------------------- ---------------------
0000 CP   High No       0.190562   1.974%     0.828988   8.589%     8.603271  89.143%
0001 CP   High No       0.098836   1.024%     0.393259   4.074%     9.143735  94.743%
0002 CP   High No       0.086573   0.897%     0.415063   4.300%     9.136385  94.667%
0003 zIIP High No       0.015463   0.160%     2.227832  23.083%     7.398707  76.662%
0004 zIIP High No       0.000000   0.000%     1.094373  11.339%     8.551280  88.604%
---- ---- ---- ---- --------------------- --------------------- ---------------------
                        0.391434              4.959518             42.833380 

This shows

  • Most of the time was spent in TCB “application thread” mode (4.959 seconds of CPU) rather than SRB “system thread” mode (0.391 seconds of CPU).
  • One ZIIP was busy 23 % of the time, the other ZIIP was busy 11 % of the time.

Summary of CPU overall over 5 engines

 SRB time      :     0.391434 
 TCB time      :     4.959518 
 Idle time     :    42.833380 
 CPU Overhead  :     0.070886 
                 ------------ 
         Total :    48.255220  

This summarises the data

  • 4.95 seconds of CPU in TCB mode in 9.65 seconds of trace
  • 42 seconds idle
  • 5 engines * 9.65 seconds duration = 48.25

CPU break down by ASID/Jobname

CPU breakdown by ASID: 
                                                    
ASID Jobname    SRB Time     TCB Time    Total Time 
---- -------- ------------ ------------ ------------
0001 *MASTER*     0.011086     0.017940     0.029027
0003 RASP         0.000186     0.000000     0.000186
0005 DUMPSRV      0.035545     0.008959     0.044504
0006 XCFAS        0.021590     0.074411     0.096001
...   
0044 IZUSVR1      0.021217     3.638295     3.659513
0045 COLIN        0.000000     0.000000     0.000000
0046 RMF          0.010238     0.020204     0.030442
0047 RMFGAT       0.019961     0.160512     0.180474
              ------------ ------------ ------------
                  0.391434     4.959518     5.350953

Most of the CPU was in ASID 44 for job IZUSVR1.

Breakdown by system thread (SRB) by address space/jobname

SRB breakdown by ASID: (WHERE command bypassed for CPU usage less than 0.100000): 
                                                                                   
ASID: 0001   Jobname: *MASTER* 
IASN      SRB PSW      # of SRBs     Time 
---- ----------------- --------- ------------ 
0001 070C0000 83D0E8A0         2     0.000314 
...  
ASID: 0003   Jobname: RASP 
IASN      SRB PSW      # of SRBs     Time

Ignore this unless the SRB usage was high.

Breakdown of CPU by used thread by address space/jobname


TCB breakdown by ASID: 
                                                   
ASID Jobname  TCB Adr  # of DSPs     Time 
---- -------- -------- --------- ------------ 
0001 *MASTER* 008EDE88         1     0.000535
... 
ASID Jobname  TCB Adr  # of DSPs     Time 
---- -------- -------- --------- ------------ 
0044 IZUSVR1  008C8E88        22     0.013143 
0044 IZUSVR1  008AD7A0        30     0.006694 
0044 IZUSVR1  008B97B8        37     0.015926 
0044 IZUSVR1  008BA3E8        50     0.017547 
0044 IZUSVR1  008B2628        15     0.007748 
0044 IZUSVR1  008C4840        19     0.008433 
0044 IZUSVR1  008BD2D8        20     0.008551 
0044 IZUSVR1  008CDC68        14     0.008107 
0044 IZUSVR1  008C8328        15     0.006540 
0044 IZUSVR1  008CAC68        16     0.006612 
0044 IZUSVR1  008C9E88        14     0.006634 
0044 IZUSVR1  008B5C68        14     0.005668 
0044 IZUSVR1  008CBBE0        28     0.015650 
0044 IZUSVR1  008ADE00        17     0.005861 
0044 IZUSVR1  008B9470        15     0.006014 
0044 IZUSVR1  008BEA48        17     0.017092 
0044 IZUSVR1  008C6CF0        20     0.010093
...
0044 IZUSVR1  008CC2D8       548     0.827491 
0044 IZUSVR1  008D2E88        25     0.445230 
0044 IZUSVR1  008D2510       819     0.412526 
0044 IZUSVR1  008CEE88        14     0.158703
0044 IZUSVR1  008D3E88         8     0.003189 
0044 IZUSVR1  008C4CF0        18     0.013237 
                                 ------------ 
                                     3.638295
  • There were 166 TCB’s which did something in the time period.
  • TCB with address 008D2510 was dispatched 819 times times in 9 seconds – using 0.4 seconds of CPU! This was being dispatched 100 times a second, and used 5 milliseconds of CPU on average per dispatch. This looks high considering the system was not doing any work.
  • TCB with address 008d2E88 was dispatched 25 times in 9 seconds, and used 0.44 seconds of CPU or 17 ms of CPU per dispatch. This is doing more work per dispatch than the previous TCB.

Display lock usage

Lock events for CEDQ   
  None found                
Lock events for CSMF       
  None found               
Lock events for CLAT        
  None found              
Lock events for CMS         
  None found                
Lock events for OTHR        
  None found                

Nothing of interest here.

Display local lock usage – locking the job

Lock events for LOCL of ASID 0010 OMVS 
Lock ASID Jobname  TCB/WEB  Type    PSW Address    IASN  Suspended at    Resumed at     Suspend Time 
---- ---- -------- -------- ---- ----------------- ---- --------------- --------------- ------------ 
CML  0044 IZUSVR1  008C33E8 TCB  00000000_04868084 0010 16:24:49.612051 16:24:49.612076     0.000025 
CML  0044 IZUSVR1  008B4938 TCB  00000000_048687E4 0010 16:24:49.612090 16:24:49.612570     0.000480 
... 
---- ---- -------- -------- ---- ----------------- ---- --------------- --------------- ------------ 
Suspends:      6  Contention Time:     0.000821    0.008%               WU Suspend Time:    0.000823 
                                                                                                        
Lock events for LOCL of ASID 0044 IZUSVR1 
Lock ASID Jobname  TCB/WEB  Type    PSW Address    IASN  Suspended at    Resumed at     Suspend Time 
---- ---- -------- -------- ---- ----------------- ---- --------------- --------------- ------------ 
LOCL 0044 IZUSVR1  008D3E88 TCB  00000000_010CCD62 0044 16:24:46.404417 16:24:46.404561     0.000144 
LOCL 0044 IZUSVR1  008D3E88 TCB  00000000_010ADA78 0044 16:24:46.410188 16:24:46.412182     0.001993
Suspends:     83  Contention Time:     0.042103    0.436%               WU Suspend Time:    0.079177

The LOCal Lock (LOCL) is the MVS lock used to serialise on the address space, for example updating some MVS control blocks. For example if MVS wants to cancel an address space, it has to get the Local lock, to make sure that critical work completes.

  • For the OMVS addess space, address space IZUZVSR1 got the lock 6 times, and was delayed for 0.823 milliseconds waiting for the local lock.
  • For the IZUSVR1 address space, 83 TCBs got the local lock, and were suspended for a total of 79 milliseconds.

Display timer events (CPU Clock comparator CLKC and timer TIMR)

ASID: 0044   Jobname: IZUSVR1 
SRB/TCB  IASN   Interrupt PSW    Count   Where processing 
-------- ---- -------- -------- -------- ----------------------------------------
00000000 0044 070C0000 81D83CB8        2 IEANUC01.ASAXMPSR+00     READ/WRITE NUCLEUS 
...
008CEE88 0044 078D0401 945F2B28       11 AREA(Subpool252Key00)+CB28 EXTENDED PRIVATE 
008CEE88 0044 078D2401 945F99BE        1 AREA(Subpool252Key00)+0139BE EXTENDED PRIVATE 
008CEE88 0044 078D2401 FA63F71E        1 SPECIALNAME+03F71E     EXTENDED PRIVATE 
008CEE88 0044 078D0401 FAB00178        1 SPECIALNAME+0178     EXTENDED PRIVATE 
008CEE88 0044 078D2401 FAB447BE        1 SPECIALNAME+0447BE     EXTENDED PRIVATE 
008CEE88 0044 078D0401 FAD9E660        1 SPECIALNAME+29E660     EXTENDED PRIVATE 
008B17B8 0044 070C0000 81C92030        1 IEANUC01.IAXVP+4048     READ ONLY NUCLEUS 
008B27C0 0044 072C1001 91AF2460        1 BBGZAFSM+7520     EXTENDED CSA 
...
008D2E88 0044 078D0401 945F2B28       22 AREA(Subpool252Key00)+CB28     EXTENDED PRIVATE 
008D2E88 0044 078D0401 FB036F08        1 SPECIALNAME+036F08     EXTENDED PRIVATE 
...
008D2E88 0044 078D0401 FC145732        1 AREA(Subpool229Key00)+A732     EXTENDED PRIVATE 

This displays

  • The TCB
  • The virtual adress where the interrupt occurred
  • These entries are in time sequence, and so we can see the second entry had 11 interupts in quick succession (count is 11).
  • The Where processing, is a guess at converting the address into a module name. Sometimes it works, for example Module IEANUC01, csect ASAXMPSR, offset 0. Sometimes it cannot tell, for example from Java code.

This shows 2 things

  • The application said wake me up in a certain time period
  • The TCB was executing and z/OS interrupted it because it needed to go and dispatch some other work. This gives a clue as to hot spots in the code. If the same address occurs many times – the code was executing here many times. I look in the raw systrace to see if this is a TIMer (boring) or a CLKC interesting. Interesting gives you a profile of what code is CPU intensive.
  • You can delete all the records outside of this block, then sort 15 32 to sort on PSW address. For my IPCS dump the address 078D0401 945F2B28 occurred 35 times.

I/O activity

 Device   SSCH Issued    I/O Occurred     Duration   
 ------ --------------- --------------- ------------ 
  0A99  16:24:48.009819 16:24:48.010064     0.000244 
  0A99  16:24:48.033619 16:24:48.033856     0.000236 
  0A99  16:24:48.051014 16:24:48.051081     0.000066 
  0A99  16:24:48.057377 16:24:48.057434     0.000056 
  0A99  16:24:48.080331 16:24:48.080430     0.000098 
                                        ------------ 
                                            0.000702 
                                                     
    Events for 0A99 :            5                   
    Quickest I/O    :     0.000056                   
    Slowest  I/O    :     0.000244                   
    Total           :     0.000702                   
    Average         :     0.000140                   

This says for the device 0A99 there were 5 I/O requests, total time 0.7 milliseconds

  • I used the REPORT VIEW to get the data into ISPF edit,
  • deleted all the records above the I/O section
  • Used X ALL
  • F TOTAL ALL
  • This shows the totals for all I/Os. Most totals were under 1 ms. One I/O was over 5 seconds.
  • Displaying the detailed records above this TOTAL record showed one I/O took over 5 seconds!

End of report

End of PERFDATA analysis.

Advanced topic: Look at hot spots

I had seen that PSW 078D0401 945F2B28 was hot. If you go back to the IPCS command panel, you may be able to use the command

L 945F2B28

To display the storage. This will not work. You have to remove the top bit (80), so

L 145F2B28

may work.

If the first character is a letter (A-F) then you need to put a 0 on the front for example

L 0D2345678

You might need to put the address space in as well for example

L 145F2B28 ASID ID(x’44’)

You can say

L 145F2B28 ASID ID(x’44’) LENGTH(4096)

To display large sections of storage

Dig into the trace

You can use

systrace jobname(izusvr1)tcb(x’008CC2D8′)

to display all entries for the specified TCB and jobname.

  • Go to the bottom ( type Max press PF8)
  • use the report view command to get into and edit session
  • Columns 79 to 88 contain a description of some of the system calls
  • use X ALL;f ‘ ‘ 79 84 all;del all nx to delete all lines without a description

This gives you a picture of the MVS services being used.

Some of the mysteries of Java shared classes

When Java executes a program it read in the jar file, breaks it into the individual classes, converts the byte codes into instructions, and when executing it may replace instructions with more efficient instructions (Jitting). It can also convert the byte codes into instructions ahead of time, so called Ahead Of Time (AOT) compilation.

With shared classes, the converted byte codes, any Jitted code, and any AOT code can be saved in a data space.

  • When the java program runs a second time, it can reuse the data in the dataspace, avoid the overhead of the reading the jar file from the file system, and coverting the byte codes into instructions.
  • The data space can be hardened to a file, and restored to a data space, so can be used across system IPLs.

Using this, it reduced the start-up time of my program by over 20 seconds on my slow zPDT system. The default size of the cache is 16MB – one of my applications needed 100 MB, so most of the benefits of he shared classes could not be exploited if the defaults were used.

This blog post describes more information about this, and what tuning you can do.

Issuing commands to manage the shared classes cache

Commands to manage the shared classes cache are issued like

java -Xshareclasses:cacheDir=/tmp,name=client6,printStats

which can be done using JCL

// SET V=’listAllCaches’
// SET V=’printStats’
// SET C=’/tmp’
// SET N=’client6′
//S1 EXEC PGM=BPXBATCH,REGION=0M,
// PARM=’SH java -Xshareclasses:cacheDir=&C,name=&N,verbose,&V’
//STDERR DD SYSOUT=*
//STDOUT DD SYSOUT=*

Enabling share classes

You specify -Xsharedclasses information as a parameter to the program, for example in the command line or in a jvm properties file.

To use the shared classes capability you have to specify all of the parameters on one line, like

-Xshareclasses:verbose,name=client6,cacheDirPerm=0777,cacheDir=/tmp

Having it like

-Xshareclasses:name=client6,,cacheDirPerm=0777,cacheDir=/tmp
-Xshareclass:verbose

means the name, etc all take their defaults. Only shareclass:verbose would be used.

Changing share classes parameters

You can have more than one cache; you specify a name. You specify a directory were an image is stored when the cache is hardened to disk.

Some of the options like name= and cacheDir= are picked up when the JVM starts, Other parameters like cacheDirPerm are only used when the cache is (re-)created.

You can delete the cache in two ways.

Delete the cache from your your Java program

When you are playing around, you can add reset to the end of the -Xshareclasses string to caused the cache to be deleted and recreated.This gives output like

JVMSHRC010I Shared cache “client6” is destroyed
JVMSHRC158I Created shared class cache “client6”
JVMSHRC166I Attached to cache “client6”, size=20971328 bytes

This was especially useful when tuning the storage allocations.

Delete the cache independently

java -Xshareclasses:cacheDir=/tmp,name=client6,destroy

How to allocate the size of the cache

You specify the storage allocations using -Xsc.. (where sc stands for shareclasses)

If you have -Xsharedcache:verbose… specified then when the JVM shuts down you get

JVMSHRC168I Total shared class bytes read=11660. Total bytes stored=5815522
JVMSHRC818I Total unstored bytes due to the setting of shared cache soft max is 0.
Unstored AOT bytes due to the setting of -Xscmaxaot is 1139078.
Unstored JIT bytes due to the setting of -Xscmaxjitdata is 131832.

This shows the values of maxaot and maxjitdata are too small they were

-Xscmx20m
-Xscmaxaot2k
-Xscmaxjitdata2k

Whem the values were big enough I got

JVMSHRC168I Total shared class bytes read=12960204. Total bytes stored=8885038
JVMSHRC818I Total unstored bytes due to the setting of shared cache soft max is 0.
Unstored AOT bytes due to the setting of -Xscmaxaot is 0.
Unstored JIT bytes due to the setting of -Xscmaxjitdata is 0.

How big a cache do I need?

If you use -Xshareclasses:verbose… it will display messages

for example

JVMSHRC166I Attached to cache “client6”, size=2096960 bytes
JVMSHRC269I The system does not support memory page protection

JVMSHRC096I Shared cache “client6” is full. Use -Xscmx to set cache size.
JVMSHRC168I Total shared class bytes read=77208. Total bytes stored=2038042

Message JVMSHRC096I Shared cache “client6” is full. Use -Xscmx to set cache size, tells you the cache is full – but no information about how big it needs to be.

You can use

java -Xshareclasses:cacheDir=/tmp,name=client6,printStats

to display statistics like

-Xshareclasses persistent cache disabled]                                         
[-Xshareclasses verbose output enabled]                                            
JVMSHRC159I Opened shared class cache "client6"                                    
JVMSHRC166I Attached to cache "client6", size=2096960 bytes                        
JVMSHRC269I The system does not support memory page protection                     
JVMSHRC096I Shared cache "client6" is full. Use -Xscmx to set cache size.          
                                                                                   
Current statistics for cache "client6": 
cache size                           = 2096592                       
softmx bytes                         = 2096592                       
free bytes                           = 0                             
ROMClass bytes                       = 766804                        
AOT bytes                            = 6992                          
Reserved space for AOT bytes         = -1                            
Maximum space for AOT bytes          = 1048576                       
JIT data bytes                       = 212                           
Reserved space for JIT data bytes    = -1                            
Maximum space for JIT data bytes     = 1048576                       
Zip cache bytes                      = 1131864                       
Startup hint bytes                   = 0                             
Data bytes                           = 13904                         
Metadata bytes                       = 12976                         
Metadata % used                      = 0%                            
Class debug area size                = 163840                        
Class debug area used bytes          = 119194                        
Class debug area % used              = 72%

Cache is 100% full  
                                                                             

This show the cache is 100% full, and how much space is used for AOT and JIT. The default value of -Xscmx I had was almost 16MB. I made it 200MB and this was large enough.

I could not find a way of getting my program to issue printStats.

How do I harden the cache?

You can use use the

java -Xshareclasses:cacheDir=/tmp,name=zosmf,verbose,snapshotCache

command to create the cache on disk. Afterwards the listAllCaches command gave

Cache name level        cache-type     feature 
client6    Java8 64-bit non-persistent cr
client6    Java8 64-bit snapshot       cr

Showing the non persistent data space, and the snapshot file.

You can use the restoreFromSnapshot to restore from the file to the data cache; before you start your Java program. You would typically do this after an IPL.

How can I tell what is going on and if shared classes is being used?

The java options “-verbose:dynload,class

reports on the

  • dynamic loading of the files, and processing them,
  • what classes are being processed.

For example

<Loaded java/lang/reflect/AnnotatedElement from /Z24A/usr/lpp/java/J8.0_64/lib/rt.jar>
< Class size 3416; ROM size 2672; debug size 0>
< Read time 1196 usec; Load time 330 usec; Translate time 1541 usec>
class load: java/lang/reflect/AnnotatedElement from: /Z24A/usr/lpp/java/J8.0_64/lib/rt.jar
class load: java/lang/reflect/GenericDeclaration from: /Z24A/usr/lpp/java/J8.0_64/lib/rt.jar

dynload gave

<Loaded java/lang/reflect/AnnotatedElement from /Z24A/usr/lpp/java/J8.0_64/lib/rt.jar>
< Class size 3416; ROM size 2672; debug size 0>
< Read time 1196 usec; Load time 330 usec; Translate time 1541 usec>

this tells you a jar file was read from the file system, and how long it took to process it.

class gave

class load: java/lang/reflect/AnnotatedElement from: /Z24A/usr/lpp/java/J8.0_64/lib/rt.jar
class load: java/lang/reflect/GenericDeclaration from: /Z24A/usr/lpp/java/J8.0_64/lib/rt.jar

This shows two classe were extracted from the jar file.

In a perfect system you will get the class load entries, but not <Loaded….

Even when I had a very large cache size, I still got dynload entries. These tended to be loading class files rather than jar files.

For example there was a dynload entry for com/ibm/tcp/ipsec/CaApplicationProperties. This was file /usr/lpp/zosmf./installableApps/izuCA.ear/izuCA.war/WEB-INF/classes/com/ibm/tcp/ipsec/CaApplicationProperties.class

If you can make these into a .jar file you may get better performance. (But you may not get better performance, as it may take more time to load a large jar file).

I also noticed that there was dynload for com/ibm/xml/crypto/IBMXMLCryptoProvider which is in /Z24A/usr/lpp/java/J8.0_64/lib/ext/ibmxmlcrypto.jar, so shared classes has some deeper mysteries!

What happens if the .jar file changes?

As part of the class load, it checks the signature of the file on disk, matches the signature on the data space. If they are different the data space will be updated.

Using jConsole and with z/OS Liberty web server

I wanted to get some monitoring information out from z/OSMF using jConsole on my Ubuntu machine. Eventually this worked, but I had a few problems on the way. The same technique can be used for base Liberty, MQWeb, z/OSMF and ZOWE all of which are based on Liberty.

Configuring z/OSMF

I changed the z/OSMF configuration to include

<featureManager> 
  <feature>restConnector-2.0</feature> 
</featureManager> 

and restarted the server.

In the stdout (or message log) will be something like

CWWKX0103I: The JMX REST connector is running and is available at the following service
URL: service:jmx:rest://sss.com:10443/IBMJMXConnectorREST

You need the URL. The message above gave service:jmx:rest://sss.com:10443/IBMJMXConnectorREST, but I needed to use service:jmx:rest://10.1.1.2:10443/IBMJMXConnectorREST .

The port number came from the httpEndpoint with id=”defaultHttpEndpoint” . I have another httpEndpoint with port 24993, and this also worked with jConsole.

Set up jConsole

I set up a script for jConsole

k1='-J-Djavax.net.ssl.keyStore=/home/colinpaice/ssl/ssl2/adcdc.p12'
k2='-J-Djavax.net.ssl.keyStorePassword=password'
k3='-J-Djavax.net.ssl.keyStoreType=pkcs12'
t1='-J-Djavax.net.ssl.trustStore=/home/colinpaice/ssl/ssl2/zca.jks'
t2='-J-Djavax.net.ssl.trustStorePassword=password'
t3='-J-Djavax.net.ssl.trustStoreType=jks'
d='-J-Djavax.net.debug=ssl:handshake'
d=' '
de='-debug'
de=' '
s='service:jmx:rest://10.1.1.2:10443/IBMJMXConnectorREST'
jconsole $de $s $k1 $k2 $k3 $t1 $t2 $t3 $d

Where

  • the -J .. parameters are passed through to java,
  • the -Djava… are the standard set of parameters to define the key stores on the Linux

Running this script gave a pop up window with

Secure connection failed. Retry insecurely?

The connection to service:jmxLret://10.1.1.2:10443/IBMJMXConnectorREST could not be made using SSL.

Would you like to try without SSL?

This was because of the exception

java.io.IOException: jmx.remote.credentials not provided.

I could not see how to pass userid and password to jConsole.

I then used Cntrl+N to create a new connection and entered Username: and Password: which jConsole requires. After a short delay of a few seconds jConsole responded with a graphs of Heap Memory Usage, and Threads in use. You can then select from the Measurement Beans.

The TLS setup

In the keystore I had a certificate which I had used to talk to a Liberty instance before.

This was signed, and the CA certificate had been imported into the key trust keyring on z/OS, for that HttpEndPoint.

The server responded with a server certificate (“CN=SERVER,O=SSS,C=GB”) which had been signed on z/OS. The signing certificate had been exported from z/OS and downloaded to Linux

I created a jks key trust store using this certificate, using the command

keytool -importcert -file temp4ca.pem -keystore zca.jks -storetype jks -storepass password

and used this trust store to validate the server certificate sent down from z/OS.

This worked with jConsole.

I created a pkcs12 keystore using keytool

keytool -importcert -file temp4ca.pem -keystore zca2.p12 -storetype pkcs12 -storepass password

Which also worked.

Problems using a .p12 trust store

I used

runmqakm -keydb -create -db zca.p12 -type pkcs12 -pw password
runmqakm -cert -add -file temp4ca.pem -db zca.p12 -type pkcs12 -pw password -label tempca
runmqakm -cert -details -db zca.p12 -type pkcs12 -pw password -label tempca

to create a pkcs12 keystore and import the z/OS CA certificate. The -details option displayed it.

When I tried to use it, jConsole produced the message (after the Cntl+N)

Secure connection failed. Retry insecurely?

The connection to service:jmxLret://10.1.1.2:10443/IBMJMXConnectorREST could not be made using SSL.

Would you like to try without SSL?

I used Ctrl-N as before, and got the same message.

Using

d=’-J-Djavax.net.debug=ssl:handshake’

and rerunning the script, produced a TLS trace. At the bottom was

VMPanel.connect, handling exception: java.lang.RuntimeException: Unexpected error: java.security.InvalidAlgorithmParameterException: the trustAnchors parameter must be non-empty

%% Invalidated:…
VMPanel.connect, SEND TLSv1.2 ALERT: fatal, description = internal_error

Using a trace at the server, gave the unhelpful , SEND TLSv1.2 ALERT:

Using openssl also failed. Create the .p12 keystore

openssl pkcs12 -export -out zca.p12 -in temp4ca.pem -name zCA -nokeys

and rerun the jconsole script, and it failed the same way.

Unexpected error: java.security.InvalidAlgorithmParameterException: the trustAnchors parameter must be non-empty

It looks like runmqakm and openssl do not create a valid trust store with an imported certificate.

Additional diagnostics

When the trust store created by keytool was used; at the top of the TLS trace output was

System property jdk.tls.client.cipherSuites is set to ‘null’

Ignoring disabled cipher suite: SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA
trustStore is: /home/colinpaice/ssl/ssl2/zca.p12
trustStore type is : pkcs12

trustStore provider is :
init truststore
adding as trusted cert:
Subject: CN=TEMP4Certification Authority, OU=TEST, O=TEMP
Issuer: CN=TEMP4Certification Authority, OU=TEST, O=TEMP
Algorithm: RSA; Serial number: 0x0
Valid from Tue Jul 14 00:00:00 BST 2020 until Fri Jul 02 23:59:59 BST 2021

keyStore is : /home/colinpaice/ssl/ssl2/adcdc.p12
keyStore type is : pkcs12
keyStore provider is :
init keystore
init keymanager of type SunX509

When the runmqakm or openssl was used, the green entries were missing.

When I used runmqakm to create the pkcs12 keystore

runmqakm -cert -details -db zca.p12 -type p12 -pw password -label tempca

listed the certificate successfully.

When I used keytool to list the contents

keytool -list -keystore zca.p12 -storetype pkcs12 -storepass password
Keystore type: PKCS12
Keystore provider: SunJSSE

Your keystore contains 0 entries

When I created the key store with keytool, both runmqakm and keytool displayed the certificate.

The problem looks like Java is only able to process the imported CA certificates when keytool was used to create the trust store.

How to restrict what certificates and algorithms clients can use to connect to java web servers

As part of your regular housekeeping you want to limit connections to your web server from weak keys and algorithms.   Making changes to the TLS configuration could be dangerous, as there is no “warning mode” or statistics to tell you if weak algorithms etc are being used.  You have to make a change and be prepared to have problems.

In this posting I’ll explain how to do it, then explain some of the details behind it.

How to restrict what certificates and algorithms can be used by web servers and java programs doing TLS.

One way which does not work.

The jvm.options file provided by mqweb includes commented out

-Djdk.tls.disabledAlgorithms=… and  -Djdk.tls.disabledAlgorithms=…..

These is the wrong way of specifying information, as you do it via the java.security file, not -D… .

Create an mqweb specific private disabled algorithm file

Java uses a java.security file to define security properties.

On my Ubuntu, this file if in /usr/lib/jvm/…/jre/lib/security/java.security  .

Create a file mqweb.java.security.  It can go anywhere – you pass the name using a java system property.

Copy  from the java.security file to your file, the lines with  with jdk.tls.disabledAlgorithms=..  and jdk.certpath.disabledAlgorithms=… . 

On my system, the lines are (but your security people may have changed them – if so,  you might want to talk to them before making any changes)

jdk.tls.disabledAlgorithms=SSLv3, RC4, DES, MD5withRSA, DH keySize < 1024,     EC keySize < 224, 3DES_EDE_CBC, anon, NULL

jdk.certpath.disabledAlgorithms=jdk.certpath.disabledAlgorithms=MD2, MD5,    SHA1 jdkCA & usage TLSServer,    RSA keySize < 1024, DSA keySize < 1024, EC keySize < 224

The jvm.options file provided by IBM has

-Djdk.tls.disabledAlgorithms=SSLv3, TLSv1, TLSv1.1, RC4, MD5withRSA, DH keySize < 768, 3DES_EDE_CBC, DESede, EC keySize < 224, SHA1 jdkCA & usage TLSServer

So you may want to add this as in your override file ( without the -D), so add “, SHA1 jdkCA & usage TLSServer” to  jdk.certpath.disabledAlgorithms .

Tell mqweb to use this file

Create a java system property in the mqweb jvm.options file

“-Djava.security.properties=/home/colinpaice/eclipse-workspace-C/sslJava/bin/serverdisabled.properties”

Restart your web server.  You have not changed anything – just copied some definitions into an mqweb specific file, so it should work as before.

Limit what can be used

I set up several certificates with combination of RSA and Elliptic Curves, varying keysize, signatures;  and signed with CAs with RSA, and Elliptic Curve, and different signatures.

For example RSA4096,SHA256withECDSA,/EC256,SHA384with ECDSA means

  • RSA4096 certificate is RSA with a key size of 4096
  • SHA256withECDSA signed with this
  • /EC256 the CA has a public key of EC 256
  • SHA384with ECDSA and the CA was signed with this

I then specified different options in the servers’ file, and recorded if they TLS connection worked or not; if not – why not.

certpath: RSA keySize <= 2048

Server EC407,   SHA256withRSA,   /RSA4096,   SHA512withRSA

  • ✅RSA4096,SHA256withECDSA,   /EC256,SW=SHA384with ECDSA
  • RSA2048, SHA256withRSA,      /RSA4096,/SHA512withRSA
  • ✅ EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA
  • ✅EC384,       SHA256withECDSA, /EC256,      SHA384withECDSA

certpath: RSA keySize <= 4096

Server EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA

  • RSA4096,SHA256withECDSA, /EC256,       SHA384with ECDSA
  • RSA2048,SHA256withRSA,     /RSA4096,  SHA512withRSA
  • ❌EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA
  • ✅EC384,       SHA256withECDSA, /EC256,      SHA384withECDSA

certpath:EC keySize <= 256

Server EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA

  • ❌  RSA4096,SHA256withECDSA, /EC256,       SHA384with ECDSA
  • ✅ RSA2048,SHA256withRSA,       /RSA4096,  SHA512withRSA
  • ✅ EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA
  • ❌ EC384,       SHA256withECDSA, /EC256,      SHA384withECDSA

tls:EC keySize <= 256

Server EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA

  • ✅ RSA4096,SHA256withECDSA,   /EC256,       SHA384with ECDSA
  • ✅ RSA2048,SHA256withRSA,        /RSA4096,  SHA512withRSA
  • ✅ EC407,      SHA256withRSA,       /RSA4096, SHA512withRSA
  • ✅ EC384,       SHA256withECDSA, /EC256,      SHA384withECDSA

certpath: SHA256withRSA

Server EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA

  • ✅ RSA4096,SHA256withECDSA, /EC256,       SHA384with ECDSA
  • ❌RSA2048,SHA256withRSA,     /RSA4096,  SHA512withRSA
  • ❌ EC407,      SHA256withRSA,    /RSA4096, SHA512withRSA
  • ✅ EC384,       SHA256withECDSA, /EC256,      SHA384withECDSA

tls:SHA256withRSA

Server EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA

  • ✅ RSA4096,SHA256withECDSA, /EC256,       SHA384with ECDSA
  • ❌RSA2048,SHA256withRSA,     /RSA4096,  SHA512withRSA
  • ❌ EC407,      SHA256withRSA,    /RSA4096, SHA512withRSA
  • ✅ EC384,       SHA256withECDSA, /EC256,      SHA384withECDSA

either: RSA

Server RSA4096,SHA256withECDSA, /EC256,       SHA384with ECDSA

All requests failed due to the server’s RSA.   Only 18 out of 50 cipher suites were available.  Server reported javax.net.ssl.SSLHandshakeException: no cipher suites in common

  • ❌RSA4096,SHA256withECDSA, /EC256,       SHA384with ECDSA
  • ❌ RSA2048,SHA256withRSA,     /RSA4096,  SHA512withRSA
  • ❌ EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA
  • ❌EC384,       SHA256withECDSA, /EC256,      SHA384withECDSA

certpath: RSA keySize == 4096

Server RSA4096,SHA256withECDSA, /EC256,       SHA384with ECDSA

This was a surprise as I did not think this would work!

  • RSA4096,SHA256withECDSA, /EC256,       SHA384with ECDSA
  • RSA2048,SHA256withRSA,     /RSA4096,  SHA512withRSA
  • ❌EC407,      SHA256withRSA,      /RSA4096, SHA512withRSA
  • ✅EC384,       SHA256withECDSA, /EC256,      SHA384withECDSA

Summary of overriding.

You can specify restrictions in the server’s jdk.certpath.disabledAlgorithms and jdk.certpath.disabledAlgorithms. The restrictions apply to the how the certificate has been signed and the CA certificate.

You should check that the server’s certificate is not affected.

More details and what happens under the covers

The section below may be too much information, unless you are trying to work out why something is not working.

In theory jdk.tls.disabledAlgorithms and jdk.certpath.disabledAlgorithms are used for different areas of checking – reading certificates from key files, and what is passed during the handshake – but this does not seem to be true.  I found that it was best to put restrictions on both lines.

A certificate is of type RSA, EC, or DSA.

A certificate is signed for example Signature Algorithm: SHA256withECDSA.   This comes from the CA which signed it, message digest SHA256, and the CA is an Elliptic Curve.  See How do I create a certificate with Elliptic Curve (or RSA).

Signature Algorithms: is a combination of Hash Algorithm and Signature Type.   There are 6 hash algorithms: md5, sha1, sha224, sha256, sha384, sha512, and three types:  rsa, dsa, ecdsa.    These can be combined to to give 14 combinations of Signature Algorithms used in TLSv1.2

You can use java.security to control what TLS does.  On my Ubuntu this file /usr/lib/jvm/java-8-oracle/jre/lib/security/java.security.

This includes

  • jdk.certpath.disabledAlgorithms: Algorithm restrictions for certification path (CertPath) processing:  In some environments, certain algorithms or key lengths may be undesirable for certification path building and validation. For example, “MD2” is generally no longer considered to be a secure hash algorithm. This section describes the mechanism for disabling algorithms based on algorithm name
    and/or key length. This includes algorithms used in certificates, as well as revocation information such as CRLs and signed OCSP Responses.
  • jdk.tls.disabledAlgorithms: Algorithm restrictions for Secure Socket Layer/Transport Layer Security  (SSL/TLS) processing.  In some environments, certain algorithms or key lengths may be undesirable when using SSL/TLS. This section describes the mechanism for disabling algorithms during SSL/TLS security parameters negotiation, including protocol version negotiation, cipher suites selection, peer authentication and key exchange mechanisms.

I found you get better diagnostics if you put the restrictions on both statements.

The TLS Handshake (relating to java.security)

Server starts  up

  • I had 50 available cipher suites
  • Using -Djdk.tls.server.cipherSuites=…,… you can specify a comma separated list of  which cipher suites you want make available.  I recommend you do not specify this and use the defaults.
  • Using jdk.tls.disabledAlgorithm you can specify which handshake information is not allowed.  For example
    •  Any of the following would stop cipher suite TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384 from being used
      • java.security.tls = AES_256_CBC
      • java.security.tls= SHA384 – this loses 4 certificate TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384 etc
      • java.security.tls=TLS_ECDHE_ECDSA
    • Elliptic curves names Extension elliptic_curves, curve names: {secp256r1, secp384r1, secp521r1, sect283k1, sect283r1, sect409k1, sect409r1, sect571k1, sect571r1, secp256k1}.  Specifying EC keySize <= 521 would only allow {sect571k1, sect571r1} to be used
  • The server builds a supported list of cipher suites, signature algorithm, and elliptic curve names

Client starts up

  • As with the server, the client builds up a list of supported cipher suites, signature algorithms, and supported Elliptic curve names.
  • The client sends “ClientHello” and the list to the server.

Server processes

  • The server takes this list and iterates over it  to find the first acceptable certificate ( or for wlp, if <ssl … serverKeyAlias=”…” />, then the specified aliases  is used )
    • if the cipher suite name is like  TLS_AAA_BBB_WITH…   AAA must match the servers certificate type ( RSA, Elliptic Curve, DSA)
    • the signature algorithm (BBB).   This is the algorithm for encrypting the payload, and the algorithm for calculating the hash of the payload
    • if the certificate is EC,  check the  elliptic curve name is valid.  A  server’s certificate created with openssl ecparam -name prime256v1, would be blocked if EC keySize <= 256 was specified in the client resulting.
  • If no certificate was found in the trust store which passed all of the checks, it throws javax.net.ssl.SSLHandshakeException: no cipher suites in common , and closes the connection
  • The server sends “ServerHello” and the server’s public key to the client.
  • The server sends the types of certificate it will accept.   This is typically RSA, DSA, and EC
  • The server sends down the Elliptic Curve names it will accept, if present  – I dont think it is used on the java client
  • The server uses the jdk.certpath.disabledAlgorithm to filter the list of Signature Algorithms, and sends this filtered list to the client.
  • The server extracts the CAs and self signed certificates from the trust store and sends them down to the client.
  • The server sends “ServerHelloDone”, saying over to you to respond.

Client processing:

  • Checks the server’s certificate is valid, including
    • Checks the public certificate of the servers CA chain is allowed according to the client’s jdk.certpath.disabledAlgorithm..  So jdk.certpath.disabledAlgorithm =…, SHA256withECDSA would not allow a  server’s certificate with Signature algorithm:SHA256withECDSA .
  • The client takes the list of certificate types ( RSA, DSA, EC), and CAs and iterates over the keystore and selects the records where
    • the certificate type in the list
    • the signature algorithm is in the list
    • the certificate signed by one of the CA’s in the list
  • Displays this list for the end user to select from.  It looks like the most recently added certificate is first in the list.
  • The client sends “Finished” and  the selected certificate to the server

Server processing

  • The server checks the certificate and any imbeded CA certificates from the client matches.
    • Checks the signature algorithm
    • Checks the constraints, for example RSA keySize < 2048
    • Checks the certificate and CA are valid

End of handshake.

This is a useful link for describing the java.security parameters.

This specification  describes the handshake, with the “ClientHello” etc.

Using java -Djavax.net.debug=… to examine data flows, including TLS

Jan 2021. This page gets many hits. Please can you tell me if the information below is what you were looking for, or if you were looking for more information, such as understanding the trace flow, and finding problems.   Please send me an email or post a comment below with information on what you were looking for, and I’ll see what I can do.

There are different levels you can get from the -Djavax.net.debug option.  You can display its options using -Djavax.net.debug=help .

Ive added a section on -Djava.security.debug=… which looks at keystore access.

Ive also added a examples of what each trace option give you.

I’ve also put up a post which describes the trace, and has an annotated output (from both ends), showing common problems and possible solutions.

With -Djavax.net.debug you get

all            turn on all debugging
ssl            turn on ssl debugging

The following can be used with ssl:

    record       enable per-record tracing
    handshake    print each handshake message
    keygen       print key generation data
    session      print session activity
    defaultctx   print default SSL initialization
    sslctx       print SSLContext tracing
    sessioncache print session cache tracing
    keymanager   print key manager tracing
    trustmanager print trust manager tracing
    pluggability print pluggability tracing

    handshake debugging can be widened with:
    data         hex dump of each handshake message
    verbose      verbose handshake message printing

    record debugging can be widened with:
    plaintext    hex dump of record plaintext
    packet       print raw SSL/TLS packets

and your program exits.

You can use

-Djavax.net.debug=ssl:record or -Djavax.net.debug=ssl:handshake

To display specific levels of detail.

To specify more than one option use -Djavax.net.debug=ssl:keymanager:record

-Djava.security.debug=

Out of all the options below, I found certpath,provider provided the most useful information for seeing what was happening with certificates and the handshake.  For example

certpath: X509CertSelector.match(SN: 1a
Issuer: CN=TEMP4Certification Authority, OU=TEST, O=TEMP
Subject: CN=SERVER, OU=SSS, O=ZZZZ)
certpath: X509CertSelector.match: subject DNs don’t match
certpath: ForwardBuilder.getMatchingCACerts: found 0 CA certs
certpath: SunCertPathBuilder.depthFirstSearchForward(): certs.size=0
certpath: PKIXCertPathValidator.engineValidate()…
certpath: AdaptableX509CertSelector.match: subject key IDs don’t match. Expected: [] Cert’s: []
certpath: NO – don’t try this trustedCert
certpath: X509CertSelector.match(SN: 0
Issuer: CN=TEMP4Certification Authority, OU=TEST, O=TEMP
Subject: CN=TEMP4Certification Authority, OU=TEST, O=TEMP)
certpath: X509CertSelector.match returning: true
certpath: YES – try this trustedCert
certpath: anchor.getTrustedCert().getSubjectX500Principal() = CN=TEMP4Certification Authority, OU=TEST, O=TEMP
certpath: AlgorithmChecker.contains: SHA256withRSA
Provider: MessageDigest.SHA-256 algorithm from: SUN

I grepped with pkcs12: and got

pkcs12: Loading PKCS#7 encryptedData (PBEWithSHA1AndRC2_40 iterations: 2048)
pkcs12: Loading PKCS#7 data
pkcs12: Checking keystore integrity (HmacPBESHA1 iterations: 2048)
pkcs12: PKCS12KeyStore load: private key count: 1. secret key count: 0. certificate count: 1
pkcs12: Retrieved a protected private key at alias ‘ss’ (PBEWithSHA1AndDESede iterations: 2048)
pkcs12: Retrieved a 1-certificate chain at alias ‘ss’

The options…


all              turn on all debugging - this produces millions of lines of
                 output for one handshake! 
access           print all checkPermission results 
certpath        PKIX CertPathBuilder and CertPathValidator debugging 
combiner         SubjectDomainCombiner debugging 
gssloginconfig   GSS LoginConfigImpl debugging 
configfile       JAAS ConfigFile loading 
configparser     JAAS ConfigFile parsing 
jar              jar verification 
logincontext     login context results 
jca              JCA engine class debugging 
policy           loading and granting 
provider        security provider debugging 
pkcs11           PKCS11 session manager debugging 
pkcs11keystore   PKCS11 KeyStore debugging 
sunpkcs11        SunPKCS11 provider debugging 
scl              permissions SecureClassLoader assigns 
ts               timestamping 

The following can be used with access: 

stack            include stack trace 
domain           dump all domains in context 
failure          before throwing exception, dump stack and domain that 
                 didn't have permission 
thread           include the thread name 

The following can be used with stack and domain: 

permission=<classname> 
                only dump output if specified permission is being checked 
codebase=<URL>  only dump output if specified codebase  is being checked 
permname=<name> only dump output if the specified name matches the 
                permission getName() 
permactions=<actions>  only dump output if the specified actions 
                matches the permission getActions() 

The following can be used with provider: 

engine=<engines> only dump output for the specified list of JCA engines.  
                Supported values: 
                   Cipher, KeyAgreement, KeyGenerator, 
                   KeyPairGenerator, KeyStore, Mac, 
                   MessageDigest, SecureRandom, Signature. 

Note: Separate multiple options with a comma  

-Djavax.net.debug=ssl:record gave

records doing read and write
SSLSocketOutputRecord.java:241|WRITE: TLS12 handshake, length = 294
SSLSocketInputRecord.java:214|READ: TLSv1.2 handshake, length = 2948

-Djavax.net.debug=ssl:handshake gave

All of the sections.

-Djavax.net.debug=ssl:handshake:verbose gave

the same as ssl:handshake +

Signature algorithm, ed448, is not supported by the underlying providers
SignatureScheme.java:373|Ignore unsupported signature scheme: ed25519
SignatureScheme.java:373|Ignore unsupported signature scheme: ed448
SignatureScheme.java:393|Ignore disabled signature scheme: rsa_md5

-Djavax.net.debug=ssl:keygen gave

No records.

-Djavax.net.debug=ssl:session gave just

Session initialized:  Session(1611922238363|TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384)

-Djavax.net.debug=ssl:defaultctx gave

No records.

-Djavax.net.debug=ssl:sslctx gave

javax.net.ssl|DEBUG|01|main|2021-01-29 12:29:48.847 GMT|X509TrustManagerImpl.java:79|adding as trusted certificates (
  "certificate" : {
      "subject"            : "CN=DANCA1, OU=DAN, O=DAN",
...
  "certificate" : {
    "subject"            : "CN=SS, O=SSS, C=GB",
... 
  "certificate" : {
    "subject"            : "CN=ecec, O=cpwebuser, C=GB",
...
System property jdk.tls.client.cipherSuites is set to 'null'
System property jdk.tls.server.cipherSuites is set to 'null'
jdk.tls.keyLimits:  entry = AES/GCM/NoPadding KeyUpdate 2^37. AES/GCM/NOPADDING:KEYUPDATE = 137438953472
Ignore unsupported cipher suite: TLS_AES_256_GCM_SHA384
found key for : ecec (
  "certificate" : {
       "subject"            : "CN=ecec, O=cpwebuser, C=GB",
 
    "subject"            : "CN=SSCA256, OU=CA, O=SSS, C=GB",
  ...
found key for : mqweb (
  "certificate" : {...   
trigger seeding of SecureRandom
done seeding of SecureRandom
...
Produced ClientHello handshake message (
"ClientHello": {
...
Consuming ECDH ServerKeyExchange handshake message (
"ECDH ServerKeyExchange": {
  "parameters": {
    "named group": "secp256r1"
    "ecdh public": {
      0000: 04 5F 30 8E 64 45 55 C0   
      0010: 55 23 1B 69 CA FF 78 8D  
      0020: B5 59 72 BA B4 95 8A 4C  
      0030: 2B 37 55 3D F2 A5 3D 71  
      0040: 34                                               
    },
  },

-Djavax.net.debug=ssl:sessioncache gave

No records.

-Djavax.net.debug=ssl:keymanager gave

found key for : ecec (
“certificate” : {
“version”            : “v3”,

found key for : mqweb (
“certificate” : {

-Djavax.net.debug=ssl:trustmanager gave

adding as trusted certificates (
“certificate” : {

“subject” : “CN=mqweb8, O=cpwebuser, C=GB”,

“certificate” : {

“subject” : “CN=DANCA1, OU=DAN, O=DAN”,

Found trusted certificate (
“certificate” : {

“issuer” : “CN=DANCA1, OU=DAN, O=DAN”,

“subject” : “CN=DANCA1, OU=DAN, O=DAN”,

ss private or public key is not of EC algorithm

Where adding as …  is what the local trust store found, and found trusted is what as sent from the server as part of the certificateRequest.

-Djavax.net.debug=ssl:pluggability

No records.