Multics may crash due to Overflow Fault in scheduler (pxss.alm)

[Gary Dixon]

This bug description resulted from dump analysis of a system crash on Eric Swenson's GHM system on March 1, 2021. Details of the dump analysis will be attached as later comments to this bug description.
GHM was running in a 2-CPU Multics configuration with a near R2.0 version of the dps8 simulator.

The Multics process scheduler (pxss.alm) maintains a "bank account" of quantum credits that it doles out to work classes containing at least one ready-to-run process in its work class queue. These credits are refreshed on a per-CPU basis each time the scheduler is invoked on that CPU. The pxss label "compute_virtual_clocks" is preceded by a comment suggesting its purpose is to split idle CPU time among the various categories of idle. However, one of its initial functions is to measure the number of microseconds that have elapsed since pxss last ran on this CPU, and to add those microseconds (which it calls delta_t) to the tc_data|governing_credit_bank: a one-word data field manipulated as a signed fixed bin(35) integer by the referencing instructions.

The ALM listing for the code in question is shown below.

    004300                        3893  compute_virtual_clocks:
    004300  4a  4 00152 3521 20   3894            eppbp     pds$apt_ptr,*       set bp to this process
    004301  4a  4 00262 2351 20   3895            lda       pds$page_waits      copy page fault count into APT entry
    004302  aa  2 00002 7551 00   3896            sta       bp|apte.page_faults
    004303  aa  2 00046 2371 00   3897            ldaq      bp|apte.virtual_cpu_time Remember bp's vcpu
    004304  aa  6 00134 7571 00   3898            staq      temp                Use temp for delta virtual time.
                                  3899
                                  3900            read_clock
    004305  4a  4 00104 6331 20                   rccl      sys_info$clock_,*
    004306  aa  3 00034 7571 00   3901            staq      bb|last_time        save last time anyone run
    004307  4a  4 00324 1771 20   3902            sbaq      prds$last_recorded_time delta t in microseconds
    004310  aa  6 00154 7571 00   3903            staq      delta_t
    004311  aa  3 00451 0561 00   3904            asq       bb|governing_credit_bank

Beginning at line 3900, the read_clock macro reads the system's calendar clock into the AQ register as a signed fixed bin(71) integer. It saves this clock reading into tc_data|last_time to record when the scheduler last ran on any processor. It then subtracts from this time stamp the value prds$last_recorded_time: the time at which the scheduler last ran on this processor. This gives a delta_t value: the microseconds of quanta which is also a signed fixed bin(71) integer value. [See lines 3902-3903 above.]

The problem occurs in the ASQ instruction on line 3904. That instruction uses signed arithmetic to add two single-word integers together: C(Q) + C(Y) -> C(Y). In this case, Y is the address of tc_data|governing_credit_bank, a fixed bin(35) signed value. Q contains the right word of delta_t: a double-word fixed bin(71) value. The right-word is effectively an unsigned fixed bin(36) integer. But the ASQ instruction treats Q as a signed fixed bin(35) value, with the left-most bit in this word being the sign bit.

In situations where that sign bit is "1"b, the ASQ instruction adds a negative value to the previous tc_data|governing_credit_bank, often causing it to become negative. Code which assigns those credits (see pxss.alm line 2963++) ignores assignment of credits if the bank value is negative. Thus the negative tc_data|govern_credit_bank value remains negative when scheduling ends on that CPU.

The next time the scheduler runs on that CPU, if the delta_t value has a right-word storage that again looks like a negative integer, that negative value again gets added to the still-negative tc_data|governing_credit_bank value. This process can continue until the ASQ instruction overflows the negative range of the fixed bin(35) signed storage space. ASQ then turns on the Overflow indicator bit. And since the Overflow Mask indicator bit is off, an Overflow Fault is also triggered.

That scenario (or some variant) caused an Overflow Fault while running in ring-0, producing the GHM system to crash.

[Gary Dixon]

The following data describes results of the dump analysis that identified the issue described above.

The dump reports an Overflow fault in the scheduler (pxss|4311).

azm:  why

Crash Message:
    sys_trouble: Fault while in masked environment.

Inconsistency found in Dump Associative Memories.
          Bootload cpu is a
Fault while in masked environment
Overflow Fault (33)
By: 44|4311  bound_tc_priv$pxss|4311
Ref: 112|451  tc_data|451
          (rev) prev_sp not valid 231|7720 for frame 72|1220

pxss is at the base of bound_tc_priv bound segment, according to the .bindmap of that seg.

A listing generated by compiling pxss.alm shows the following instructions:

    004300                        3893  compute_virtual_clocks:
    004300  4a  4 00152 3521 20   3894            eppbp     pds$apt_ptr,*       set bp to this process
    004301  4a  4 00262 2351 20   3895            lda       pds$page_waits      copy page fault count into APT entry
    004302  aa  2 00002 7551 00   3896            sta       bp|apte.page_faults
    004303  aa  2 00046 2371 00   3897            ldaq      bp|apte.virtual_cpu_time Remember bp's vcpu
    004304  aa  6 00134 7571 00   3898            staq      temp                Use temp for delta virtual time.
                                  3899  
                                  3900            read_clock
    004305  4a  4 00104 6331 20                   rccl      sys_info$clock_,*
    004306  aa  3 00034 7571 00   3901            staq      bb|last_time        save last time anyone run
    004307  4a  4 00324 1771 20   3902            sbaq      prds$last_recorded_time delta t in microseconds
    004310  aa  6 00154 7571 00   3903            staq      delta_t
    004311  aa  3 00451 0561 00   3904            asq       bb|governing_credit_bank
                                  3905
    004312  aa  2 00016 0771 00   3906            adaq      bp|apte.time_used_clock update time used in APT
    004313  aa  2 00016 7571 00   3907            staq      bp|apte.time_used_clock
    004314  4a  4 00260 1771 20   3908            sbaq      pds$virtual_delta   update the virtual CPU time
    004315  aa  2 00046 7571 00   3909            staq      bp|apte.virtual_cpu_time


Events show the fault was recorded in pds$signal_data:

azm:  events
Events from 03/01/21  6:28:54.616112
    Time  CPU Proc Event                           Circumstances

54.616112  a       Fault:  DRL                     RTB Machine Conditions
  .098015  b    0  Fault:  CON                     prds$sys_trouble_data
  .097967  a    6  Fault:  CON                     prds$sys_trouble_data
  .097922  a    6  Fault:  OFL                     pds$signal_data


Machine conditions stored at that location for the fault show contents of 
A and Q registers, as well as other regs used in code just before the fault.

azm:  mc pds$signal_data -long
Machine Conditions from (71|140) pds|140.
Pointer Registers:
   PR0 (ap) - 16|17514    as_linkage|17514
   PR1 (ab) - 231|7720    >pdd>!BLbCjxZbBBBBBB>stack_1|7720
   PR2 (bp) - 112|4200    tc_data|4200
   PR3 (bb) - 112|0       tc_data|0
   PR4 (lp) - 17|2612     ws_linkage|2612
   PR5 (lb) - 44|343      bound_tc_priv$pxss|343
   PR6 (sp) - 72|1220     prds|1220
   PR7 (sb) - 72|0        prds|0
Processor Registers:
   X0 - 1 X1 - 0 X2 - 4200 X3 - 3123
   X4 - 2 X5 - 0 X6 - 3344 X7 - 3406
   A Register - 000000000000  Q Register - 451307070725  E Register - 0
   Timer Register - 402022035 Ring Alarm Register - 0
Overflow Fault (33)
SCU Data:
By: 44|4311  bound_tc_priv$pxss|4311
Ref: 112|451  tc_data|451
On: cpu a (#0)
Indicators:  cary, ovfl, ^bar
APU Status:  priv, xsf, sd-on, pt-on, fabs
Instructions:
 14650   3 00451 0561 00      asq       pr3|451
 14651   3 00451 0561 00      asq       pr3|451
Mem Controller Mask: 000230000043 000400000000
MC Fault Time: 21-03-01 06:28:54.97922 pst Mon  (153615605450112002)
Setting Temporary pointers from 71|140.


Notice from code before the fault that Q results from reading the clock, 
which was stored in tc_data.last_time

azm:  d bb -as tc_data.last_time 
  last_time = 3792061734097910   2021-03-01 06:28:54.097910 pst

or in octal...

azm:  d pr3|34 2
Segno 112 tc_data|34

    34      0 000000153615 605450111766

and subtracting from that the last recorded time at which scheduler was 
invoked on processor A  (prds$last_recorded_time).

azm:  d prds$last_recorded_time 2
Segno 72 prds|332

   332      0 000000153615 134141021041

The Q shown in the machine conditions above holds the correct subtraction value.  
Note that this is right word of a double-word (long long or fb(71)) integer and 
is therefore unsigned.

Q Register-  451307070725

Source shows Q being added to bb|governing_credit_bank (tc_data|451)
which is a positive integer after the ASQ instruction ran.  But it is difficult 
to determine its value before that addition occurred.  I suspect it was a 
negative value.

azm:  d pr3|451 -octal
Segno 112 tc_data|451

   451      0 122615176160

However, the asq instruction (which was executing when the Overflow Fault 
occurred) is performing signed arithmetic.  Since the sign-bit is ON in the 
Q register, a large negative quantity is being added to an unknown (probably 
negative) value. The result must have been a very large negative value which
overflowed the negative end of the fixed bin(35) integer range.
The Overflow (ovfl) indicator is set in the Indicators; and an Overflow fault 
was triggered because the Overflow Mask indicator (oflm) is NOT set in the 
Indicators recorded in the machine conditions.  

[Gary Dixon]

Any solution to this issue must do two things:

• Find a better way to interpret a large value in a fixed bin(36) unsigned word AS a signed fixed bin(35) value.
  • Test whether Q is negative. If so, jump to code which sets tc_data|governing_credit_bank to the largest possible integer value (377777777777 octal).
• Protect the ASQ addition from possible Overflow Faults by:
  • Setting the Overflow Mask indicator before issuing the ASQ.
  • Checking for an Overflow indicator after the ASQ instruction ends. If one has occurred, then set tc_data|governing_credit_bank to the largest possible integer value (377777777777 octal).

While this solution would keep tc_data|governing_credit_bank non-negative and avoid possible Overflow Fault in ring 0, it could have adverse affect on the scheduler algorithms. pxss code has probably never run in situations where tc_data|governing_credit_bank values equaled the largest possible positive integer value. Without understanding details of the work class scheduling algorithm, it is impossible to predict what impact this change might have on overall scheduling of Multics processes onto processors.

Prediction of impact is more difficult because the simulated calendar clock rate provided by the dps8 simulator is thought to be running much faster than the calendar clock in real Multics hardware. This difference between real-world versus simulated passage of time can impact Multics code in situations such as are described in this issue. Multics storage words and double-worded may not be large enough to handle the faster clock rates provided in the simulated dps8 system. Processes may be getting many more simulated "microseconds" of quantum in which to execute that they would have on real Multics hardware. Time-related variables might reside in storage that has too few bits to correctly track such increase quanta sizes.