Opened 5 years ago
Closed 17 months ago
#228 closed defect (fixed)
Multics may crash due to Overflow Fault in scheduler (pxss.alm)
| Reported by: | Gary Dixon | Owned by: | Eric Swenson |
|---|---|---|---|
| Priority: | major | Milestone: | MR12.9 |
| Component: | Hardcore | Version: | MR12.6f |
| Keywords: | Cc: |
Description (last modified by )
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.
Change History (14)
comment:1 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:3 by , 5 years ago
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.
comment:4 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:5 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:6 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:7 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:8 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:9 by , 3 years ago
I got this same error after suspending my laptop with a running Multics. The code that overflowed is doing math based on "number of microseconds that have elapsed since pxss last ran on this CPU", so I am thinking that in my case, number was something along the line of "6 hours in useconds", which led to an overflow in the elapsed time calculation, leading to an overflow in the accumulated time. I don't know it the above reported case was a suspend incidence, but given that this bug seems to be unknown in the long term running production systems, suspending seems a likely root cause. So I would think that the fix would be to do a sanity check on the initial "elapsed time since pxss ran" calculation, clamping it to a small multiple of the scheduling quantum.
comment:10 by , 3 years ago
My understanding of the "compute_virtual_clocks" is that it is trying to determine if a process was interrupted (either external or fault) prior to the expiration of its scheduling quantum, allowing tracking of actual CPU usage rather than scheduled.
This code assumes that CPUs run at a constant, fixed rate and thus CPU usage can be measured with wall clock time. Unfortunately in the simulator this is not a valid assumption. CPU threads are subject to the vagaries of the host scheduler can can stall due to local events such as resource starvation and global events such as system suspension or hiberation.
If I am understanding compute_virtual_clocks() correctly, the longest "delta_t" should be a scheduler quantum: 1/4 second.
I have instrumented up a simulator to print the values saved in "delta_t" on a 5 CPU system. On an idle system, delta_t is calculated as ~250,000 uSeconds, as predicted.
A "alm -list pxss" produced varying values from 280 to250,000 us. (as expected from the above model), plus a few large values ranging from 265,116 to 763,125 us.
I am guessing that the large numbers are due to I/O being done in the CPU thread plus host paging overhead; the numbers seem large but not implausible. (I possible further test would be to track what process was being timed; if the large times correlate with I/O performing processes, that would support this hypothesis.)
I then suspended the simulator for 10 seconds; the next 5 delta_t values were on the the order of 10 seconds, supporting the hypothesis that simulator suspension can cause inappropriately large delta_t values, and is the root cause of the reported crash.
Looking at the scheduling code, I see
tc_data.cds: tc_data.process_initial_quantum = 2000000;
Under some circumstances, a process will be granted a 2 second quantum; this may explain some of the greater than 1/4 second numbers I observed.
Also:
guaranteed_eligibility_on:
eppbp pds$apt_ptr,* set bp-> own apte
lda apte.prior_sched,dl Turn on high priority mode
orsa bp|apte.flags2
lda 4,du Boost time slice
asa bp|apte.temax
This would add about 1 second to the quantum.
Rummaging further through the code, I find that ed_mgt can set quanta for a work class, so it is less clear what a maximum quantum could be.
If I understand the code correctly, the scheduled quantum is in apte.temax.
If this is correct, then I propose the following fix to pxss.alm compute_virtual_clocks:
Original code:
read_clock
staq bb|last_time save last time anyone run
sbaq prds$last_recorded_time delta t in microseconds
staq delta_t
Proposed code:
read_clock
staq bb|last_time save last time anyone run
sbaq prds$last_recorded_time delta t in microseconds
cmpa 0,dl has delta_t overflowed 36 bits?
tnz delta_ov yes
cmpq bp|apte.temax is delta_t larger then scheduled?
tnc delta_ok no
delta_ov: lda 0,dl set delta_t to scheduled
ldq bp|apte.temax
delta_ok: staq delta_t
(This off-the-cuff and totally untested.)
comment:11 by , 3 years ago
Test the "delta T" too large hypothesis.
I added a hack to the simulator to allow the interception of the SBAQ instruction that calculates the Delta T and replace the result of the calculation with a specified value.
Multics code to be intercepted:
004300 3893 compute_virtual_clocks:
...
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
Code to set the intercept:
{"DELTAT", setDeltaT, 0, "Delta T\n", NULL, NULL },
word36 deltaT;
static t_stat setDeltaT (UNUSED int32_t arg, const char * buf) {
if (! buf)
return SCPE_ARG;
word36 n = strtoul (buf, NULL, 0);
deltaT = n;
sim_printf ("deltaT set to %lu(%lo)\n", deltaT, deltaT);
return SCPE_OK;
}
The intercept code:
case x0 (0177): // sbaq
{
// C(AQ) - C(Y-pair) -> C(AQ)
L68_ (cpu.ou.cycle |= ou_GOS;)
HDBGRegAR ("sbaq");
HDBGRegQR ("sbaq");
bool ovf;
word72 tmp72 = YPAIRTO72 (cpu.Ypair);
tmp72 = Sub72b (convert_to_word72 (cpu.rA, cpu.rQ), tmp72, 1,
I_ZNOC, & cpu.cu.IR,
& ovf);
convert_to_word36 (tmp72, & cpu.rA, & cpu.rQ);
extern word36 deltaT;
if (cpu.PPR.PSR == 044 && cpu.PPR.IC == 0004307 && deltaT) {
cpu.rQ = deltaT;
deltaT = 0;
sim_printf ("sbaq sets Q to %lu(%lo)\n", cpu.rQ, cpu.rQ);
}
Test run:
M-> CONSOLE: RELEASED 1743 rdra Card input started. 1743 rdra rdra: ***** Device Attention. 1743 rdra ***** Hopper empty or Stacker full. 1743 rdra 1743 prta prta driver: No requests, driver is idle. ^S DPS8M> deltat 0400000000000 deltaT set to 34359738368(400000000000) sbaq sets Q to 34359738368(400000000000) 0145.2 initializer: 4009 scas_init state 1 phase 4. 0145.2 initializer: 4010 tc_init$early state 1 phase 4. 0145.2 initializer: 4011 init_sst$early state 1 phase 4. 0145.2 initializer: 4012 disabling slt allocation state 1 phase 4. 0145.2 initializer: 4013 initialize_faults$interrupt_init state 1 phase 4. 0145.2 initializer: 4016 load_disk_mpcs state 1 phase 4. 0145.2 initializer: 4017 init_pvt state 1 phase 4. 0145.2 initializer: 4018 read_disk$init state 1 phase 4. 0145.2 initializer: 4019 init_root_vols state 1 phase 4. 0145.2 initializer: 4020 establish_temp_segs state 1 phase 4. 0145.2 initializer: 4021 find_file_partition state 1 phase 4. 0145.2 initializer: 4025 load_mst$init_commands state 1 phase 4. 0145.2 initializer: 4028 scs_and_clock_init$date_time state 1 phase 4. 1745.2 initializer: 4029 io_config_init state 1 phase 4. 1745.2 initializer: 4030 ioi_init state 1 phase 4. 1745.2 initializer: 4032 bce_get_to_command_level state 1 phase 4. CONSOLE: ALERT sys_trouble: Fault in idle process. bce (crash) 1745.2:
comment:12 by , 3 years ago
Testing proposed fix:
lf pxss.alm
Edit pxss.alm
cpa pxss.alm.orig pxss.alm A3903 staq delta_t Changed by B to: B3903 cmpa 0,dl has delta_t overflowed 36 bits? B3904 tnz delta_ov yes B3905 cmpq bp|apte.temax is delta_t larger then scheduled? B3906 tnc delta_ok no B3907 delta_ov: lda 0,dl set delta_t to scheduled B3908 ldq bp|apte.temax B3909 delta_ok: staq delta_t Comparison finished: 1 difference, 8 lines.
Build
alm -list pxss lf -library ** bound_tc_priv.archive ac ud bound_tc_priv pxss bind bound_tc_priv
Get a local copy of hardcore.search. Edit it, adding the cwd at the top.
pr hardcore.search >user_dir_dir>SysAdmin>Repair>deltat >ldd>hard>execution >ldd>firmware
Get a local copy of hardcore.header
cp >ldd>hardcore>info>hardcore.header
Generate tape
gm hardcore deltat -dr
Examine hardcore.list and verify that the new version of pxss was used:
bound_tc_priv 04/22/23 1243.9 Repair.SysAdmin.a binder >user_dir_dir>SysAdmin>Repair>deltat pxss 04/22/23 1242.6 Repair.SysAdmin.a alm meter_response_time 05/11/19 1505.4 Swenson.SysAdmin.a alm
Boot with deltat.tap:
bootload_0: Booting system hardcore generated 04/22/23 1338.4 pst Sat.
Test:
DPS8M> deltat 0400000000000 deltaT set to 34359738368(400000000000) sbaq sets Q to 34359738368(400000000000)
No crash.
comment:13 by , 17 months ago
| Milestone: | → MR12.9 |
|---|---|
| Status: | new → accepted |
comment:14 by , 17 months ago
| Resolution: | → fixed |
|---|---|
| Status: | accepted → closed |
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.