Race condition in RCF ADD leads to hung system or "Fault/Interrupt on prds" crash.

[canthony]

Ongoing work on increasing the resilience of Multics running on the dps8 simulator has identified several race conditions in the init_processor code. There race conditions are simulator specific as the code in question makes the reasonable assumption that the hardware CPUs all execute instructions at similar rates; however in the case of the simulator, resource contention and scheduling overhead can cause significant variation in the relative timing of individual simulated CPUs.

Historically, this was addressed with "stall points": specific instructions in the CPU boot processes were targeted, and when executed, were delayed in order for other CPUs to catch up. This solution was clumsy and unreliable, leading to the current effort to devise a better solution.

Ideally, the solution is to force all of the simulated CPUs to execute instructions in lockstep, but the overhead of this is prohibitive, so a viable subset solution was devised: forcing the CPUs to work in lockstep, but only when a CPU is being started.

Overhead was also reduced by defining "lockstep" as batches of approximately 512 instructions, and by only checking to see if lockstep mode has been order every 64 instructions.

Early testing was very promising; but RCF ADD would still occasionally fail. (The test being a .ini script that brings the system to "boot stan", and then does hundreds of RCF ADDs and DELETEs; and running stress-ng to starve the simulator of resources.)

Two failure modes were observed; first, Multics hanging after the CPU was started with RCF apparently waiting on the added CPU, and more rarely a "Fault/interrupt on prds" sys$trouble error.

The assumption was that there was an additional undetected race condition in the code. For testing, the simulator was tweaked to hold the CPUs in complete lock step (waiting for all CPUs to complete a single CPU cycle before proceeding to the next cycle) and keeping them in lock step until the newly added CPU enters the idle loop, If this configuration was robust, then that would be evidence that the init_processor algorithm did indeed have a race condition.

Surprisingly, Multics would still hang or crash.

Using dbg on the hung process, the PPRs of the CPUs was examined to try to identify what was hanging the system.

In this instance, the hung command was "RCF ADD CPU D"; CPUs A, B and C were running, and E had been deleted earlier and was in DIS wait state.

CPU A:

(gdb) p/o cpus[0].PPR
$1 = {PRR = 0, PSR = 042, P = 01, IC = 054}

42:54 is in page_fault:

    000052                         306  ptl_repeat:
    000052  aa  3 00020 3541 00    307          stac    sst|sst.ptl     hurry up and wait
    000053  aa   000000 0110 00    308          nop
    000054  aa   000000 0110 00    309          nop
    000055  0a   000070 6010 00    310          tnz     ptlfail         locked, see if wait needed
                                   311          read_clock
    000056  4a  4 00026 6331 20                   rccl  sys_info$clock_,*
                                        "       ifend
                                        "         rccl  0
                                        "       ifend
    000057  4a  4 00032 1771 20    312          sbaq    pds$arg_1
    000060  aa  3 00156 0771 00    313          adaq    sst|sst.loop_lock_time
    000061  aa  3 00156 7571 00    314          staq    sst|sst.loop_lock_time
                                   315          increment       sst|sst.loop_locks      meter times we had to loop lock
                                                missing increment,sst|sst.loop_locks
    000062  aa  3 00154 0541 00                 aos     sst|sst.loop_locks
    000063                         316  ptl_ok:

CPU A is handling a page fault.

CPU B:

(gdb) p/o cpus[1].PPR
$3 = {PRR = 0, PSR = 042, P = 01, IC = 052}

CPU B is in the same code.

CPU C:

(gdb) p/o cpus[2].PPR
$4 = {PRR = 0, PSR = 042, P = 01, IC = 036615}

42:36615 is in bound_page_control:cam_cache:000125

    000121  aa   001750 2350 07    236          lda     1000,dl         bail-out of loop limit
    000122  4a  4 00050 3715 20    237          epplb   scs$fast_cam_pending array of check-off cells
    000123  aa   000001 1750 07    238  wait:   sba     1,dl            one more loop
    000124  0a   000103 6040 00    239          tmi     repeat          try entire cycle again
    000125  aa   000140 1064 00    240          cmpc    (),(pr,rl),fill(0)      check entire array clear
    000126  aa   000000 000000     241          desc9a  0,0
    000127  aa   500000 000006     242          desc9a  lb|0,ql

CPU D (the newly added CPU)

(gdb) p/o cpus[3].PPR
$5 = {PRR = 0, PSR = 061, P = 01, IC = 0275}

61:275 is in init_processor:

    000273  4a  4 00054 2343 20    312          szn     scs$connect_lock  connect lock cleared? 
    000274  0a   000300 6002 00    313          tze     *+4             if so, exit loop
    000275  aa   000110 7772 00    314          llr     72              wait for a while 
    000276  aa   000110 7772 00    315          llr     72              ..      
    000277  0a   000273 7102 00    316          tra     *-4             ..

Summary:

A: Handling a page fault
B: Handling a page fault
C: Attempting to clear CAM on all processors
D: Spinning on connect_lock

The race condition stems from the fact the cam_cache code uses connect_lock to synchronize the CAM clearing operation across the CPUS, and init_processor uses connect_lock to synchronize a newly added processor.

It appears that there is some periodic background process that will cause a CAM cache clear and that if you do many RCF ADDs, and you starve resources in such a way that the amount of wall clock time spent in init_processor is more likely to overlap whatever periodic event is leading to the CAM cache clear, you can create a Multics resource conflict.

It would appear that there is insufficient locking around the use of connect_lock, allowing cam_cache and init_processor to run at the same time, causing misuse of connect_lock.

It it hypothesized that the "Fault/interrupt of prds" crash is of a similar nature; the timing being slightly different so as to cause a different winner in the race.

[Eric Swenson]

Do we know of a way to reproduce this hang?

[canthony]

I have been able to reproduce the Fault/Interrupt on prds crash with history debugging, and have found a plausible story that this is actually a simulator issue, and not a Multics issue. (Other than Multics relying on timing.)

[canthony]

I invoke the hang or crash with a .ini file that brings Multics up to stan and then does

autoinput rcf delete cpu b\n
autoinput rcf delete cpu c\n
autoinput rcf delete cpu d\n
autoinput rcf delete cpu e\n
autoinput rcf add cpu b\n
autoinput rcf add cpu c\n
autoinput rcf add cpu d\n
autoinput rcf add cpu e\n

a couple of hundred times.

While it is grinding away at that, I run:

stress-ng --cpu 6 --syncload 32 --syncload-msbusy 2000 --syncload-mssleep 500

It may take several tries to get it to fail.

[canthony]

I have been unable to get the prds crash when running HDBG, so I cannot give a detailed analysis of the events leading up to the crash. I have succeeded in doing a "dump -long" and am attaching a backup_dump of >dumps.

Humm. Too big to attach.

Link to dumps.tap: ​https://drive.google.com/file/d/1aSvFNauElEJJiqsL9WQWuCjTm66XO9DB/view?usp=drive_link

[canthony]

The crash has been tracked down to a simulator bug.