The Problem

I have Hercules set up on my home server as well as my personal laptop, both primarily running instances of z/VM. I started to encounter issues where from the z/VM side, it completely hanged when first logging into a specific CMS guests. I quickly isolated the issue to being DASD I/O related, hence it only affected z/VM Users that accessed minidisks or SFS that utilized a particular DASD volume.

Looking at the Hercules logs:

HCPMHT2153I DASD  0107 I/O CANCELLED DUE TO A MISSING INTERRUPT
HHC00418E 0:0107 CKD file ./dasd/PALFP0.ckd: invalid track header for cyl 0 head 6 00 0E9C 0007
HHC00007I Previous message from function 'ckd_dasd_read_track' at ckddasd.c(1095)
HCPERP517I  DASD  0107 AN OPERATION WAS TERMINATED BECAUSE AN  
HCPERP517I  UNRECOGNIZED ERROR OCCURRED 
HCPERP6303I SENSE = INVALID 
HCPERP6304I IRB = 00C24017 7FFD50D0 0C001F88 00800000  
HCPERP6305I USERID = SFSPAL   
HCPERP2216I CHANNEL PATH ID = 01
HCPMHT2153I DASD  0107 I/O CANCELLED DUE TO A MISSING INTERRUPT
HHC01315I 0:0107 CHAN: ccw DE24E000 7FFD5008=>00000001 7834A000 00000001 78348000 ................
HHC01312I 0:0107 CHAN: stat 0E00, count 0000
HHC01313I 0:0107 CHAN: sense 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

The Troubleshooting

The CKD DASD File

The uncompressed CKD64 file in question was a 3390-1. Programatically, I performed a full scan of the CKD file to validate all track headers. All came back clean, and more importantly, the header that the HHC00418E message referenced was nowhere to be found. This made me confident that the issue is most likely within Hercules emulation of DASD rather than the Host Linux Filesystem corrupting the CKD file. Nonetheless, I proceeded to verify that the Linux host was not the culprit.

Linux and Filesystems

I was able to reproduce the error on both BTRFS and XFS filesystems. I reproduced the error while having I/O monitoring in place and was able to determine that while the hangup was occurring within Hercules, there were no device reads against the CKD file. The stalled I/O that z/VM and hercules was reporting never made it to the filesystem/kernel. Now it was time to get dirty and go deep into how Hercules handles CKD DASD.

Hercules

Prior to this point, I had reproduced the error countless times and I had noticed that my laptop fan would ramp up. Monitoring the CPU while I reproduced the error showed that during the hangup, a single core was constantly maxed out at 100%. This made me suspect something was looping. Sure enough, a thread monitor showed the clear signs of a cpu bound spin loop. I started incrementally adding some additional print statements within channel.c and ckddasd.c files, aiming to identify where the spin-loop was occuring. Finally, after many iterations, I found the root cause within the ckd_read_count function in ckddasd.c source. When performing a Read Any operation, the CCWs are completed one by one, decrementing dev->ckdlcount until it reaches a value of 1, which represents the final CCW of the domain. The Suffixed Read Count is now walking through the track’s records, reaching the end-of-track marker, and instead of finishing, it restarts its search forever.

Root Cause

There was indeed a spin loop occurring within ckd_read_count function of ckddasd.c. The function has the classic, unbounded loop at line 1786:

/* Search for next count field */
    for ( ; ; )
    {

An unbounded loop like this is not necessarily bad as long as you take into account all the possible edge cases to make sure you always have a condition that will trigger the breaking out of the loop. Unfortunately for my z/VM system, there is such an edge case. ckd_read_count function walks through the track’s records, until it reaches this section of code that is meant to handle LRE (Locate Record Extended):

 /*  ((( Something to do with LR/LRE Read Count Suffix?? )))  */
if (1 
      && IS_CCW_MTRACK( code )
      && (dev->ckdlaux & CKDLAUX_RDCNTSUF)
      && (0
          || dev->ckdlcount == 1
          || (0
              || (dev->ckdloper & CKDOPER_CODE) == CKDOPER_RDANY
              || (dev->ckdloper & CKDOPER_CODE) == CKDOPER_WRTANY
             )
         )
      &&  dev->ckdfcoun
    )
{
	memcpy( rechdr, dev->ckdfcwrk, CKD_RECHDR_SIZE );
    cyl  = fetch_hw( rechdr->cyl );
    head = fetch_hw( rechdr->head );
    if ((rc = ckd_seek( dev, cyl, head, NULL, unitstat )) < 0)
	    return -1;
    continue;
}

Before going into the issues with this piece of code within the search loop, let me explain what the code is doing currently.

The IF statement has 4 primary conditions that need to be meet:

Condition 1

#define IS_CCW_MTRACK(c)   (((c)&0x80))
IS_CCW_MTRACK( code )

IS_CCW_MTRACK is a bitwise AND, so it either evaluates to 0x80 (decimal 128) when the M/T bit is set, or to 0 when it isn’t. It relies on the C language convention that zero is treated as false, and any non-zero value as true. This is counter to many other programming languages where it is simply a 0 or 1. A command without the M/T bit set, is supposed to be confined to the current track. This means that it should either fail or wrap around on the same track if it fails to find what it is looking for before reaching the index point. A command with the M/T bit set, is allowed to advance to following tracks to continue its search operation.

Condition 2

(dev->ckdlaux & CKDLAUX_RDCNTSUF)

This is comparing the locate record aux byte with the Suffixed read count CCW. The LRE call that z/VM/CMS issued would set the suffix flg, and it only gets reset by the next locate record.

Condition 3

(0
  || dev->ckdlcount == 1
  || (0
	  || (dev->ckdloper & CKDOPER_CODE) == CKDOPER_RDANY
      || (dev->ckdloper & CKDOPER_CODE) == CKDOPER_WRTANY
      )
)

ckdlcount is the ’locate record count’, and it gets decremented oncer per CCW after the command handler returns. The last data operation is at count 2, so once it decrements to a value of 1, the guard is essentially testing that the current CCW is the suffix.

The other comparison within the OR statements is simply checking if the current operation is Read Any or Write Any, as in either of the two cases. wrap around handling would apply at any point, not just the suffix.

Condition 4

dev->ckdfcoun

This is set in the READ COUNT case hander. It stores off the data for the first read count in dev->ckdfcwrk and then sets dev->ckdfcoun to a value of 1, which means the first read count is done.

The Defect

The decrement of dev->ckdlcount within Condition 3 is found after the handler returns, so it was impossible for the value to change. In the print statements I added, it sat with a value of 1 for every iteration… all 9.13 billion iterations that occured…. Additionally, Condition 4 also is in a state of impossible change. The condition is there to make sure dev->ckdfcwrk is valid. So when all the 4 conditions are met, and the IF block is executed it consumes dev->ckdfcwrk without clearing dev->ckdfcoun:

memcpy( rechdr, dev->ckdfcwrk, CKD_RECHDR_SIZE );

It continues on to another defect:

 cyl  = fetch_hw( rechdr->cyl );
 head = fetch_hw( rechdr->head );
 if ((rc = ckd_seek( dev, cyl, head, NULL, unitstat )) < 0)
    return -1;

It is treating the Record ID, the saved count’s CCHH, as a physical address. This is incorrect, dev->ckdfcwrk is not where the record physically lives, it is supposed to be the data of the first read count, which is the record ID. This is causing the ckd_seek to incorrectly as it has no checks to enforce the Define Extent boundary. Because of this, it does not crash/abend. Real IBM Mainframe hardware would terminate the channel program with a File Protection error. Interestingly enough, Hercules does have an mt_advance function that enforces the Define Extent boundary, which would have caught the issue and thrown a SENSE1_FP (File Protection Exception).

I wager the reason this went undetected for so long is due to the following:

• Majority of hercules users are running older versions of OS, such as MVS 3.8, VM/370, etc. All of which use the DX+LR Read/Write CKD or track level operations instead of Read Any with suffix, which was implemented later on, primarily for z/VMs CP Minidisk Cache (MDC) and SFS Block I/O.
• The defect regarding Record IDs being treated as physical is actually correct by mistake for non virtualized systems, and even with z/VMs full-pack minidisks that begin at cylinder 0 instead of 1. So it would work for non z/VM systems, however in z/VM, CMS formats a minidisk record ID in minidisk relative coordinates. The CP is in charge of translating the extent and seek addresses whenever the guest performs I/O, however the IDs stored in the count fields on disk stay virtual! This was clearly represented in my additional logging I temporarily added to hercules for troubleshooting.

The Solution

The solution is actually very short/simply:

• Restore state from the saved count field, as if it had just been read.
• Remove the backward seek and continue statement
• Set the dev->ckdfcoun to a value of 0 once dev->ckdfcwrk is consumed
• Return the saved count as the CCW’s result Below is the new IF block in question:

 if (1
     && IS_CCW_MTRACK( code )
     && (dev->ckdlaux & CKDLAUX_RDCNTSUF)
     && (0
         || dev->ckdlcount == 1
         || (0
             || (dev->ckdloper & CKDOPER_CODE) == CKDOPER_RDANY
             || (dev->ckdloper & CKDOPER_CODE) == CKDOPER_WRTANY
            )
        )
     &&  dev->ckdfcoun
 )
 {
     memcpy( rechdr, dev->ckdfcwrk, CKD_RECHDR_SIZE );
     
     dev->ckdcurrec = rechdr->rec;
     dev->ckdcurkl  = rechdr->klen;
     dev->ckdcurdl  = (rechdr->dlen[0] << 8) + rechdr->dlen[1];
     dev->ckdrem    = 0;
     
     if (dev->ckdcyls < 32768)
         dev->ckdtrkof = (rechdr->cyl[0] == 0xFF) ? 0 : rechdr->cyl[0] >> 7;
     else
         dev->ckdtrkof = 0
         
     dev->ckdfcoun = 0;
     break;
 }

With these changes, the backward seek is entirely gone, with the loop termination guaranteed between correctly clearing dev->ckdfcoun as well as utilizing break instead of continue. The device state remains coherent now as well, as it is set from the returned count exactly as if it had been read from the track, and the orientation remains at the end of the track. The Read Count Suffix exists to tell the OS where a Read Any domain should continue to process. In the case for wrap-around operations, it would be the first record processed, which was saved in dev->ckdfcwrk.

If the issue was this spin loop, then why did we get error messages that mention invalid track headers, and missing interrupts?

That is because those errors are a side-effect/result of the spin loop. The infinite loop of the CCW never responds with an ending status, therefore z/VM fires the missing interrupt handler once the timeout is triggered.

HHC00418E 0:0107 CKD file ./dasd/PALFP0.ckd: invalid track header for cyl 0 head 6 00 0E9C 0007

The solution I described in this post fixed an edge case that caused the spin loop to occur which exposed this race condition. It does not however fix the underlying race condition. There could be other edge cases and scenarios where this race condition can resurface. However, that is out of scope for this fix, and it should be something that the Hercules maintainers and community discuss on the best and optimal way to fix and prevent the race condition.