One Minute MVS performance – DASD

Question: In your car how do you tell if your car has a problem? Answer: You look at the dashboard and see if there is a red light showing. You may not know how to fix it – but you know that you need to get help to fix it.

The aim of this series of blog posts is to show you what to look for in z/OS performance and if you have a problem.

I will cover

For some of these you need data from z/OS. This post describes how to get the SMF data, and format it using RMF.

DASD has changed in 40 years

40 years ago “disk storage” was on huge rotating disks and you had to carefully manage where you put your datasets -both which disk, and whereabouts on the disk. For example people would put the hot dataset in the “centre” of the disk to minimise the time to move the heads.

For the last 20 years people use the term “storage” because most I/O activity goes to cache in the disk controller, and the disk controller writes the data out to PC sized disks – which in turn may be solid state, and have no moving parts.

A pictorial view of disks

  • You have the processor running z/OS
  • Plugged into the side of the processor is the I/O adapter
  • Plugged into this I/O adapter are a lot of channels (think optical fibre cables)
  • Theses cables can be plugged into a switch – think of a plug board or telephone exchange. This allows channels from 2 processors plugged into the switch, and have one cable down to the storage controller . You could avoid a switch and have cables directly from the processor to the storage controller. Each processor would need its own set of cables.
  • The storage controller manages all of the IO
    • It has a lot of cache so most I/O may go to the cache. During a read, the storage controller will read from the disks if the data is not in the cache.
    • It has many PC type of disks. These disks could be solid state, or have rotating disks
    • If you have mirrored disks, the storage controller talks to a remote storage controller
  • Within each channel are many logical sub channels. Each disk has at least one sub-channel allocated to it. A disk can have multiple sub-channels allocated to it. There can be a pool of sub-channels which are used as needed to allowed parallel I/O to a disk.

The I/O journey

  • Your application wants to read the first record of a file.
  • Once the file has been opened, the application can issue the read.
  • z/OS knows where the data set is on disk (eg VOLID A4USR1, Cylinder 200, track 4)
  • z/OS builds up a set of commands (such as locate disk, locate cylinder 200, locate track 4, read data, read data, read data) to get the data and issues the Start Sub channel request, passing the list of I/O commands.
  • This is queued to the I/O adapter.
  • The original application is suspended (until the I/O is complete)
  • The I/O adapter looks for a free sub-channel for the disk, or gets one from the sub-channel pool.
  • The I/O adapter takes the list of commands, and executes them one at a time.
  • When the I/O adapter has finished the list of commands, it sends an interrupt to the mainframe saying “this subchannel has finished”.
  • z/OS wakes up, looks at the interrupt, and resumes the application.

Today you have to consider 3 areas where you can get delays, you need to be an expert if you want to look at more detail.

  1. Waiting in the I/O adapter before being able to get a sub channel. This is known as IOSQ – IO subsystem Queueing.
  2. Establishing the connection from processor to the storage controller
  3. Transferring the data the connect time.

This is complicated by being able to use disks 50 km away, which adds to the delay time.

RMF Reports

In the RMF MFR000… report with section D I R E C T A C C E S S D E V I C E A C T I V I T Y. (I search for IOSQ).


                  DEVICE   AVG  AVG   AVG  AVG  AVG   AVG  AVG  AVG    %      %    
 VOLUME PAV  LCU  ACTIVITY RESP IOSQ  CMR  DB   INT   PEND DISC CONN   DEV    DEV  
 SERIAL   1       RATE     TIME TIME  DLY  DLY  DLY   TIME TIME TIME   CONN   UTIL 
 A4RES1   1       102.896  .044 .003  .001 .000       .004 .000 .036   0.38   0.38 
 A4RES2   1        27.293  .036 .000  .001 .000       .003 .000 .032   0.09   0.09 
 USER00   1        25.331  .031 .003  .001 .000       .004 .000 .024   0.06   0.06 
 A4SYS1   1       365.102  .026 .005  .001 .000       .004 .000 .017   0.62  24.52 

Key fields

  1. Volume Serial such as A4RES1 is the volid of the disk
  2. PAV – I’ll mention this below.
  3. Device Activity Rate – how many requests (start sub channel) from z/OS, per second
  4. Average response time in milliseconds
  5. Average IOSQ – how long did it have to wait in z/OS and the I/O adapter before the request was sent down to the storage controller

The times are in milliseconds.

There are often thousands of volumes in a z/OS environment some are heavily used, some are not used. See below on how to find the hot volumes.

I typically look at the volumes with the highest I/O. If the hot volumes have good response time, the not so hot should be OK.

If you think of the sub-channel connection between the mainframe and the volid in the storage controller, there can only be one I/O requests at a time per sub-subchannel. You can have multiple connections down to a volume. These are known as PAV, or Parallel Access Volumes. The PAV is the average number of sub-channels in use.

The first field you look at is the IOSQ. This is the time between z/OS starting the request, and before the I/O could be started to the storage controller. This should be small 10s of microseconds ( 0.0xx in the report above). If this value is larger than this, you need to speak to your Storage Manager or z/OS Systems Programmer.

The second field you look at is the % DEV UTIL. How busy was the connection to the storage controller. A value of 100% means that it was running flat out. If the utilisation is around 70-80% it may be a OK – just something to note. More PAVs can increase throughput for a busy disk.

The next figure you look at is the RESP TIME. This is the response time the application sees. For local disk, response times of under 1 millisecond are OK. If you have remote disks, and synchronous I/O then the response time will be longer.

Finding the hot volumes

I take the RMF report and extract the DASD records.

  • For SDSF where the output is in the spool
    • I use Status to list all of the jobs, (Output or Hold work just as well)
    • Put ? in front of the job to show all of the spool data sets
    • use the SE command to Spool Edit the report
  • For a dataset I use the View prefix command in ISPF 3.4
  • Put DD in line prefix area on line 1
  • Find ‘D I R E C T’
  • Put DD in line prefix area, press enter, to delete the lines above it
  • Find ‘D I R E C T’ last
  • put d9999 in the line prefix area following the data (My report has ‘P A G I N G’), and press enter.
  • You should now have only DASD records
  • Put ‘cols’ in the line command area, note the columns of the DAR (50 to 58)
  • In the command line type SORT 50 58 D on Device Activity Rate.
  • This shows you the top usage volumes. Check the response times. Under 1 millisecond is good for locally attached disks. It can be down to 0.1 ms
  • If the response time is 1 ms or larger…
    • Check columns 60-65 (AVG IOSQ TIME) this should be 0. If this is non zero it means there was queueing in z/OS before it got to the disks. If there was only one I/O request to the volume, then there would IOSQ would be zero. If there are multiple I/O requests then you can get IOSQ queuing time.
    • Any IOSQ could be reduced by moving data sets to other volumes, or adding more paths(sub-channels) between the mainframe and the disks. Each disk requires at least one subchannel. You can allocate more in a pool – which are used when needed, but this is a z/OS system programmer/Storage manager job.
    • As a performance person you can control which disks you use, and can spread the load.
    • Avg CMR (ComMand Response) is the time to get from the processor down to the Storage Controller, and the controller to respond with “I’ve got the request” This should be small. This value allows you to see if delays are due to getting to the Storage controller, or within the controller.

If you do this for all disks you get an overall view of the data. Now you can select the DASD volumes you are using and check those.

If you find you have a long response time, then it is hard to find out the root cause. There are many links in the end to end chain. See here for more information.

One Minute MVS performance – CPU at the LPAR level

Question: In your car how do you tell if your car has a problem? Answer: You look at the dashboard and see if there is a red light showing. You may not know how to fix it – but you know that you need to get help to fix it.

The aim of this series of blog posts is to show you what to look for in z/OS performance and if you have a problem.

I will cover

For some of these you need data from z/OS. This post describes how to get the SMF data, and format it using RMF.

CPU

There are two basic things you need to check

  1. Has my LPAR got all the CPU it wanted – has the hyper-visor restricted the CPU?
  2. How busy are my CPUs?

Has my LPAR got all the CPU it wanted

An LPAR can be configured to have dedicated engines, or share a pool of engines. Dedicated engines means that the engine is always there when it is needed. If the LPAR is using a shared engine, it may not always be available when needed.

An example to explain the concept

You have a class from 10am to 11 am.  You go in, and sit down.  The teacher starts the class.  the teacher’s phone rings and goes out of the classroom. You play with your phone until the teacher comes back after 40 minutes. (The teacher went to teach in a different class room.)
How long were you in class for and how much work did you do?

  • You were in class for 1 hour.
  • You did 20 minutes work.

This concept is the same as any LPAR with shared engines.

  • The 1 hour class is a time slice as seen by z/OS.
  • The “processor” (teacher) was used in the time slice for only 20 minutes
  • For 40 minutes the “processor” was doing work elsewhere.

How do you get the report to show these figures.?

You need the RMF CPU report. It has “C P U A C T I V I T Y “ at the top of the page.

Look at the section

---CPU---    ---------------- TIME % ----------------   
NUM  TYPE    ONLINE    LPAR BUSY    MVS BUSY   PARKED   
 0    CP     100.00    46.68        46.32        0.00   
 1    CP     100.00    38.98        38.78        0.00   
 2    CP     100.00    34.91        34.62        0.00   
TOTAL/AVERAGE          40.19       39.90               
 3    IIP    100.00    94.43        94.70        0.00   
 4    IIP    100.00    93.50        93.74        0.00   
TOTAL/AVERAGE          93.96       94.22               

LPAR BUSY is how much teacher time you got

MVS Busy is how much time you were in the classroom for.

  • If MVS BUSY TIME = LPAR BUSY TIME, perfect, what you needed you got.
  • If MVS BUSY TIME > LPAR BUSY TIME, MVS had to wait for an engines, the system may need more CPU, a small difference(5%) is OK.
  • If MVS BUSY TIME >> LPAR BUSY TIME, For much of the time, there was no engine when MVS needed This will have a major impact on your work. If your end user work is not meeting targets, you need more CPUs, or give your LPAR a higher dispatching priority.

These values should be similar: MVS BUSY TIME 39.60 is close to LPAR BUSY 40.19, and for the ZIIP, 93.96 is close to 94.22.

When these figures are significantly different, stop, and fix the problem. This can make all other performance data look bad. For example, disk response time, and timing in application trace entries.

How busy are my CPUs?

The TOTAL/Average will be close to 100 % on a busy system. 95% busy is OK, Make a note that the system may be short of CPU.

These are average values. The individual values could be spiky. For example at 100% busy for 4 minutes, 80% busy for 1 minute, or an average of 96% busy over 5 minutes. Consider using an online monitoring to see if you have big peaks and trough.

More advanced topic for information.

The following section gives you information on how much work was waiting. It is hard to say what is good or bad, as it could look bad, but all the performance goals are being met.

How much work was waiting?

-----------------------DISTRIBUTION OF IN-READY WORK UNIT QUEUE--------------
 NUMBER OF              0    10   20   30   40   50   60   70   80   90   100
 WORK UNITS     (%)     |....|....|....|....|....|....|....|....|....|....|  
                                                                             
<=  N          26.3     >>>>>>>>>>>>>>                                       
 =  N +   1   12.9     >>>>>>>                                              
 =  N +   2    10.1     >>>>>>                                               
 =  N +   3    10.1     >>>>>>                                               
<=  N +   5    12.5     >>>>>>>                                              
<=  N +  10    11.0     >>>>>>                                               
<=  N +  15     6.0     >>>>                                                 
<=  N +  20     5.2     >>>                                                  
<=  N +  30     1.6     >                                                    
<=  N +  40     0.6     >                                                    
<=  N +  60     1.1     >                                                    
<=  N +  80     1.1     >                                                    
<=  N + 100     0.8     >                                                    
<=  N + 120     0.1     >                                                    
<=  N + 150     0.0                                                          
>   N + 150     0.0                                                          

N is the number of CPUs. I have 5 on my system.

The data is sampled. If system was sampled 10 times a second, every 0.1 of a second RMF counts the number of tasks in the “ready to dispatch queue”, and increments the value in the appropriate box; if there were 5 tasks executing and one task waiting, increment the N+1 element;

  • 26.3 % of the time, there were no tasks waiting for CPU.
  • 12.9 % of the time, there was 1 task waiting for CPU. See the bold data in the data above. (N+1 12.9 >>)
  • 10.1 % of the time, there were 2 tasks waiting for CPU
  • 5.2 % of the time there were between 16 and 20 tasks waiting for CPU
  • 0.1 % of the time there were between 101 and 120 task waiting for CPU

Remember this could be waiting for CP, or IIP.

If there are hundreds to tasks waiting for CPU you should make a note. It may not be a problem.

If there are under 50 tasks waiting for CPU, this should be OK.

On a busy system there will always be work waiting to run. Compare the pictures from a busy time and a not so busy time.

Is this important?

I once did some measurements with MQ on a machine with 16 processors, on average the engines were about 5% busy. A performance person from IBM said that my workload showed a shortage of CPU! 5 % busy on 16 processors – was I really short of CPU?

My application received some data, and posted 30 threads to come and process the data. The first 15 threads could be dispatched because there were 15 unused CPUs. 15 threads had to wait.

This showed up in the above report at line N+15 of the tasks were waiting 20% of the time.

Out of the 30 tasks that were dispatched, one processed the work,the other 29 went back to sleep.

We changed the program to post no more threads the number of CPUs (16) in the LPAR, and had a significant saving in CPU.

One minute MVS performance – getting batch RMF reports

There is an introduction to getting RMF reports docucmented here.

You can display information about your SMF environment, using

D SMF,O

This tells you if you are using SMF datasets, or log streams ( in the coupling facility) for the RMF data.

Copy the data from SMF dataset

// SET SMFPDS=SYS1.S0W1.MAN3 
// SET SMFSDS=SYS1.S0W1.MAN4 
//* 
//SMFDUMP  EXEC PGM=IFASMFDP 
//DUMPINA  DD   DSN=&SMFPDS,DISP=SHR,AMP=('BUFSP=65536') 
//DUMPINB  DD   DSN=&SMFSDS,DISP=SHR,AMP=('BUFSP=65536') 
//* MPOUT  DD   DISP=(NEW,PASS),DSN=&RMF,SPACE=(CYL,(1,1)) 
//DUMPOUT  DD   DISP=SHR,DSN=IBMUSER.RMF SPACE=(CYL,(1,1)) 
//SYSPRINT DD   SYSOUT=* 
//SYSIN  DD * 
  INDD(DUMPINA,OPTIONS(DUMP)) 
  INDD(DUMPINB,OPTIONS(DUMP)) 
  OUTDD(DUMPOUT,TYPE(70:79)) 
  DATE(2020316,2022284) 
  START(0930) 
  END(1700) 
/* 

This job copies the records from the “MAN” data sets, and writes them to the DUMPOUT.

The RMF records with types 70 to 79 are copied, within the specified dates and start and end times.

Copy the data from a log stream.

SMF can write data to log streams, for example MQ records go to the MQ stream, and the RMF records go to the RMF Stream.

//SMFDUMP EXEC PGM=IFASMFDL
//DUMPOUT DD DSN=&TEMP,SPACE=(CYL,(10,10),RLSE),DISP=(NEW,PASS)
//SYSPRINT DD SYSOUT=*
//SYSIN DD *
DATE(2018004,2018012)
START(0900)
END(1900)
LSNAME(IFASMF.RMF,OPTIONS(ALL))
OUTDD(DUMPOUT,TYPE(70:79,116))
/*

This step writes the data to a temporary data set.

Sort the data

If you are processing the data from more than one LPAR you will need to sort the data. See here.

Format the RMF data

The RMF control statements are described here

//POST EXEC PGM=ERBRMFPP 
//* use the following if using a temporary data set in same job.
//* MPFINPUT DD DISP=SHR,DSN=*.SMFDUMP.DUMPOUT 
//MFPINPUT DD DISP=SHR,DSN=IBMUSER.RMF 
//PPXSRPTS DD   SYSOUT=*,DCB=(LRECL=200,BLKSIZE=4000) 
//SYSPRINT DD   SYSOUT=* 
//SYSOUT   DD   SYSOUT=* 
//SYSIN DD * 
  SUMMARY(INT,TOT) 
  NODELTA 
  SYSOUT(H) 
  REPORTS(ALL,NOENQ,DEVICE(NOUNITR,NOCOMM)) 
SYSRPTS(WLMGL(RCPER)) 
SYSRPTS(WLMGL(SCPER)) 
/* 
/* SYSRPTS(WLMGL(RCPER)) 
/* SYSRPTS(WLMGL(SCPER,RCLASS,RCPER,SCLASS)) 

This takes the records from MFPINPUT which could be a permanent data set, or a temporary data set passed from a previous job step.

You can have the output go to the spool (by default) or to preallocated data sets. See here

One Minute MVS performance reports of interest are

REPORTS(CPU,DEV(DASD))

For WLM the reports

SYSRPTS(WLMGL(RCPER,SCPER))

Refreshing my zD&T and ADCD z/OS libraries

I wanted to refresh my zD&T system, and update some of the Z/OS volumes available from ADCD, so I could run the latest z/OS on my Ubuntu server.

It was not easy to find the route, and on the journey I found IBM has some web sites that are hard to use!

Getting started

You access the updates through IBM Passport Advantage.

I started with the IBM home page for my country, logged on and searched for “passport advantage”.

The top item was Download products from IBM Passport Advantage. Great, I clicked and got to a page giving an overview of Passport Advantage. Hidden at the very bottom it has a picture and a link “Sign on to Passport Advantage”.

This gets me to a page Passport Advantage Online for Customers. Click on “Sign on to your Passport Advantage site” (even though I am already signed on). If you click on the “sign in now” link, you get to a page with another(!) sign on link. It would be better to call this path ” Sign in now, with just a few more clicks now and then wait 30 seconds”.

Under Software download & media access click “Download Software“.

This gets you to another page called “Software download & media access”.

At the bottom of a page is a pull down with “Passport Advantage Express” pre selected. “Click on the Continue button to begin your personalized download experience“. It was “Passport Advantage Slow” rather than express.

You get to yet another page called “Software download & media access”.

You can pick a part if you know the name or part number, but I found this almost impossible to use. I kept going round in circles. Instead I used “All Products” (see below). This would be better called “All products you are licensed to”.

I cannot see how you get a product to appear as “My preferred products”. I have zD&T as a favourite.

Selecting All products displayed the following below the text.

IBM Z Development and Test Environment Personal Edition

When I clicked on it, it gave me the choice of

  • All operating systems
  • Redhat Enterprise Linux Base Server
  • Redhat Enterprise Linux Base Server

I wanted Ubuntu – and not two copies of Redhat, so I selected “All operating systems”.
I chose English language

This gives a page with a lot of information, and is a bit hard to navigate until you understand it.

This says you are using version 13.01.00 – click on change to select a different version. The version pull down has a random order – 10, 13, 8, 9 13 etc.

Pick your version.

The screen displays content based on your selection.

Expand “select individual files”. This gave me

Review the IBM z Development so you know what to expect. I think it is good practice to upgrade zD&T before upgrading ADCD.

Update the level of zD&T.

Expand IBM Z Development and Test Environment Personal Edition 13.01.

Download the ZDT* file and follow the instructions here.

I used sudo instead of using a super user password (which I do not have configured)

sudo ./ZDT_Install_PE_V13.0.0.0.x86_64

After it installed, I shutdown and rebooted.

After the reboot the z1091ver command gave

z1091, version 1.10.55.05.01, build date – 09/15/20 for Linux on Ubuntu 64bit

This is the same as it was with version 12.05!

Once you have reipled z/OS and checked it works, you can think about upgrading z/OS.

You can download the z/OS volumes while you are on the web site, and install them later.

Select the Z/OS volumes you want to download

Expand ADCD…

This gives a table with contents like

z/OS 2.4 Part 1 of 19 – RES volume 1 Multilingual (CC88DML)

At the top of the table click “show details”. This gives additional information like

  • z/OS 2.4 Part 1 of 19 – RES volume 1 Multilingual (CC88DML)
  • Part number: CC88DML
  • File name: B4RES1.ZPD

For zD&T version 12.05, the set of download files for z/OS 2.4 were called A4… for version 13.0.0 service refresh the files were called B4… for version 13.1.0 the files were called C4… . I expect the first volumes for z/OS 2.5 will be called A5RES1 etc.

If you know what volid you want within a release, you can enter it in the Search: box, for example B4RES1.

Download the files you want.

Using them is a much bigger challenge which I may write up another day. (For example SYS1.LINKLIB is currently catalogued on A4RES1. If I add B4RES1 to my system, I cannot just IPL from it as the volids will not match up.

How to become a performance expert in 3 easy lessons

and many hard lessons.

I had emails from two people, with different experiences of doing performance on z/OS. One person has recently started, and is not sure what is involved. The other person has been doing lots of work with customers explaining that his product is not the cause of the performance problems.

I thought it might be interesting for people who might be tempted to work in performance, to see the route to becoming an expert.

What does “performance” mean?

Performance work covers many different areas, and once you are competent in one product area it is not too difficult to cover additional areas.

“Performance” covers

Making sure it scales close to linearly

If you double the throughput, the costs per transaction should be similar. As the throughput increases, the response time does not increase significantly. You can have many threads running concurrently.

If the workload has disk I/O then you need to have multiple threads, so while one task is waiting for I/O another task can be using the CPU.

You need a box with multiple CPUs to detect contention. If you have only one or two engines you may not detect concurrency issues.

Work to remove contention until you can drive the CPUs at 100% busy (and then you ask for a bigger box). If you cannot drive the box at 100% find out why, resolve it and repeat.

Reduce CPU

Once you have eliminated as much contention as possible, you need to investigate where the CPU is being used, and try to eliminate any hot spots. This might be

  • Change algorithms – use a hash table instead of a linked list.
  • Avoid unnecessary work. Do you really need to store intermediate values in a database?
  • Can you tune the services being used. For example tune the database, add an index to a table.
  • Rearrange the code, for example have the “hot code” located in the same few pages. Avoid lots of error handling code in the mainline code – branch out of the mainline to handle it.
  • Remove debug code, or put debug code within if (debug enabled) then { debug code}.

Work with customers problems

Understand what areas the users have problems with, identify “problem areas” which take time to identify the problem.

Enhance the design

From your testing, and the experience with customer problem propose improvements to help diagnose problems for example

  • Capture the number, the average time, and the maximum time of database requests. Report this as a statistics or in response to a display command.
  • Record the number of times a resource, such as a lock, was not available, record total count of requests, number of blocked requests, time spent waiting. This code may never be executed, but if it is, you get useful information about the size of the problem.

Provide useful information to the end user

These are often known as “performance reports”. It is easy to produce reports that people cannot use – I have done it many times. Producing reports with nice graphs are often not easy to use, as they do not match your scenario.

You need to consider the questions the end users will have.

  • I want to run an ill defined workload (I do not know all the details), how big a box do I need (how many CPUs), to support 1000 requests a second.
  • What should I look at to tell me if things are running well or not.
  • What are common symptoms, and what actions can I take to solve performance problems.
  • What things do we need to consider to make it run well? For example table layout, how many requests per commit, how often you need to sign on.

Performance roles

The roles below are typical of the sort of activities a performance person will do

Run tests

The first tasks a person usually does when becoming a performance person is to run tests, and collect the data. This may involve writing scripts and tools so it can all be automated. For example on z/OS you might use Netview to run scripts, capture responses, and take actions when there are problems. This could all be done using Rexx scripts in TSO, and possibly using a REST interface.

Good automation will collect all of the key metrics into one place, for example a spread sheet, so the analyst can simply press a button or two to be able to display the data.

There may be a management report produced daily or weekly to show that performance overall has improved – or has not got worse.

Look at a component

You need to look at components within the whole environment, for example this week, look at the z/OSMF SDSF interface, next week the logon process.

You need to drive a high volume workload using this component. You need to focus on the component, for example with a REST requests 90% of the cost may be in the logon and establish a session. This makes it hard to focus on the other 10%. Sign on once, and have an application that just issues requests to the component.

When I was testing MQ under CICS, the duration of an MQPUT took 50 microseconds, and the cost of starting the CICS transactions was 1000 microseconds. I changed the transaction to process 1000 messages, so the transaction now took about 50 milliseconds, and most of the work was in the MQPUT area, and not in the CICS transaction overhead.

Capture the response time of the transactions and plot it over time. You should get a flat line. If the response increases over time, you might have a storage leak, and so it takes longer to get storage.

You may find it does not scale. Turning trace on can give an indication where the problem is. You often get function entry and exit trace, with time stamps, so you can post process the output to calculate the duration within the function. Trace often does not scale, so you cannot always believe the output.

You may want to instrument a private copy of the code. Obtain the time on entry and exit to the function, and across major calls to external requests. Calculate the duration of the calls, add logic to say “If duration > 10 millisecond then throw exception”, or accumulate the data in a global control block. When I did this, I found the trace code was adding significant delays, and the root cause of the problem was an insignificant line of code, which got an exclusive latch for an update!

I added code to measure the average duration of file I/O, and output this in the statistics. This made solving some problems very easy – you have an I/O problem. See here, it is taking 10 ms to write a page of data!

Unless you are testing the startup times, you should allow the system under test to “warm up”, so the hardware cache is in a steady state, database tables are in memory etc.

I found it useful to warm it up, then take 5 sets of measurements each of 1-5 minutes. When displaying the data, the results should all be similar. If not, you need to find out why. You should also run these tests once a week, and whenever you change a component, such as putting fixes onto your system, or change the hardware. Some example of things that can change your results

  • Overnight the Operations Team run backups and cause a different disk response time
  • The order the LPARs were ipled has changed. Last week your system had 6 CPUs in one book (so all very close to each other) this week your system has 3 CPUs in one book – and 3 CPUs in a different book – 1 metre away.
  • The network between your driving system and the test system has changed, or has a different load.

Usually the performance machines have their own dedicated hardware, processors, disks, connections to the disks, network.

Develop skills in other products

My background is MQ performance on z/OS. I had to learn about the performance characteristics of z/OS, DB2, TCP/IP, IMS, and understand the tools these products provide. Once you understand one trace, other traces are basically similar. The hard part is capturing the trace.

MQ passes messages from system to system. There were several problems where the “network was slow”. This meant we had to understand what was happening under the covers. Some good problems with easy fixes included

  • There was a TCP performance “improvement” where one end would delay sending a packet for a few milliseconds, as it is more efficient to send one big packet rather than several smaller packets. This meant that every MQ message sent over the network had a couple of millisecond delay. This fix was easy – disable this feature.
  • TCP/IP by default uses small buffers (256 bytes). You can configure a session to have very large buffers and tell it to automatically tune the best buffer size ( up to MB sized buffers).

Work with customers on their performance problems

The work involves working on performance problems where you do not have any of your specially written code included in it. You may need to turn on the product trace for a few seconds, then turn it off, and then process the output. Many customers do not run with trace on because of the overhead and major impact on throughput.

You can acquire the skills to talk to customers on the phone about their problems. It is very good to feedback what you heard. “Let me check what you just said … when you do … you get … “

Over time you will build up a list of questions to ask.

Once the problem has been resolved, consider what would have made it easier to find the root cause. Can you get development to put in some statistics, so next time this happens, you can tell the customer to check a value.

In the early days on MQ, we used to get many problems, because the in-memory buffer was too small. Development put out a fix, so that every 10 minutes or so it would report if it had detected a buffer full problem since the last message. After this fix was rolled out, we had no more of these problems.

There is no limit as to how far you can go

Once you have skills in one component you can apply these skills to other products or components. For example I spent some time looking at MQ on Linux so I could understand (and blog) on the performance data produced. (The performance data was “here are some numbers, we are not going to tell you what they mean”).

I’ve also been looking at Java performance, which lead me to look at the zFS file system, and the statistics it provides (it provides some – but they are not very useful).

You can also go deep. I knew about z architecture instructions and how some are fast and some are slow. I attended a taskforce with lots of hardware people. I met the team leader for the “load instructions”, and found that the “load instruction” was not an instruction – it is more like a subroutine with logic, for example

  • Find which CPU which currently “owns” this data in the CPU cache, and go and get it
  • Lock the page
  • Go and get this value from another page
  • Add the two values
  • Unlock both the pages

The subroutine had to communicate with other CPUs in the LPAR, worry about its own CPU cache etc. Deep Stuff!

Once you know this sort of stuff, it helps you program, for example it is better not to share a field if you do not have to. When a multi threading program uses a buffer to trace into, do not have one buffer which they all share, but give each thread its own buffer. This way the hardware will not be fighting over the buffer, and the data for each application can be kept on the same CPU as the program. This is obvious once you know!

Collect statistics at the thread level, and not at the global level. Merge them at display time. You know the reason why.

The hardware can start to execute instructions out of order – as long as they “commit” in the right order.

The z hardware has instrumentation which samples the executing system, and can tell you why instructions were delayed. For example

  • Data had to be obtained from the L2 cache on the chip
  • The instruction needed to be interpreted and added to the Translation Lookaside Buffer

This is a bit deep for many people, especially if they are at the level of using “printf” in their programs to display debug information.

“Me, with the brain the size of a planet ….”

This is a quote from Marvin the paranoid Android in the Hitchhiker’s guide to the galaxy. With performance work you can go deep, or you can go wide, but you would need a bigger brain than I had to go deep and wide – but it is a fascinating area.

Example of zFS statistics

This blog post gives an example of zFS statistics, and my interpretation of what they mean.

Related posts

I IPLed my z/OS to give a clean system.

I used a batch job to read all of the files in a directory and throw away the output.

sh cat /usr/lpp/java/J8.0_64/lib/ext/* 1> /dev/null

The command

du -ka /usr/lpp/java/J8.0_64/lib/ext/

gave 16728 KB, and there were 30 files in the directory.

The interface layer

The command

query -knpfs

gave

------------- ---------- ---------- ---------- ----------
Operation              Count      XCF req        Avg Time        Bytes 
-------------     ----------   ----------      ----------   ---------- 
zfs_opens                 37            0           0.053 
zfs_closes                37            0           0.024 
zfs_reads              4160            0           0.080      16.234M 
zfs_getattrs              86            0           0.036 
zfs_accesses             377            0           0.027 

There were 4160 read requests of 4096 bytes = 16MB

There were 30 opens one for each file.

There was an open for ‘/’, ‘/usr’ ‘/usr/lpp’ etc .. so 37 opens in total. At the end, each of these objects were closed.

The interface layer calls the buffer manager

The command

query -usercache

gave the User FIle (VM) Caching System Statistics report. It had

External requests
Reads     4160 Fsyncs     0 Schedules 0
Writes       0 Setattrs   0 Unmaps    0
Asy Reads 4126 Getattrs 153 Flushes   0

Which says there were 4160 read requests, which matches the zfs_reads request.

There were 4126 requests from the interface layer which had read-ahead set. This tells the buffer manager to get the pages. If they are not already in the buffer start reading them from disk. The Asy Reads does not give the reads from disk.

When I repeated the test I had: Reads 4160, Asy Reads 4120, with reads from disk 0 (as expected).

 File System Reads:
 Reads Faulted          34     (Fault Ratio    0.817%) 
 Writes Faulted          0     (Fault Ratio    0.000%) 
 Read Waits             34     (Wait Ratio     0.817%) 
 Total Reads           276 

This shows there were 276 reads from a file system, of which 34 requests had to wait for I/O.

I interpret this as saying there were 34 requests for get page which required disk I/O. The remained 276 – 34 caused I/O for read ahead so the application did not have to wait. I think the first page of each file was not in the cache, so there was an I/O to read the first segment(16 pages) of records in. There were 30 files, so 34 is close enough. The first request also started a Read Ahead to read the next segment in.

 Page Management (Segment Size = (64K) ) (Page Size = 8K) 
 -------------------------------------------------------- 
 Total Pages           121725     Free             118843 
 Segments                 395 
 Steal Invocations          0     Waits for Reclaim     0 

Before the test the free pages was 120933, so the delta is 2490 pages. Each page is 8KB, so the amount of storage used is 2490 * 8KB = 19.5 MB. The amount of data read from disk is 16.234MB so these numbers are comparable.

The Steal Invocations is the number of 64KB segments released to make space in the cache. In another test, I used a very small cache (10MB) and read 25636 KB of data in, and repeated the reads. Steal invocations was 404. 404 * 64 * 1024 = 25856 KB. This is close to the amount of data processed. Note: The documentation is incorrect,it says the value is the number of 4KB pages, not 64KB segments.

Data level

                   I/O Summary By Type 
                   ------------------- 
                                                                      
 Count       Waits       Cancels     Merges      Type 
 ----------  ----------  ----------  ----------  ---------- 
         75          61           0           0  File System Metadata 
          0           0           0           0  Log File 
        276          51           0           0  User File Data 

This shows there were 75 I/O requests for meta information about the file, and 276 I/O requests to read the file itself. Reading the documentation I think the WAITS column indicates an I/O request was delayed before its I/O started, for example there was already an I/O outstanding.

                  zFS I/O by Currently Attached Aggregate 
 DASD   PAV 
 VOLSER IOs Mode  Reads  K bytes  Writes  K bytes  Dataset Name 
 ------ --- ----  -----  -------  ------  -------  ------------ 
 ... 
 A4PRD3   1  R/O    302    16780       0        0  JVB800.ZFS 
 ... 
 ------ --- ----  -----  -------  ------  -------  ------------ 
                    337    17104      14       56  *TOTALS* 

This shows there was I/O to the data set containing the Java file system. There were 302 reads, and it read 16780 KB of data.

I’ve omitted the other file systems which with 35 Reads, and 14 Writes.

These counts do not seem to tie up. There were 276 Reads to the User File Data, and 75 reads for File System Meta data, a total of 351. The zFS read count was 337.

zFS performance reports I would like to use on z/OS (but can’t)

What started off as an investigation in why Java seemed slow on z/OS; was it due to a ZFS tuning problem? It changed into what performance health checks can I do with zFS.

It may be that zFS is so good you do not need to check its status, but I could find no useful reports, on what to check, and found that basic reports are not available, and useful data is missing. I would rather check than assume things are working OK.

Related posts

Getting the data

Data is available from SMF 92 records. Records are produced on a timer, either the SMF Interval broadcast, or the zFS -smf_recording interval.

Data is available from the zFS commands, for example query -reset -usercache.

If you use the display command, you get the data accumulate since the system was started, or the last reset was issued.

You may want to have a process to issue the display and reset commands periodically to provide a profile throughout the day. Having data accumulated for a whole day does not allow you to see peaks and troughs.

Some data does not include the duration of the data (or reset time), so you cannot directly calculate rates. You might need to save the reset time in a file, and use this to calculate the interval.

query fsinfo includes the reset time; query metacache, usercache and dircache do not include the reset time.

There is an API BPX1PCT(“ZFS “,ZFSCALL_STATS, … This returns the data in a C structure, but z/OS does not seem to provide this as a header file! It provides sample c programs for printing the data for each sort of data.. I do not know if the data is cumulative, or since the last reset.

Simple scenario

Consider the simple scenario,

  • I have a web server (Liberty on z/OS) for example z/OSMF, z/OS Connect, WAS with people using it.
  • There are people developing a Java application
  • I have a production Java program which runs every hour, reads in data from a file, does some processing, and puts sends it over HTTP to a monitoring system. This could be reading SMF data, and coverting it to JSON.

What the basic reports did I expect?

The question below would apply to any work, for example a business transaction, using CICS, DB2, MQ and IMS, zFS is just another component within a transaction.

  • When I start my Java application – it sometimes takes much longer to start than at other times – 20 seconds longer. What is causing this? Is it due to the delays in reading files or should I look else where?
    • For each job, I would like to know the total time spent processing files, and identify the files, used by the job, were most time is spent.
  • We had a slow down last week, can we demonstrate that zFS is not the problem?
  • Do I need to take any actions on zFS
    • Today – because it is slow
    • Next week – because I can see an increase in disk I/O over the past few weeks.
  • Can I tell which files or file systems are using most of the cache, and what can I do about it?

For each job, I would like to know the total time spent processing files, and identify the files, used by the job, were most time is spent.

This information is not available.

From the SMF 92-11 records you can get some information

  • Job name
  • File name. Some files are given as /u/adcd/j.sh, other files are given as write.c with no path, just the name used. This is not very helpful, as it means I am unable to identify the specific file used.
  • Time file was opened
  • Time file was closed (so you can calculate the open duration)
  • The number of directory reads. For the file “.” this had 1 read,
  • The number of reads, blocks read, and bytes read
  • The number of writes, locks written, and bytes written. For example an application did 10,000 writes, with a buffer length of 4096. There were 10,003 blocks written and 40,960,000 bytes written.

This information does not tell you how long requests took. A fread() could require data to be read from the file, or it may be available in the cache.

You cannot get this information from the zfs commands. You can get other information, for example the I wrote to a file and issued the command fileinfo -path /u/adcd/temp.temp -both this gave


path: /u/adcd/temp.temp 
owner                S0W1       file seq read           yes 
file seq write       yes        file unscheduled        0 
file pending         625        file segments           625 
file dirty segments  0          file meta issued        0 
file meta pending    0          
 

The data is described here.

  • unscheduled Number of 4K pages in user file cache that need to be written.
  • pending Number of 4K pages being written.
  • segments Number of 64K segments in user cache.
  • dirty segment Number of segments with pages that need to be written.

Given a filename you can query how many segments it has, but I could not find a way of listing the files in the cache. You would have to search the whole tree, and query each file to find this. This operation would significantly impact the metadata cache.

We had a slow down last week. Can we demonstrate that zFS is not the problem?

You can get information on

  • the number of pages in the various pools
  • the number of reads from the file system, and the number of requests that were available from the cache – the cache hit ratio. A good cache hit is typically over 95%.
  • Steal Invocations tells you if the cache was too small, so pages had to be reused.
  • The I/O activity (number of reads and writes, and number of bytes) by file system.
  • The average I/O wait time by volume.
  • The number of free pages never goes down, you can use it to see the highest number of pages in use, since ZFS started. It it reached 95% full on Monday – it will stay at 95% until restart.

If you compare the problem period with a normal period you should be able to see if the data is significantly different.

You need to decide how granular you want the data, for example capture it every 10 minutes, or every minute.

Do I need to take any actions on ZFS?

Today – because it is slow

Display the key data for the cache, cache hits, compare the amount of I/O today with a comparable day.

I do not think there are any statistics to tell you how much to increase the size of the cache. Making the cache bigger may not always help performance, for example if a program is writing a 1GB file, then while the cache is below 1GB it will flood the cache with pages to be written, and read only pages will have been overwritten.

Next week

You can monitor the number of reads and writes per file, and the number of file system I/Os, but you cannot directly see the files causing the file system I/O.

If there is a lot of sustained I/O to a file system, you may want to move it to a less heavily used volume, or move subdirectories to a different file system, on a different volume.

There are several caches: User Cache, Meta data cache, VNode cache, Log cache. The size of these can all be reconfigured, but I cannot see how to tell how full they are, and if they need to be increased in size.

Can I tell which files or file systems are using most of the cache, and what can I do about it?

The SMF record 92-59 contains the number of pages the file system has in the user cache, and in the meta cache.

The field SMF92FSUS has the number of pages this file system has allocated in the user cache.

The field SMF92FSMT has the number of pages this file system has allocated in the meta data cache

For 40 file systems, the time the record was created was within 2ms, so you should be able to group records with a similar time stamp, for example save the data, and show % buffers per file system.

The command fsinfo -full -aggregate ZFS.USERS provides the same information. It gave me

Statistics Reset Time:     May 30 11:09:51 2021 
Status:RW,NS,GF,GD,SE,NE,NC 
Legend: RW=Read-write, GF=Grow failed, GD=AGGRGROW disabled                                  
        NS=Mounted NORWSHARE, SE=Space errors reported, NE=Not encrypted                     
        NC=Not compressed                                                                    
   *** local data from system S0W1 (owner: S0W1) ***                                         
Vnodes:              48              LFS Held Vnodes:         4       
Open Objects:        0               Tokens:                  0       
User Cache 4K Pages: 5011           Metadata Cache 8K Pages: 39      
Application Reads:   11239           Avg. Read Resp. Time:    0.046   
Application Writes:  22730           Avg. Writes Resp. Time:  0.081   
Read XCF Calls:      0               Avg. Rd XCF Resp. Time:  0.000   
Write XCF Calls:     0               Avg. Wr XCF Resp. Time:  0.000   
ENOSPC Errors:       1               Disk IO Errors:          0 

This also showed:

  • there was 1 no-space error
  • Status had
    • GF=Grow failed
    • GD=AGGRGROW disabled
  • There were 48 Vnodes (files) in the meta cache.

It looks like the Application Reads and Writes are true application requests. I had a program which wrote 10,000 4KB records, and the Application writes increased by 10002. The reads increased by 23 event. I think this due to the running of the program.

The command also gave


VOLSER PAV    Reads      KBytes     Writes     KBytes     Waits    Average           
------ --- ---------- ---------- ---------- ---------- ---------- ---------          
A4USS2   1         55        532       1658      91216         83 0.990              
------ --- ---------- ---------- ---------- ---------- ---------- ---------          
TOTALS             55        532       1658      91216         83 0.990              

The number of write ( to the file system) increased by 630, the KB written increased by 40,084KB which is the approximate size of the file (40,000KB)

You can use the command fileinfo -path /u/adcd/aa -both and it will display information about the file system the file is on.

Although you can see how much data was written to the file system, I could not find easily find which file it came from. The SMF 92-11 records can give an indication, but writing 10MB to a file, and deleting the file may mean no data is written to disk, so the SMF 92-11 records are not 100% reliable.

How to collect zFS statistics

This blog post is part of a series on the zFS file system on z/OS and how to identify performance problems.

Related posts

How to collect the statistics data.

You can collect statistics data from zFS using

  • SMF type 92 records
  • Using operator commands. This should not be the normal way of collecting data, as it is verbose, and does not format well
    • You can display accumulated data
    • You can display and reset accumulated data
  • Using a batch/tso command. You can create output datasets of the information
    • You can display accumulated data
    • You can display and reset accumulated data
  • You can display them in RMF.
  • You can write your own program to extract the records. zFS provides the code of their commands.

SMF

You need to enable SMF collection using the zfsadm command. I could only get this to work through JCL.

// SET P='config -smf_recording off' 
// SET P='config -smf_recording on,10' 
// SET P='config -smf_recording on' 
// SET P='configquery -all' 
//AGGRINFO EXEC PGM=IOEZADM,REGION=0M, 
// PARM=('&P') 
//SYSPRINT DD SYSOUT=H 
//STDOUT DD SYSOUT=H 
//STDERR DD SYSOUT=H 
//SYSUDUMP DD SYSOUT=H 
//CEEDUMP DD SYSOUT=H 

You can use

  • configquery -all to display the current configuration
  • config -smf_recording on,10 to produce records every 10 minutes
  • config -smf_recording on to enable SMF recording on the SMF interval broadcast
  • config -smf_recording off to stop the collection of SMF data

You need to check that SMF is configured to collect the SMF 92 records. The operator command d SMF,o shows what is being collected. If it reports NOTYPE(14:19,62:69,92,99) with 92 in the list of NOTYPE, then SMF 92 records will not be collected.

You use a standard SMF job to copy the SMF data for post processing. I could not find an IBM provided formatter, so I wrote one.

I could not see how to cofigure zFS to not produce the SMF 92-11 records on individual zFS usage. I think you have to disable it at the SMF interval.

Operator command

You can issue a command at the console for example

F OMVS,PFS=ZFS,QUERY,VM

or

f ZFS,QUERY,VM

There is a lot of output, and it does not always format well on the console.

Using OMVS command line

You can use the omvs command zfsadm, for example zfsadm query -iobyaggr to display the data.

You’ll need to issue a command like

zfsadm query -iobyaggr 1>output_file

To capture the output

Using Batch

I use JCL (and move the relevant SET P statement to the bottom of the list as needed).

// SET P='config -smf_recording on,10' 
// SET P='/fileinfo /u/ibmuser      ' 
// SET P='config -smf_recording on' 
// SET P='configquery all' 
// SET P='config -smf_recording off' 
// SET P='query -iobyaggr' 
//AGGRINFO EXEC PGM=IOEZADM,REGION=0M, 
//  PARM=('&P') 
//SYSPRINT DD SYSOUT=H 
//STDOUT DD SYSOUT=H 
//STDERR DD SYSOUT=H 
//SYSUDUMP DD SYSOUT=H 
//CEEDUMP DD SYSOUT=H 

The query command has many options. I think you can only pass parameters via the parm statement. You cannot pass a list of command in//SYSIN.

Command interface

For the command interface, The values displayed are accumulated until reset, for example query -reset -iobyaggr

RMF

I started RMF, then used F RMF,START III to collect additional information.

I used the TSO RMFWDM command (RMF Work Delay Monitor). This gave me RMF Monitor III Primary Menu.

Selection S SYSPLEX Sysplex reports and Data Index

Selection I ZFSOVW zFS Overview

This gave

                                                                        
                                 ---------- Cache Activity ------------ 
System       -----Wait%------    ---User---    --Vnode---    -Metadata- 
              I/O  Lock Sleep     Rate Hit%     Rate Hit%     Rate Hit% 
                                                                        
S0W1         24.8   1.2   6.7    694.9 98.6    569.3 97.0    743.3 99.6 

This displays the user, vnode, and Metadata data cache. The rate of activity and the cache hit ratio. High(> 95%) is good. The rate is the number of get page requests a second.

If you tab to any of the numbers and press enter, it displays more information, for example

                     zFS Overview - User Cache Details                 
                                                                       
 The following details are available for system S0W1                   
 Press Enter to return to the Report panel.                            
                                                                       
 Size        :       951M         Storage fixed :  NO                  
 Total Pages :       122K                                              
 Free Pages  :      98245                                              
 Segments    :       4694                                              
                                                                       
 --------- Read ---------    --------- Write --------                  
  Rate  Hit%  Dly%  Async     Rate  Hit%  Dly%  Sched     Read%  Dly%  
                     Rate                        Rate                  
 261.3  96.4   0.2  97.44    433.6   100   0.0  7.010      37.6   0.0  
                                                                       
 ---------- Misc -----------                                           
 Page Reclaim Writes :     0                                           
 Fsyncs              :     7                                           

Selection 14 ZFSFS zFS File System (or zff)


                    RMF V2R4   zFS File System  - ADCDPL          Line 55 of 80
 Command ===>                                                  Scroll ===> CSR
                                                                               
 Samples: 100     Systems: 1    Date: 06/01/21  Time: 08.51.40  Range: 100   Sec
                                                                                
 ------ File System Name --------------------              I/O  Resp Read  XCF  
                  System    Owner     Mode    Size Usg%   Rate  Time  %    Rate                                                                                 
 ZFS.S0W1.USR.MAIL                                                              
                  *ALL      S0W1      RW     3600K  4.9  0.000 0.000  0.0 0.000 
 ZFS.S0W1.VAR                                                                   
                  *ALL      S0W1      RW       37M 63.2  265.1 0.033  100 0.000 
 ZFS.S0W1.VARWBEM                                                               
                  *ALL      S0W1      RO      105M 33.8  0.000 0.000  0.0 0.000 

If you put the cursor on any value ( except file name) you get more information.

I cound not find how to sort the data.

                           zFS File System Details                        
 File System Name : JVB800.ZFS                                            
 Mount                                                                    
 Point :                                                                  
 System : *ALL              Owner : S0W1              Mode : RO           
 -------------- Read -------------    ------------- Write -------------   
 --- Appl --- ---- XCF ----   Aggr    --- Appl --- ---- XCF ----   Aggr   
  Rate   Resp   Rate   Resp   Rate     Rate   Resp   Rate   Resp   Rate   
         Time          Time                   Time          Time          
 112.8  0.191  0.000  0.000  36618    0.000  0.000  0.000  0.000  0.000   
                                                                          
 Vnodes              :   111          USS held vnodes         :    68     
 Open objects        :    47          Tokens                  :     0     
 User cache 4k pages :  9549          Metadata cache 8k pages :   106     
                                                                          
 ENOSPC errors       :     0          Disk I/O error          :     0     
 XCF comm. failures  :     0          Cancelled operations    :     0     

Selection 15 ZFSKN zFS Kernel (zfk)

This gave me


                    RMF V2R4   zFS Kernel       - ADCDPL            Line 1 of 1
 Command ===>                                                  Scroll ===> CSR
 Samples: 100     Systems: 1    Date: 06/01/21  Time: 08.51.40  Range: 100   Sec
                                                                                
 System      - Request Rate -  --- XCF Rate ---  - Response Time -              
 Name         Local   Remote    Local   Remote    Local   Remote                
                                                                                
 S0W1          8599    0.000    0.000    0.000    0.054    0.000                

In all these reports you can use PF10 and PF11 to scroll through time.

Annoyances

With all the output you do not get the duration of the statistics, so you are not able to display rates, for example MB/Second to a file system.

If you enable SMF, then the first record contains the accumulated data since ZFS was started, or SMF was disabled. If you try plotting the values against time – you will get a strange graph.

There is no SMF formatter provided so I’ve written my own.

You cannot pass all of the parameters to IOEZADM as the parameter field is too long, so you have to use PARMSDD=

//AGGRINFO EXEC PGM=IOEZADM,REGION=0M,
// PARMDD=PARMS
//PARMS DD *
query -reset -iobyaggregate -iobydasd -knpfs -ctkc
-usercache -iocounts -metacache -dircache -logcache
/*

zFS on z/OS concepts, from a performance perspective

I was looking into a Java performance problem, and thought the problem may be connected to the performance of the unix files in the ZFS file system. I found it hard to find out useful information on how to investigate the problems. ZFS can produce a lot of information, but I found it hard to know which reports to look at, and what the key fields were.

This blog post gives the overall concept of a cached file system, it is based on my experience of other cached “file” systems. I have no special knowledge about zFS. I hopes it explains the concepts, it may not reflect reality.

Aside:

It reminds be of a lectures at University, where they explained matter was atoms with electrons whizzing around a small, solid nucleus. This was a good picture but entirely inaccurate. We then learned that the nucleus was composed to protons and neutrons. This was also a good picture, and entirely inaccurate. We then learned that protons and neutrons are composed of quarks particles, a good picture, but inaccurate. We then got into string theory and got knotted. Which ever picture you used, it help with the understanding but was not accurate.

Related posts

General background of cache systems.

A cached file system is common in IT. DB2 has buffer pools, MQ has buffer pools, and ZFS has a cache. The concepts are very similar. Over the years the technology has improved and the technology is efficient. For example all of the above system, use data in 4KB pages, and the IO to external media has been optimised.

I like to think of the technology in different layers.

  • The application layer, where the application does an fread(), MQGET or SQL query.
  • The interface layer, where it knows which records to get, which MQ message to gets, or which tables, rows and columns to get. This layer has a logical view of the data, and will request the next level down. “Please get me the data for this 4KB page on this data set at this position.
  • The buffer manager layer. The aim of the buffer manager is to keep the optimum amout of data in cache, and minimise I/O.
    • If the requested 4KB page is in the cache then return it. This counts as a cache hit.
    • If it is not in the cache then call the data layer, and say please read this page from disk at this location, into this buffer. This counts as a cache miss.
    • The buffer manager may have logic which can detect if a file is being read sequentially and perform read ahead. Logic like
      • Read page 19 of the data set, wait for the I/O to complete, return
      • Read page 20 of the data set, wait for the I/O to complete, return
      • Read page 21 of the data set, wait for the I/O to complete, return
      • Read page 22 … Hmm – this looks like a sequential read. Get pages 22 to 30 from the data set, wait for the IO to complete, return page 22
      • Read page 23 – get it from the buffer and return, no I/O
      • Read page 24 – get it from the buffer and return, no I/O
    • When a page has been updated, usually it is not written directly to the disk. It is more efficient to write multiple pages in one I/O. This means the application does not have to wait for the I/O. This is often called “write behind” or “lazy write”. When the application has to be sure the write to disk has worked, for example the fsync() request, or a transactional commit; the requester has to wait until the I/O has completed. The write to the disk is a collection of pages possibly from different applications. It is totally separate to the applications writing the records.
    • If the cache fills up, the buffer manager is responsible for making space. This might be to reuse the space for pages which have not been used for a long time, or if there are a lot of updated pages, writing these out – or doing both.
    • If the same file is often used, then the pages should be in the buffer. If a file is used for the first time, it will need to be read in – some pages synchronously by the application, then pages read in by the read ahead processing.
  • The data layer. This does the IO to the disk or other external media.

What statistics make sense?

The application can time the request and provide a true duration of the request.

At the interface level, one file read requests may have resulted in many calls to the buffer manager. The first few “get page” requests may be slow because it had to do I/O to the disk. After read ahead became active the reads from the buffer were very fast. “The average get page time” may have little value.

It may be possible to record the number of synchronous disk writes an application did (the fsync() request), but if the write was a lazy write it will not be recorded by against the file. If one I/O wrote 10 pages, four pages were for this application,six pages for that application. Recording the duration of the lazy write for each application has no value.

You can tell how many read and write requests there were to a data set (file system), and how long these requests took. You can also record how many bytes were read or written to a data set.

Overall there may be many statistics that tell you what each level is doing, and how it is performing, but they may not be very helpful when looking from an application viewpoint.

Simple file access example

  • fopen file name
  • fread
  • fwrite
  • fclose

fopen – Under the covers

Conceptually, the fopen may have logic like

zfs_open. This looks up to see if the file has been used before. It looks for the path name in the meta data cache. The meta data cache has information about the file, for example the file owner, the permissions for the owner, last time the file was read and pointer to the file system it is on, and its location on the file system.

If the path name is not in the meta cache then go to the file system and get the information. To get the information for file /u/colin/doc/myhelp.txt it may have to get a list of the files under /u/colin, then find where the ‘doc’ directory is. Then get information of the files under /u/colin/doc, this has record for myhelp.txt which has information on where this file is on disk. Set “next page” to where the file is on disk. Each of these steps may need or more pages to be read from disk.

fread – under the covers

The fread may have logic like

zfs_reads. Within this it may have logic like

  • Get the next page value. Does this page exist for in the cache? If so, return the contents, else read it from the file system, store it in the cache, update the next page pointer, and then return the contents.
  • Loop until enough data bas been read. As the pages are in 4KB units – to read a 10KB message will need 3 pages.

There are smarts; the code has read ahead support. If the system detects there have been a sequence of get next page requests, instead of “Loop until enough data has been read” it can do

  • Loop until enough data has been read, and start reading the next N pages, ready for the next request from the application.

By the time the application issues the next fread request, the data it needs may already have been read from disk. To the application it looks like there was no file I/O.

There may also be calls to zfs_getattrs, zfs_lookups.

fwrite – under the covers

The fwrite does not write directly to the disk. It writes some log data, and writes the data to the cache. This is known as “dirty data” because it has been changed. There is an internal process that writes the data out to the file system. Writing many records to the file system in one I/O is more efficient than writing one page each time in many IO.

Applications can use the fsync() request to force the writes to the disk.

Characteristics of the cached file system

It changes over time

The behaviour of the ZFS cache will change over time.

At start up, as files are used, the files will be read from disk into the cache.

Once the system has “warmed up”, the frequently used files will be in the cache, and should not need to be read from disk.

You could IPL the system at 0600, and for the first hour it warms up, and the cache settles down to a steady state for the rest of the day. In the evening, you may start other applications for the overnight processing, and these new applications will have a warm up period, and the cache will reach another steady state.

Data in the cache

Data in the file cache can be

  • Read only, for example a java program uses .jar files to execute. Some .jar files may be used by many applications and be access frequently.
  • Read only application data. For example a list of names.
  • Write application data – for example an output list of names, a trace or log file. For some writes this may be an update and so the previous contents need to be read in.

Read only jar files

The cache needs to be big enough to hold the files. Once the files have been read in, there may be no reads from the file system. Any files that had not been used before will need I/O to the file system. If the cache is not big enough then some of the data can be thrown away, and reloaded next time it is needed.

Read only application data

This data may only be used once a day. Typically it will be read in as needed, and once it has been used it is the cache storage could be stolen and reused for other applications.

Write application data

If the write updates existing pages for example writing to the end of a file, or updating a record within the file then the pages will be needed to be in cache. This may require disk I/O, or the page may be in the cache from a previous operation.

If the data is written to an empty page, then the page need not be in the cache before it is written to. Once the page has been updated, it will be written asynchronously, as it is more efficient to write multiple pages in one I/O than multiple I/Os with just one page.

File system activity

A program product file system

This will typically be used read only (even though it may be mounted read/write), so you can expect pages read from the data set, but no write I/O.

User’s data

A user will typically read and write files read I/O and write I/O.

Using subystems like Liberty Web Server ( and so products like z/OSConnect, z/OSMF, ZOWE) these will have read and write activity, as configuration information is used, and data is written to logs.

What happens as the cache is used?

Writing to a file

When data is written to a file, the cache gets updated. Modified pages get queued to be written to disk when

  • A segment of 64KB of data for a file is filled up.
  • The application does a fsync() request to say write the file out to disk.
  • The file is closed
  • The zfsadm config -sync_interval n has expired.
  • The cache is very full of updated (dirty) pages the so called Page Reclaim Writes

Reading a file

When a page has been used, it gets put on a queue, with most recent used pages at the front. A hot page (with frequent use) will always be near the front of the queue. If all the pages have data, and the buffer pool needs a buffer page, then the oldest page on this queue is stolen, (or reclaimed) for the new request.

Ideally the buffer pool needs to be big enough so there is always unused space.

If you have a cache of size 100 pages and read a 50 page file, it will occupy 50 pages in the cache. The first time the file is used data will have to be read from disk. The second time the file is used, all the pages are in memory and there is no disk I/O.

If the cache is only 40 pages, then the first 40 pages of data will fill the cache. When page 41 is read it will use replace the buffer with page 1 in it (the oldest page). When page 42 is read, it will replace the buffer with page 2 in it.

If you now read the file a second time – page 1 is no longer in the cache, so it will need to be read from disk, and will replace a buffer. All 40 pages will be read from disk.

Will making the cache bigger help? If you make the cache 45 pages it will have the same problem. If you make it 50 pages the file will just fit – and may still have a problem. If the cache is bigger than 50 pages the file should fit in – but other applications may be using other files, so you need to make the cache big enough for the 50 page file, and any other files being used. There is nothing to tell you how big to make it. The solution seems to be make the cache bigger until the I/O stops (or reduces), and you have 5-10% free pages. If you make the cache very large it might cause paging, so you have a balancing act. It is more important to have no paging, as paging makes it difficult for the buffer manager to manage. (For example it wants to write out a dirty page. It may need to page in the data, then write it out!)

Reusing pages

A page cannot be stolen(reused) if it needs to be written to disk. Once the contents have been written to disk the page can be stolen.

In reality it looks like blocks of 64 KB segments are used, not pages.

There is a VM statistic called Steal Invocations. This is a count of the number of 64KB blocks which were reused.

Overall performance objective

The cache needs to be big enough to keep frequently used files in the cache. If the cache is not big enough then it has to do more work, for example discard files, to make space, and reading files in from disk.

The system provides statistics on

  • How big the cache is
  • How many free pages there are
  • How many segments have been stolen (should be zero)
  • How many read requests were met from data in the cache (Cache hit), and so by calculation the number of requests that were not in the cache (cache miss), and required disk I/O.

Typically you will not achieve a cache hit of 100% because the application data may not be hot.

A little whoops

I had a little whoops. I wrote to a file, and filled the file system. When I deleted the file, and tried again, it reported there was no space on the device. When I waited for a few seconds, and repeated the command, it worked! This shows there are background tasks running asynchronously which clean up after a file has been used.

Just to make it more complex

  • ZFS uses 8KB as its “page” which is 2 * 4K pages on disk.
  • Small files live in the meta data, and not in the user cache!
  • There is also a Directory Backing Cache also known as Metadata Backing Cache. This seems to be a cache for the meta data, which doesn’t have the same locking. It is described in a Share presentation, zFS Diagnosis I: Performance Monitoring and Tuning Guidelines from 2012. It looks from the more recent documentation as if this has been rolled into the meta cache.

Sysplex support

The sysplex support makes it just a little more complex.

The ZFS support behaves like a client server.

One LPAR has the file system mounted read write – acting as the server. Other system act as the client.

If SYSA has the file system mounted Read Write, and SYSB wants to access a file, it sends a request through XCF. The access is managed by use of Tokens, and a Token Cache.

If you display KNPFS (Kernel Nodes Physical File System?) you get operations such as zfs_open

  • On Owner. On my single LPAR sysplex, I get values here
  • On Client. These are all zeros for me.

SMF 92-51 provides statistics on the zfs verbs such as zfs_open

  • Count of calls made to file systems owned locally or R/O file systems
  • Count of calls that required a transmit to another sysplex member to complete for locally-owned file systems.
  • Count of calls made to file systems owned remotely from this member.
  • Count of calls that required a transmit to another sysplex member to complete for remotely-owned file systems.
  • Average number of microseconds per call for locally-owned file systems.
  • Average number of microseconds per call for remotely-owned file systems

Configuration

The ZFS configuration is driven from the SYS1.PARMLIB(BPXPRM00), member with

FILESYSTYPE TYPE(ZFS) ENTRYPOINT(IOEFSCM)

This can have PRM=(aa, bb, …, zz) for SYS1.PARMLIB(IOEPRMaa)… It defaults to parmlib member IOEPRM00. See here for the contents.

“Why were the options I passed to Java ignored” – or “how to tell what options were passed to my Java?”

I was struggling to understand a problem with shared classes in Java and I found the options being used by my program were not as I expected.

I thought it would be a very simple task to display at start up options used. It may be, but I could not find how to do it. If anyone knows the simple answer please tell me.

I found one way – take a dump! This seems a little extreme, but it was all I could find. With Liberty you can take a javacore dump (F IZUSVR1,JAVACORE) and display it, or you can take a dump at start up.

In the jvm.options I specified

-Xdump:java:events=vmstart

This gave me in //STDERR

JVMDUMP039I Processing dump event “vmstart”, detail “” at 2021/05/20 13:19:06 – please wait.
JVMDUMP032I JVM requested Java dump using ‘/S0W1/var/…/javacore.20210520.131906.65569.0001.txt’
JVMDUMP010I Java dump written to /S0W1/var…/javacore.20210520.131906.65569.0001.txt
JVMDUMP013I Processed dump event “vmstart”, detail “”.

In this file was list of all the options passed to the JVM

1CIUSERARGS UserArgs:
2CIUSERARG -Xoptionsfile=/usr/lpp/java/J8.0_64/lib/s390x/compressedrefs/options.default
2CIUSERARG -Xlockword:mode=default,noLockword=java/lang/String,noLockword=java/util/Ma
2CIUSERARG -Xjcl:jclse29
2CIUSERARG -Djava.home=/usr/lpp/java/J8.0_64
2CIUSERARG -Djava.ext.dirs=/usr/lpp/java/J8.0_64/lib/ext
2CIUSERARG -Xthr:tw=HEAVY
2CIUSERARG -Xshareclasses:name=liberty-%u,nonfatal,cacheDirPerm=1000,cacheDir=…
2CIUSERARG -XX:ShareClassesEnableBCI
2CIUSERARG -Xscmx60m
2CIUSERARG -Xscmaxaot4m
2CIUSERARG -Xdump:java:events=vmstart
2CIUSERARG -Xscminjitdata5m
2CIUSERARG -Xshareclasses:nonFatal
2CIUSERARG -Xshareclasses:groupAccess
2CIUSERARG -Xshareclasses:cacheDirPerm=0777
2CIUSERARG -Xshareclasses:cacheDir=/tmp,name=zosmf2
2CIUSERARG -Xshareclasses:verbose
2CIUSERARG -Xscmx100m

the storage limits

1CIUSERLIMITS User Limits (in bytes except for NOFILE and NPROC)
NULL ------------------------------------------------------------------------
NULL         type            soft limit  hard limit
2CIUSERLIMIT RLIMIT_AS       1831837696   unlimited
2CIUSERLIMIT RLIMIT_CORE        4194304     4194304
2CIUSERLIMIT RLIMIT_CPU       unlimited   unlimited
2CIUSERLIMIT RLIMIT_DATA      unlimited   unlimited
2CIUSERLIMIT RLIMIT_FSIZE     unlimited   unlimited
2CIUSERLIMIT RLIMIT_NOFILE        10000       10000
2CIUSERLIMIT RLIMIT_STACK     unlimited   unlimited
2CIUSERLIMIT RLIMIT_MEMLIMIT 4294967296  4294967296

and environment variables used.

1CIENVVARS Environment Variables
2CIENVVAR LOGNAME=IZUSVR
2CIENVVAR _CEE_ENVFILE_S=DD:STDENV
2CIENVVAR _EDC_ADD_ERRNO2=1
2CIENVVAR _EDC_PTHREAD_YIELD=-2
2CIENVVAR WLP_SKIP_MAXPERMSIZE=true
2CIENVVAR _BPX_SHAREAS=NO
2CIENVVAR JAVA_HOME=/usr/lpp/java/J8.0_64

All interesting stuff including the -X.. parameters. I could see that the parameters I had specified were not being picked up because they were specified higher up! Another face palm moment.

There was a lot more interesting stuff in the file, but this was not relevant to my little problems.

Once z/OSMF was active I took a dump using the f izusvr1,javacore command and looked at the information on the shared classes cache

1SCLTEXTCMST Cache Memory Status
1SCLTEXTCNTD Cache Name      Cache path
2SCLTEXTCMDT sharedcc_IZUSVR /tmp/javasharedresources/..._IZUSVR_G37
2SCLTEXTCPF Cache is 85% full
2SCLTEXTCSZ Cache size = 104857040
2SCLTEXTSMB Softmx bytes = 104857040
2SCLTEXTFRB Free bytes = 14936416

This is where I found the shared cache was not what I was expecting! I originally spotted that the cache was too small – and made it bigger.

Afterwards…

Remember to delete the javacore files.

I removed the -Xdump:java:events=vmstart statement, because I found it more convenient to use the f izusvr1,javacore command to take a dump when needed.