CAC 2015-09-04

fromSource

Died with no message; running 03_build, was at ‘gm MR12.5plus MR12.5plus -dr -file’

0800  as   act_ctl_: Automatic update: users = 7, pf=8, vcpu=0.254, rt=0.314
Stopping IPC ... deleted 1 peers ... done

simCycles = 370840320820

cpuCycles = 185419706281
Master mode entry 1 faults = 8098
Fault tag 1 faults = 1
Timer runout faults = 277621
Connect faults = 31187
Illegal procedure faults = 10
Overflow faults = 3
Directed fault 0 faults = 31185
Directed fault 1 faults = 209111
Access violation faults = 5889
Fault tag 2 faults = 11770
start_sve.ini-57> boot iom0

Breakpoint, IC: 000012 (000312657220)
BCE DIE
Stopping IPC ... deleted 0 peers ... done
Goodbye
Debug output disabled
Log file closed
Stopping IPC ... deleted 0 peers ... done

The ‘Fault tag 1 faults = 1’ is interesting…
Can’t reproduce…

check_mst -file MR12.5plus
Begin checker
Read collection 0.5
Read collection 1.0
Read collection 1.2
Read collection 1.5
Read collection 2.0
Read collection 3.0
Begin Crossreference.
Checking collection 0.0.
Checking collection 1.0.
Error:  Linkage error by trace_catch_|2740
(>system_library_standard>bound_trace_)
referencing trace_error_halt_|trace_error_halt_
Segment not found.

There is no trace_error_halt_ segment anywhere in the Multics distribution…

Same failure with 'check_mst -tape 20184'

compare_mst -master_volume 20184 -copy_file MR12.5plus
Mounting tape 20184 for reading
Mounted Multics volume "12.5MULTICS_CF0019" (recorded at 800 BPI), on device ta
\cpa_02

Begin comparison.

Error:  Fixed point overflow by compare_mst$|12646 (line 859)
(>user_dir_dir>SysEng>Anthony>fromSource>work>bound_checker_)
system handler for error returns to command level
012646  aa  6 01777 0761 00   adq       pr6|1023
             if has_acl (COPY) = 1 then n_acls (COPY) = mst_ptr (COPY) -> mst2.n_acls (1);

012617  aa  6 00265 2361 17   ldq       pr6|181,7           has_acl
012620  aa   000001 1160 07   cmpq      1,dl
012621  aa   000033 6010 04   tnz       27,ic               012654
012622  aa   000004 2360 07   ldq       4,dl
012623  aa   000000 6260 06   eax6      0,ql
012624  aa  6 00465 2361 00   ldq       pr6|309             n_acls
012625  aa   000013 4020 07   mpy       11,dl
012626  aa   000001 0760 07   adq       1,dl
012627  aa  6 01776 7561 00   stq       pr6|1022
012630  aa  6 00465 2361 00   ldq       pr6|309             n_acls
012631  aa   000013 4020 07   mpy       11,dl
012632  aa   000001 0760 07   adq       1,dl
012633  aa  6 01776 1761 00   sbq       pr6|1022
012634  aa  6 01776 7561 00   stq       pr6|1022
012635  aa  6 00505 2361 00   ldq       pr6|325             path_length
012636  aa   000003 0760 07   adq       3,dl
012637  aa   000002 7320 00   qrs       2
012640  aa   000001 0760 07   adq       1,dl
012641  aa  6 00271 4021 00   mpy       pr6|185             has_branch
012642  aa  6 01777 7561 00   stq       pr6|1023
012643  aa  6 00467 2361 00   ldq       pr6|311             n_names
012644  aa   000011 4020 07   mpy       9,dl
012645  aa   000006 0760 07   adq       6,dl
012646  aa  6 01777 0761 00   adq       pr6|1023
012647  aa  6 01776 0761 00   adq       pr6|1022
012650  aa  6 00452 3515 36   epp1      pr6|298,6*          mst_ptr
012651  aa  1 00000 2361 06   ldq       pr1|0,ql            mst2.n_acls
012652  aa  6 00463 7561 17   stq       pr6|307,7           n_acls
012653  aa   000002 7100 04   tra       2,ic                012655
                                                            STATEMENT 1 ON LINE 860
 ldq       pr6|309             n_acls
v COPY
COPY = 2
v n_acls
n_acls (1) = 0
n_acls (2) = 
Q <-- 0
 mpy       11,dl
Q <--0 <--  0 * 11
 adq       1,dl
Q <-- 1 <-- 0 + 1
  stq       pr6|1022
  ldq       pr6|309             n_acls
Q <-- 0
  mpy       11,dl
Q <-- 0
  adq       1,dl
Q <-- 1
  sbq       pr6|1022
Q <-- 0 <-- 1 - 1
  stq       pr6|1022
  ldq       pr6|325             path_length
v path_length
path_length (1) = 32
path_length (2) = 
Q <-- 0
  adq       3,dl
Q <-- 3 <- 0 + 3
  qrs       2
Q <-- 0 <- 3 >> 2
  adq       1,dl
Q <-- 1
  mpy       pr6|185             has_branch
v has_branch
has_branch (1) and has_branch (2) = 1
Q <-- 1 <-- 1 * 1
  stq       pr6|1023
  ldq       pr6|311             n_names
v n_names
n_names (1) = 2
n_names (2) = 
Q <-- 0
  mpy       9,dl
Q <-- 0 <-- 0 * 9
  adq       6,dl
Q <-- 6 <-- 0 + 6
  adq       pr6|1023
Q <-- 7 <-- 6 + 1

Hardly likely to overflow…

DBG(1057254580)> CPU REGDUMPAQI: A=777777777773 Q=401122154006 IR:~BAR Neg

DBG(1057254582)> CPU TRACE: 00306:034125 4 601744076100 (ADQ PR6|1744) 601744 076(0) 1 0 0 00
DBG(1057254582)> CPU APPENDING: Read (Actual) Read:  iefpFinalAddress=61273604  readData=740041144221
DBG(1057254582)> CPU FAULT: Fault 13(015), sub 0(00), dfc N, 'adq overflow fault'
DBG(1057254582)> CPU FAULT: 00306:034125 4 601744076100 (ADQ PR6|1744) 601744 076(0) 1 0 0 00

Not the expected numbers…

Ahh; changed the arguments; crashes at a different location; it's doing MASTER, not COPY…

probe
sk
q
Condition fixedoverflow raised at line 829 of header_setup_1 (level 7).
 14          command_processor_
 13          release_stack
 12          unclaimed_signal
 11          wall
 10          any_other.2
  9          wall                                          error
  8          any_other.2
  7          header_setup_1 (line 829)                     fixedoverflow
  6          read_header (line 798)
  5          read_tape (line 1071)
  4          compare_mst (line 389)
  3          command_processor_
  2          listen_
  1          initialize_process_

                                                            STATEMENT 1 ON LINE 829
             if has_acl (MASTER) = 1 then n_acls (MASTER) = mst_ptr (MASTER) -> mst1.n_acls (1);

012371  aa  6 00265 2361 17   ldq       pr6|181,7           has_acl

DBG(852988598)> CPU TRACE: 00311:041001 4 600265236117 (LDQ PR6|265,7) 600265 236(0) 1 0 0 17
DBG(852988598)> CPU REGDUMPAQI: A=777777777773 Q=000000000001 IR:~BAR

012372  aa   000001 1160 07   cmpq      1,dl

DBG(852988600)> CPU TRACE: 00311:041002 4 000001116007 (CMPQ 000001,DL) 000001 116(0) 0 0 0 07

012373  aa   000033 6010 04   tnz       27,ic               012426

DBG(852988602)> CPU TRACE: 00311:041003 4 000033601004 (TNZ 000033,IC) 000033 601(0) 0 0 0 04

012374  aa   000002 2360 07   ldq       2,dl

DBG(852988604)> CPU TRACE: 00311:041004 4 000002236007 (LDQ 000002,DL) 000002 236(0) 0 0 0 07
DBG(852988604)> CPU REGDUMPAQI: A=777777777773 Q=000000000002 IR:~BAR Carry

012375  aa   000000 6260 06   eax6      0,ql

DBG(852988606)> CPU TRACE: 00311:041005 4 000000626006 (EAX6 000000,QL) 000000 626(0) 0 0 0 06

012376  aa  6 00464 2361 00   ldq       pr6|308             n_acls

DBG(852988608)> CPU TRACE: 00311:041006 4 600464236100 (LDQ PR6|464) 600464 236(0) 1 0 0 00
DBG(852988608)> CPU APPENDING: Read (Actual) Read:  iefpFinalAddress=61326324  readData=500000371520
DBG(852988608)> CPU REGDUMPAQI: A=777777777773 Q=500000371520 IR:~BAR Carry Neg

That's a lot of ACLs.

Watch 61326324… THat's not going to work; I won't be able to reliably predict the page Multics assigns.

I need 'swatch'. Sigh.

[[code]]

working backwards…

DBG(222344192)> CPU TRACE: 00311:041006 4 600464236100 (LDQ PR6|464) 600464 236(0) 1 0 0 00
DBG(222344192)> CPU APPENDING: Read (Actual) Read: iefpFinalAddress=61274324 readData=500000371520

BG(222337212)> CPU TRACE: 00311:041051 4 600464236100 (LDQ PR6|464) 600464 236(0) 1 0 0 00
DBG(222337212)> CPU APPENDING: Read (Actual) Read: iefpFinalAddress=61274324 readData=500000371

DBG(222337192)> CPU TRACE: 00311:041034 4 600463756117 (STQ PR6|463,7) 600463 756(0) 1 0 0 17
DBG(222337192)> CPU APPENDING: Write(Actual) Write: iefpFinalAddress=61274324 writeData=50000037152

The first one was offset 041006; the listing was offset 012376, so relocation is 041006-012376: 26410

The write is offset 041034, so 041034-26410: 12424 in the listing:

012424 aa 6 00463 7561 17 stq pr6|307,7 n_acls

Thats it the 'n_acls (MATER) =' from the previous time through the loop…

Go back to the full dump of the last few thousand instructions and work backwords…

working backwards.

The write:

DBG(833109666)> CPU TRACE: 00311:041034 4 600463756117 (STQ PR6|463,7) 600463 756(0) 1 0 0 17

The read:

DBG(833109664)> CPU TRACE: 00311:041033 4 100000236106 (LDQ PR1|0,QL) 100000 236(0) 1 0 0 06
DBG(833109664)> CPU APPENDING: Read (Actual) Read: iefpFinalAddress=60607667 readData=500000371520

offset 041033-26410: 12423
012423 aa 1 00000 2361 06 ldq pr1|0,ql mst1.n_acls

The write is out of the search window; making it bigger….

That's only time that memory location is referenced, so presumably the address calculation is in error…

DBG(833109662)> CPU REGDUMPAQI: A=000000000002 Q=025531025667 IR:~BAR
DBG(833109664)> CPU REGDUMPPR: PR1/ab: SNR=00314 RNR=4 WORDNO=000000 BITNO:00

70 dcl 1 mst1 aligned based (mst_ptr (1)), /* Format of an MST segment header */
71 2 header aligned,
72 3 header_control_word aligned,
73 4 collection_mark bit (18) unaligned, /* if non-zero, this is a 2-word collection mark only */
74 4 header_length fixed bin (17) unaligned, /* length of REST of header, not counting first 2 wds *

SNR of 0314 looks dandy, but the Q is somewhat suspicious…

Working back:

if has_acl (MASTER) = 1 then n_acls (MASTER) = mst_ptr (MASTER) -> mst1.n_acls (1);

012371 aa 6 00265 2361 17 ldq pr6|181,7 has_acl
012372 aa 000001 1160 07 cmpq 1,dl
012373 aa 000033 6010 04 tnz 27,ic 012426
012374 aa 000002 2360 07 ldq 2,dl
012375 aa 000000 6260 06 eax6 0,ql
012376 aa 6 00464 2361 00 ldq pr6|308 n_acls
012377 aa 000013 4020 07 mpy 11,dl
012400 aa 000001 0760 07 adq 1,dl
012401 aa 6 01747 7561 00 stq pr6|999
012402 aa 6 00464 2361 00 ldq pr6|308 n_acls
012403 aa 000013 4020 07 mpy 11,dl
012404 aa 000001 0760 07 adq 1,dl
012405 aa 6 01747 1761 00 sbq pr6|999
012406 aa 6 01747 7561 00 stq pr6|999
012407 aa 6 00504 2361 00 ldq pr6|324 path_length
012410 aa 000003 0760 07 adq 3,dl
012411 aa 000002 7320 00 qrs 2
012412 aa 000001 0760 07 adq 1,dl
012413 aa 6 00270 4021 00 mpy pr6|184 has_branch
012414 aa 6 01750 7561 00 stq pr6|1000
012415 aa 6 00466 2361 00 ldq pr6|310 n_names
012416 aa 000011 4020 07 mpy 9,dl
012417 aa 000006 0760 07 adq 6,dl
012420 aa 6 01750 0761 00 adq pr6|1000
012421 aa 6 01747 0761 00 adq pr6|999
012422 aa 6 00452 3515 36 epp1 pr6|298,6* mst_ptr
012423 aa 1 00000 2361 06 ldq pr1|0,ql mst1.n_acls
012424 aa 6 00463 7561 17 stq pr6|307,7 n_acls

012376 aa 6 00464 2361 00 ldq pr6|308 n_acls
DBG(833109622)> CPU TRACE: 00311:041006 4 600464236100 (LDQ PR6|464) 600464 236(0) 1 0 0 00
DBG(833109622)> CPU APPENDING: Read (Actual) Read: iefpFinalAddress=61266324 readData=000000000000
DBG(833109622)> CPU REGDUMPAQI: A=000000000000 Q=000000000000 IR:~BAR Carry Zero

012377 aa 000013 4020 07 mpy 11,dl
DBG(833109624)> CPU TRACE: 00311:041007 4 000013402007 (MPY 000013,DL) 000013 402(0) 0 0 0 07
DBG(833109624)> CPU REGDUMPAQI: A=000000000000 Q=000000000000 IR:~BAR Carry Zero

012400 aa 000001 0760 07 adq 1,dl
DBG(833109626)> CPU TRACE: 00311:041010 4 000001076007 (ADQ 000001,DL) 000001 076(0) 0 0 0 07
DBG(833109626)> CPU REGDUMPAQI: A=000000000000 Q=000000000001 IR:~BAR

012401 aa 6 01747 7561 00 stq pr6|999
DBG(833109628)> CPU TRACE: 00311:041011 4 601747756100 (STQ PR6|1747) 601747 756(0) 1 0 0 00

012402 aa 6 00464 2361 00 ldq pr6|308 n_acls
DBG(833109630)> CPU TRACE: 00311:041012 4 600464236100 (LDQ PR6|464) 600464 236(0) 1 0 0 00
DBG(833109630)> CPU REGDUMPAQI: A=000000000000 Q=000000000000 IR:~BAR Zero

012403 aa 000013 4020 07 mpy 11,dl
DBG(833109632)> CPU TRACE: 00311:041013 4 000013402007 (MPY 000013,DL) 000013 402(0) 0 0 0 07
DBG(833109632)> CPU REGDUMPAQI: A=000000000000 Q=000000000000 IR:~BAR Zero

012404 aa 000001 0760 07 adq 1,dl
DBG(833109634)> CPU TRACE: 00311:041014 4 000001076007 (ADQ 000001,DL) 000001 076(0) 0 0 0 07
DBG(833109634)> CPU REGDUMPAQI: A=000000000000 Q=000000000001 IR:~BAR

012405 aa 6 01747 1761 00 sbq pr6|999
DBG(833109636)> CPU TRACE: 00311:041015 4 601747176100 (SBQ PR6|1747) 601747 176(0) 1 0 0 00
DBG(833109636)> CPU APPENDING: Read (Actual) Read: iefpFinalAddress=61267607 readData=000000000001
DBG(833109636)> CPU REGDUMPAQI: A=000000000000 Q=000000000000 IR:~BAR Carry Zero

012406 aa 6 01747 7561 00 stq pr6|999
DBG(833109638)> CPU TRACE: 00311:041016 4 601747756100 (STQ PR6|1747) 601747 756(0) 1 0 0 00

012407 aa 6 00504 2361 00 ldq pr6|324 path_length
DBG(833109640)> CPU TRACE: 00311:041017 4 600504236100 (LDQ PR6|504) 600504 236(0) 1 0 0 00
DBG(833109640)> CPU REGDUMPAQI: A=000000000000 Q=000000000000 IR:~BAR Carry Zero

012410 aa 000003 0760 07 adq 3,dl
DBG(833109642)> CPU TRACE: 00311:041020 4 000003076007 (ADQ 000003,DL) 000003 076(0) 0 0 0 07
DBG(833109642)> CPU REGDUMPAQI: A=000000000000 Q=000000000003 IR:~BAR

012411 aa 000002 7320 00 qrs 2
DBG(833109644)> CPU TRACE: 00311:041021 4 000002732000 (QRS 000002) 000002 732(0) 0 0 0 00
DBG(833109644)> CPU REGDUMPAQI: A=000000000000 Q=000000000000 IR:~BAR Zero

012412 aa 000001 0760 07 adq 1,dl
DBG(833109646)> CPU TRACE: 00311:041022 4 000001076007 (ADQ 000001,DL) 000001 076(0) 0 0 0 07
DBG(833109646)> CPU REGDUMPAQI: A=000000000000 Q=000000000001 IR:~BAR

012413 aa 6 00270 4021 00 mpy pr6|184 has_branch
DBG(833109648)> CPU TRACE: 00311:041023 4 600270402100 (MPY PR6|270) 600270 402(0) 1 0 0 00
DBG(833109648)> CPU APPENDING: Read (Actual) Read: iefpFinalAddress=61266130 readData=000000000000
DBG(833109648)> CPU REGDUMPAQI: A=000000000000 Q=000000000000 IR:~BAR Zero

012414 aa 6 01750 7561 00 stq pr6|1000
DBG(833109650)> CPU TRACE: 00311:041024 4 601750756100 (STQ PR6|1750) 601750 756(0) 1 0 0 00

012415 aa 6 00466 2361 00 ldq pr6|310 n_names
DBG(833109652)> CPU TRACE: 00311:041025 4 600466236100 (LDQ PR6|466) 600466 236(0) 1 0 0 00
DBG(833109652)> CPU APPENDING: Read (Actual) Read: iefpFinalAddress=61266326 readData=164137164151
DBG(833109652)> CPU REGDUMPAQI: A=000000000000 Q=164137164151 IR:~BAR

That can't be good.

DBG(833109570)> CPU TRACE: 00311:040657 4 600465756117 (STQ PR6|465,7) 600465 756(0) 1 0 0 17

040657-26410: 12247
n_names (MASTER) = mst_ptr (MASTER) -> mst1.n_names;

012243 aa 000002 2360 07 ldq 2,dl
012244 aa 6 00452 3735 26 epp7 pr6|298,ql* mst_ptr
012245 aa 7 00005 2361 00 ldq pr7|5 mst1.n_names
012246 aa 000001 7270 07 lxl7 1,dl
012247 aa 6 00465 7561 17 stq pr6|309,7 n_names

012243 aa 000002 2360 07 ldq 2,dl
DBG(833109562)> CPU TRACE: 00311:040653 4 000002236007 (LDQ 000002,DL) 000002 236(0) 0 0 0 07
DBG(833109562)> CPU REGDUMPAQI: A=000003512471 Q=000000000002 IR:~BAR Carry

012244 aa 6 00452 3735 26 epp7 pr6|298,ql* mst_ptr
DBG(833109564)> CPU TRACE: 00311:040654 4 600452373526 (EPP7 PR6|452,QL*) 600452 373(1) 1 0 1 06
DBG(833109564)> CPU REGDUMPPR: PR7/sb: SNR=00314 RNR=4 WORDNO=000000 BITNO:00

012245 aa 7 00005 2361 00 ldq pr7|5 mst1.n_names
DBG(833109566)> CPU TRACE: 00311:040655 4 700005236100 (LDQ PR7|5) 700005 236(0) 1 0 0 00
DBG(833109566)> CPU APPENDING: Read (Actual) Read: iefpFinalAddress=61512005 readData=164137164151

Some one "out of segment" is setting that value; it changes across successive reads.
Okay, it's the buffer for reading the tape images into; iox_$get_chars is writing to it.

[[/code]]]

Unless otherwise stated, the content of this page is licensed under Creative Commons Attribution-ShareAlike 3.0 License