QNice sometimes hangs on MOVE @R5++, R12 after reset

[Rhialto]

I'm just reporting this here to make sure that the details I researched so far get recorded.

In v0.000012 of the MegaPET core I changed the storage of the floppy disk images to HyperRAM. I suspect this issue is related. I mentioned it in the discord, so I'll just copy it here.

Sometimes when resetting the core, it doesn't reset properly, and sometimes (quite rarely) it doesn't even work when long-resetting it (until the power LED goes blue). I thought I had found some circumstances when this could happen, but it wasn't repeatable enough to debug so far. At first it seemed related to setting the 8296 memory to userport-control, and later
I thought it might be related to having a disk image inserted in the disk, but neither proved very repeatable.

For reference: when the reset doesn't complete, I have seen the QNice PC stuck at address $1EFE. That seems to correspond to this code. Meanwhile, the HELP key is unresponsive (I have learned that this usually means that QNice is busy with something else).

    007278                    ; Handle read request from drive number in R8:
    007279                    ;
    007280                    ; Transfer the data requested by the core from the linear disk image buffer
    007281                    ; to the internal buffer inside the core
    007282                    ;
    007283                    ; @TODO: Sanity check as described in vdrives.vhd protocol comment (3)
    007284  1ECE  FF90  005E  HANDLE_DRV_RD               ASUB enter, 1
    ...
    007314  1EF5  C600        _HDR_SEND_LOOP              CMP R6, R0                       ; transmission done?
    007315  1EF6  FFA3  0025                              RBRA _HDR_SEND_DONE, Z           ; yes
    007316
    007317  1EF8  0FA4  81DA                              MOVE VDRIVES_BUFS, R9            ; array of buf RAM device IDs
    007318  1EFA  1B24                                    ADD R11, R9                      ; select right ID for vdrive
    007319  1EFB  094D                                    MOVE @R9, @R3                    ; select device
    007320  1EFC  0111                                    MOVE R1, @R4                     ; select window in RAM
    007321  1EFD  05B0                                    MOVE @R5++, R12                  ; R12=next byte from disk img
    007322
    007323  1EFE  0FA0  7005                              MOVE VD_B_ADDR, R8               ; write buffer: address
    007324  1F00  0624                                    MOVE R6, R9
    007325  1F01  FFB0  2921                              RSUB VD_CAD_WRITE, 1
    007326
    007327  1F03  0FA0  7006                              MOVE VD_B_DOUT, R8               ; write buffer: data out
    007328  1F05  0C24                                    MOVE R12, R9
    007329  1F06  FFB0  291C                              RSUB VD_CAD_WRITE, 1

where I assume that the PC has already increased to the next instruction but the CPU is somehow stuck on the MOVE @R5++, R12.

So I'm getting a bit of a suspicion it is about the disk image which is now in Attic RAM.

Looking though the various vhdl files, there is the signal s_qnice_wait_o from each entity work.qnice2hyperram that eventually (if I traced it right) reaches /M2M/vhdl/QNICE/qnice.vhd where it is connected to entity work.QNICE_CPU as WAIT_FOR_DATA => cpu_wait_for_data or ramrom_wait_i,.

I suspect that the MOVE instruction is waiting for that (but I haven't put a 'scope on that to prove it yet).

As to why the s_qnice_wait_o might be active for "ever", I have no clue yet. Too much contention on the hyperram? The display meanwhile goes on fine, and so does the PET, as long as you don't try to access the disk.

Here is how I use the hyperram, which I hopefully correctly cribbed from the POC for the C64 core: https://github.com/Rhialto/PET_MEGA65/blob/v0.00012/CORE/vhdl/mega65.vhd#L681

[MJoergen]

I think your analysis is sound, i.e. that the QNICE CPU is waiting for a memory access to complete. You can debug further by tracing the hr_core_* signals in mega65.vhd. Really only the write_o, read_o, and waitrequest_i signals are needed.

[Rhialto]

I made some screenshots of the state after a reset where something hang. I added mark_debug to a few more signals than the ones you mentioned, in the hope that we can see where they are coming from.

In the first case, not even the PET startup message appeared (which may mean it is a different case than what I'm interested in here). I have 2 pictures because there are 2 clocks involved but all these signals are stable at this time:

and here is a later attempt that did get to the startup screen, but the drive LED is on (this drive signals internal activity on the drive LED as well, I think) and the HELP key isn't functional.

Note that in the second case, second image, qnice_dev_wait_o is true apparently from qnice_pet_mount0_buf_ram_wait. This would be generated from qnice_disk0_waitrequest in i_qnice2hyperram_d0, but in that signal appears to be 0.

I think I should add the qnice PC to the debug set to double-check if we're looking at the right cases.

[sy2002]

@MJoergen and @Rhialto We never tried that QNICE accesses HyperRAM. This is "a first". Just to rule out "simple" things: QNICE is reading/writing from/to memory on falling edges and might it be that Michael's QNICE/HyperRAM RAM adaptor is acting/expecting rising edges and therefore we get lock-ups from time to time (maybe in cojunction with Clock-Domain-Crossing phenomenon)?

[Rhialto]

For something that was never tried before it works very well indeed :) It is just failing on some edge case, so far.

Just some more ramblings.

Interesting note about the falling edge of the clock. While browsing I noticed in M2M/vhdl/framework.vhd that there is a comment -- Clock domain crossing: QNICE to HR using a i_avm_fifo_qnice : entity work.avm_fifo and avm_fifo which receives as clock s_clk_i => qnice_clk,. It seems to end up using ~/tools/Xilinx/Vivado/2024.1/data/ip/xpm/xpm_fifo/hdl/xpm_fifo.sv which only has posedge and never negedge, for both rd_clk and wr_clk.

There are similar qnice2hr_d0_avm_fifo : entity work.avm_fifo used in CORE/vhdl/mega65.vhd which receive qnice_clk_i.

The i_qnice2hyperram_d0 : entity work.qnice2hyperram is also used there. That uses falling_edge(clk_i) internally so that seems ok.

So, if avm_fifo internally uses only posedge, but qnice acts on the falling edge of qnice_clk_i, then naively I think that inverting this clock when feeding it to avm_fifo would improve things. So I changed that in the avm_fifos in mega65.vhd (the ones attached to the disk images). That didn't immediately break the disk access, but after a few tries the problem could still be reproduced anyway.

   qnice2hr_d0_avm_fifo : entity work.avm_fifo
      generic map (
         G_WR_DEPTH     => 16,
         G_RD_DEPTH     => 16,
         G_FILL_SIZE    => 1,
         G_ADDRESS_SIZE => 32,
         G_DATA_SIZE    => 16
      )
      port map (
         s_clk_i               => not qnice_clk_i,	-- invert clock since qnice acts on falling edge

(and the same for d1)

I set mark_debug on some other wait request signals in i_framework around i_avm_arbit_general : entity work.avm_arbit_general. It seemed that while some of its outputs said "wait", its input didn't, but for some reason I did not get to see all outputs. (hr_core_waitrequest_o might have been no-wait).

Meanwhile in mega65.vhd, we can see that qnice_pet_mount0_buf_ram_wait is 1 (coming out the qnice2hyperram) but the related input qnice_disk0_waitrequest is 0. Looking inside qnice2hyperram, this probably means that reading is 1 (since qnice_disk0_read and ..._write are both 0). It never got set to 0 which must mean that m_avm_readdatavalid_i never became 1. That would point upstream at the avm_fifo. Or it could be further upstream, such as the avm_arbit.

Here some more pictures, mostly because they have a few more signals on them.

[MJoergen]

I'm on my way on vacation, so I can't help much. However, you might want to look in the branch "mfj_POC_disk_buffer_in_hyperram" in the C64 repo:

https://github.com/MJoergen/C64MEGA65/tree/mfj_POC_disk_buffer_in_hyperram

It's very old, but the name says it all. Maybe you'll find inspiration there.

[Rhialto]

@MJoergen Thanks for the tip, that was indeed where I got my inspiration from,

I made some more pictures and added them below. It's as far as I got today but I'm not sure I can venture inside work.hyperram.

First a picture at reset of a normal, working, boot, so it's easier to spot what is missing when it fails. The signals are arranged more or less in order that goes upstream from the "drive 0 device" to wards the hyperram. Previously I had found that i_qnice2hyperram_d0/reading never turned off probably because it never saw m_avm_readdatavalid_i. I could not capture that signal for some reason but I have m_avm_readdatavalid_d which is one clock delayed, so good enough.
The extra signals I have now are further towards work.hyperram in framework.vhd. One can see that hr_read strobes (indicating the read request) and some time later hr_readdatavalid when the data is available. m_avm_readdatavalid_d pulses rather a "long time" later. (Would the fifo cause a long delay? I didn't research that)
The ILA was triggered on the rising edge of reading, and then I pressed the reset button. So are is the first access attempts that happen after reset. The first few images show one of the next accesses but they pretty much look alike.

Then one with a bit more contention on the hyperram but things still work fine.

Then a failure, with "barcode" on the screen, so here the hyperram got "stuck" even for the frame buffer. Note how hr_read pulses but hr_readdatavalid never responds.

and here a more normal failure (we do reach the normal PET boot screen), which actually seems to look totally the same:

[MJoergen]

Just a random thought: Are you sure you're using the latest version of the M2M framework, i.e. V2.0.1 (same as master)? There was a fix in the HyperRAM controller a few months ago.

[Rhialto]

I applied the patches from when that was first fixed, and then the patches from V2.0.1, but of course I can double-check if my end result is the same. Thanks for reminding me!

[MJoergen]

I applied the patches from when that was first fixed, and then the patches from V2.0.1, but of course I can double-check if my end result is the same. Thanks for reminding me!

The relevant commit is 0cf3263 from 11'th July 2024 with the message "M2M: Update with latest HyperRAM".

[sy2002]

@Rhialto After applying the patch there must not be any "barcode" any more - otherwise we have a way bigger problem...

[Rhialto]

I did a diff between MiSTer2MEGA65/M2M/ and PET_MEGA65/M2M/ and the only differences are is in PET_MEGA65/M2M/rom/options.asm where I fixed an infinite loop (issue #58) and PET_MEGA65/M2M/vhdl/top_mega65-r3.vhd where I changed a comment which mentions the core's frequency.

Note that the barcode thing usually does not happen, it is fairly rare. In the usual case the display comes up normally and the PET even works, as long as you don't want to access the disk drive (or the HELP key).

From the ILA images it might seem that the hyperram doesn't produce any data any more, but that must be wrong, since the display usually works. So I must be missing something. I intend to add more signals in the coming weekend. And maybe the time window is too short to see display data traffic (I never checked what sort of pattern that access is). At least I think the display data should be visible here, at the connections of work.hyperram, since there isn't any other arbiter further upstream, right?

[Rhialto]

I think I have a weak suspect: the work.avm_arbit_general in framework.vhd. I added most of the signals going into and coming out of it.

In two cases of "freeze", I saw the following sequence of events.

• my trigger (which is still CORE/i_qnice2hyperram_d0/reading going up),
• hr_core_read_o pulses, at the same time hr_address and a bunch of other hr_* signals change, and quickly after, hr_read pulses.
• from that I think that apparently the arbiter has decided to schedule the read from the core (from the disk image)
• before hr_readdatavalid becomes true, hr_dig_write becomes true, This is about 25 clocks later, though.

Either this sequence of events confuses the arbiter, or it is a coincidence (and things are stuck already when hr_dig_write becomes true). 25 clocks is a bit long for this time, but 15 clocks is not so unusual.

I will attach some ILA exports. Screen shots are getting a bit difficult since there are too many signals to show.

iladata.zip

[Rhialto]

Maybe the "it is already stuck at that time" theory is true. In the ILA data where it is ok, I see read activity before "reading" (i.e. hr_readdata wiggles) but not in the case where it is stuck.

Here is some more history (16 000 hyperram clocks) before "reading". In the "stuck" case there is a lot of writing to hyperram going on beforehand, so clearly the hyperram itself isn't stuck, it must be something else. That would shift suspicion to the arbiter again, or something nearby perhaps.

iladata2.zip

I looked inside the arbit_general, and noticed that for 3 downstreams it is asymmetric. The third downstream has an advantage in that case since it has 1 2-way arbiter fewer in its path. So I tried what happens if I change the order of them where it's used in framework.vhdl. I changed the order from dig, core, qnice to core, qnice, dig. The dig wires (those are for the av_pipeline, so they should, for most cases, probably have a higher priority) are normally that 3rd downstream and I changed that.
However it was difficult to say if this really made a difference. The first reset I tried already got stuck, but a whole bunch after that were fine. Since the exact time that I keep the reset button pressed may well play a role, these experiments are not very repeatable so should not be given too much weight. So effectively, this experiment didn't seem to help.

[MJoergen]

@Rhialto Thank you for all your debugging effort. I'm confused (and quite troubled!) by your traces, since it seems the HyperRAM controller is not responding to the read request.

Could you please add debugging on the following signals inside hyperram_ctrl.vhd:

• avm_read_i
• avm_waitrequest_o
• hb_read_o
• hb_dq_ie_i
• state

Plus also the signal ctrl_dq_ie inside hyperram_rx.vhd.

This is inside the state machine of the HyperRAM controller. The protocol is that the read starts when avm_read_i = 1 and avm_waitrequest_o = 0. The signals hb_read_o and hb_dq_ie_i connect to the HyperRAM device itself (through appropriate I/O stuff).

My suspicion (well, more like nightmare!) is that the signal hb_read_o gets asserted, but hb_dq_ie_i never does. That would indicate a problem in the communication between the HyperRAM controller and the HyperRAM device.

[MJoergen]

One more comment. If the problem indeed is inside the HyperRAM controller, there is a timing parameter that can be tweaked. The value for IDELAY_VALUE in line 62 in hyperram_rx.vhd. You could try changing this parameter slightly, e.g plus or minus, say, five. This is purely trial-and-error. It's only useful if the error is reliably reproducible. But it could be nice to get some statistics, e.g. a range of values that work.
Note that you might get timing violations when changing this value. I would ignore those for the moment.