1541ultimate icon indicating copy to clipboard operation
1541ultimate copied to clipboard

The virtual printer stops working and the status of the USB key changes to FAILED

Open rgc2000 opened this issue 1 year ago • 51 comments

It seems that there is a conflict between the virtual printer process and the USB stack. Printer is very CPU intensive and is running in the IEC thread which has higher priority than USB stack. This makes the USB driver to timeout on key access, making the system think that the USB key is unresponsive.

rgc2000 avatar Mar 22 '23 21:03 rgc2000

Changes in the printer code to fix this issue :

  • Interpreter procedure is now a Task created with the lowest priority (tskIDLE_PRIORITY)
  • This task is normally suspended waiting for a TaskNotify event to run and process the incoming data from IEC.
  • IEC task sends the TaskNotify to printer task when printer data is available.
  • IEC task is suspend while the printer task is processing the data waiting for another TaskNotify from printer.
  • When all the data has been processed, printer sends a TaskNotify event to IEC to go on. Printer task goes back to sleep waiting for a new TaskNotify from IEC to process new data.

Considerations :

  • IEC has to be suspended while printing. This is how a real printer works, holding the IEC bus while the printer is busy.
  • TaskNotify functions are used as binary semaphores here
  • Call to ulTaskNotifyTake and xTaskNotifyGive. Not using "index" versions go theses functions. Same as using index 0. Should not be a problem I can't find any TaskUsage call in the rest of the code.
  • Call to ulTaskNotifyTake with timeout portMAX_DELAY. Should mean no timeout if INCLUDE_vTaskSuspend is set to 1 in FreeRTOS configuration file. By security return code is tested and task is put back to sleep if return code means timeout.
  • The printer flush procedure is not handled by the printer task. This means that it runs in the GUI interface task. It seems not to disturb the USB task. I have never experienced USB errors on printer flush.

Questions someone may answer :

  • I thought that making the printer task to run with the lowest priority could make the cartridge to be responsive again while printing. Unfortunately not. I still can't invoke Ultimate screen while printing.
  • I can hear that some new sounds have been added to 3.10 (disk inserted). Do we want to add printer noise to the cartridge ? Maybe yes if it is no CPU consuming and as easy as a trigger to call to start/stop the printer sound. I already use a LED on/off call to show printer activity.

rgc2000 avatar Mar 24 '23 14:03 rgc2000

Solution seems to work fine on master branch (3.10e) on Ultimate-II+. But when back porting it to 3.10a and testing it on Ultimate-II it does not work. Worse, the software seems to crash, no reaction when pressing ultimate menu button. Fortunately, using a 3.10a ultimate.bin without the printer task on the root of SD card makes it work again. No error message on serial output.

rgc2000 avatar Mar 26 '23 22:03 rgc2000

Work in progress :

  • Printer is now a task, not only the MPS interpreter but the whole IEC printer (including RAW and ASCII printing). Task communication channel are messages and no longer using TaskNotify as it does not work properly under microblaze CPU.
  • Printer is a subsystem with its own configuration menu independent of IEC drive
  • IEC drive can be enabled/disabled and so can the printer. For the user printer and IEC drive are now two independent features but under the hood they are still sharing the same IEC processor. So there are 3 IEC codes now : one for drive only, one for printer only and one for both printer and drive depending which are enabled. It's a bit ugly because if you want to make some changes in IEC code you may need to do the change twice.
  • When flushing the printer from action menu a popup is showing that the printer job is in progress.
  • Printer action menu has 3 items : (Flush/Eject, Reset, Turn On/Off)

rgc2000 avatar Apr 16 '23 12:04 rgc2000

Sounds really excellent!!!

Message ID: @.***>

GideonZ avatar Apr 16 '23 12:04 GideonZ

Work is almost finished but when I was testing all the printer features I realized that color printer is broken under U2 (works fine under U2+ and probably U64). This is not new as it seems to be broken since 3.10a (was working in previous firmwares). It looks like there is not enough heap memory for PNG encoder. I get an error on debug console : "Sbrk called with 5121408. FAILED". It happens in lodepng_encode routine (probably a malloc, but not sure).

rgc2000 avatar Apr 23 '23 18:04 rgc2000

New fixes :

  • Modal window while printing can't be opened from the printer task. If the user is running the action menu from the network using telnet, the network interface will hang.
  • PNG code has been rewritten to need much less heap memory. This enables the color printer to run again on Ultimate II.
  • IEC code ID replacement is a nightmare depending if running on Microblaze or on Nios2 CPU, the endianness and word alignment is not handled the same way on both processors. The solution is not to rely on word alignment and read bytes one by one. Then we can build words to compare and replace. And finally write bytes one by one from the word.

Note : Everything compiling fine on riscv processor for U2+L support but not tested (I have no U2+L). According to latest RiscV specs, the toolchain is no longer backward compatible because some instruction sets are now optional. So, to compile code with latest toolchain the MARCH variable in Makefiles has to be set to rv32i_zicsr instead of rv32i. This fix has not been committed in my master branch as it depends on the toolchain.

rgc2000 avatar May 04 '23 19:05 rgc2000

Last cosmetic fix :

  • Problem: Activity LED was not ON while generating the PNG data on U2+. On U2 led is ON during PNG generation. Printer is using ITU_USB_BUSY register to show activity on LED. On U2, I mostly use a SD card, on U2+ I use a USB memory stick. I suspect the USB driver to conflict with printer because On/Off LED algorithm on printer is correct and LED should be ON.
  • Solution: Created a new register in ITU address space dedicated to printer_busy information. The activity LED is now a logical OR between SD, USB and PRINTER busy state.
  • Conclusion: Printer is no more borrowing the activity status register of the USB driver and everything is working as expected. Printer is using its own register and activity LED is now ON while generating PNG data.

@GideonZ : I have modified itu.vhd and itu_pkg.vhd files to add the printer_busy register on first free address. This will need to be reported on U64 fpga code. I hope it will not be too painful. I hope it uses the same vhdl source files.

rgc2000 avatar May 10 '23 09:05 rgc2000

Merge request #345 includes the fix for this issue and much more

rgc2000 avatar May 11 '23 21:05 rgc2000

The latest 3.11alpha build already contains fixes for this bug?

radius75 avatar Dec 14 '23 15:12 radius75

This is currently under test in the printer_enh branch. . It is 3.11alpha but this branch is also adding support for other features on IEC support (like JiffyDOS for software IEC drive) and some are not stable yet.

rgc2000 avatar Dec 14 '23 15:12 rgc2000

Got it. I noticed changes in the printer options in 311alpha, that's why I asked. Is it too early to report printing errors ?

radius75 avatar Dec 15 '23 12:12 radius75

You can report me printing errors anyway. I can check and correct it if needed. But I would says don't use JiffyDOS ROM for now while printing and don't rely on software IEC drive in 311alpha

rgc2000 avatar Dec 15 '23 14:12 rgc2000

Ultimate2plus 311aplha Test printout of 480 lines of characters (8 pages).

10 open1,4
20 fora=1to480
30 print#1,"test no.";a
40 nexta
50 close1

page-001 page-002 page-003 page-004 page-005 page-006 page-007 page-008

print480.prg.zip u2p config.cfg.zip

radius75 avatar Dec 15 '23 17:12 radius75

10 open1,4:open2,4,0:open3,4,7
20 fora=1to160
30 print#1,"test 1,4 no.";a
31 print#2,"test 2,4,0 no.";a
32 print#3,"test 3,4,7 no.";a
40 nexta
50 close1:close2:close3

Error while executing the program. The printout came out partial.

?device not present  error in 32

page-009 page-010 page-011

print160.prg.zip

radius75 avatar Dec 15 '23 17:12 radius75

Interesting!!!

GideonZ avatar Dec 15 '23 17:12 GideonZ

I ran into the ?device not present error while testing the JiffyDOS ROM. I just thought that this was because IEC interface code is not finished. Then the spurious characters are also IEC errors but I have not tested this on long prints. The previous IEC code does not have this issue and this means that potentially the IEC drive may also suffer the same issue.

rgc2000 avatar Dec 15 '23 20:12 rgc2000

I have been testing the printer in standard IEC mode. It appears that the IEC interface does not care about the printer activity. When the printer receives the data sometimes it's fast but sometimes it needs some time to interpret the data. The most obvious task is when the printer has to eject the page and generate a PNG file. When the printer is busy the IecPrinter::push_command or IecPrinter::push_data will not return until the printer is ready to receive new data again. Meanwhile the IEC interface must also wait and must not acknowledge new incoming data. This makes the C64 to hang until the IEC is able to receive data again. What I see is that the IEC interface seems to run completely asynchronously. It reads the data from the C64 in IEC even when the printer is busy and the C64 program never hangs. The printer is unable to receive data while it is busy and this data is lost.

I have not analyzed the JiffyDOS mode yet but I tried and it was looking very odd. The received data is not what was sent by the C64.

rgc2000 avatar Dec 17 '23 22:12 rgc2000

The IEC protocol itself is handled by a programmable state machine that runs in hardware. The data coming from the IEC state machine is passed through a fifo to the application. This fifo can hold events and data.

The programmable state machine should check the status of the fifo before allowing a handshake on the IEC bus that would initiate a sequence that yields a data byte, i.e: check fifo before releasing DATA when the target is listener, begore the byte transfer starts. Once the transfer starts, the byte should always fit into the fifo when the state machine ack's the byte after bit 7.

It is most probable that there are places in the programmable statemachine code where the fifo status is not checked correctly. JD is faster, and the fifo is only checked once every 10 ms by the application. At normal speeds, at most ~4-5 bytes can be transferred in this timeframe, which is fine for a fifo with depth 16. For JD is it not fine. It does check for the fifo full flag for data, but does it also do so for control bytes?

Note that it might be better to use almost full, to allow some slack. For instance, when ATN comes, the atn got active control code is pushed right away, without checking, as it interrupts current operation.

GideonZ avatar Dec 17 '23 22:12 GideonZ

I have reviewed the iec_interface.cc code and the iec_code.iec . Activated debug, made many tests and found no bug. Now it works as expected even if I disable the debug messages. I am running with the standard C64 Kernel and standard IEC protocol. Everything is correct. I have made no significant changes to the code. I don't understand why it works now. C64 is waiting as expected when the printer is busy.

For JiffyDOS I suspect my test configuration to be unstable. I can't modify a BASIC program loaded from disk (with standard 1541 ROM or with JiffyDOS 1541 ROM), the C64 crashes.

rgc2000 avatar Dec 18 '23 23:12 rgc2000

René, To get JiffyDos to work correctly on the 3.11 alpha code using SoftIEC you need to enable at least one of the virtual drives. Then you can edit a basic program after Jiffy Fast loading from SoftIEC. With only IEC drive enabled I get "? LOAD ERROR?" and the error when editing the loaded basic program.

I posted about this in the special 3.11 alpha Facebook chat. (I hope Gideon saw it there). Note: my observations are when using the U64, might be different on the U2+.

johnlivdahl avatar Dec 18 '23 23:12 johnlivdahl

I am loading the BASIC PRG file from a virtual 1541 drive, not the IEC drive. With standard kernel it works as expected but with JiffyDOS Kernel I can't edit the BASIC lines, the C64 crashes. I have not tried IEC drive or DMA load. I have to check how JD transmissions are done. Is it a byte per byte transmission or a bloc transmission like Ulticopy ? Maybe if a bloc is sent but the printer can't hancle all the incoming bytes this makes the printer to get garbage. The beginning of the transmission looks ok for several hundreds of bytes and then it goes wrong and the printer receives unexpected data.

rgc2000 avatar Dec 19 '23 08:12 rgc2000

I found one JiffyDOS bug in the iec_code. DATA was set to '1', even when the FIFO was full. Removed one line of code and the test with a for loop that prints many lines over several pages just works fine now. printer-009 printer-010 printer-011 printer-012 printer-013 printer-014 printer-015 printer-016

GideonZ avatar Dec 19 '23 21:12 GideonZ

This is a good news but there is still another issue. I am investigating what is happening when I use a secondary address while opening the printer. It seems that if the printer is busy when the secondary address is sent under ATN ($67 for OPEN 1,4,7) something goes wrong with acknowledge from printer and the C64 stops the BASIC program with ?DEVICE NOT PRESENT ERROR. This is correctly handled with non JiffyDOS IEC

rgc2000 avatar Dec 19 '23 23:12 rgc2000

I have finally been able to get rid of the ?DEVICE NOT PRESENT error. This is caused by a too long READY TO LISTEN answer from the IEC processor after ATN end. In the iec_code.iec file in the RELEASE routine, reduce the delay (I don't have an oscilloscope to know what value should be best, but 10us works fine for me) :

@@ -378,7 +378,7 @@ RELEASE
             SET ATN=1
             SET CLK=1
             SET DATA=1
-            WAIT FOR 100 us #Why!?
+            WAIT FOR 10 us #Why!?
             JUMP reset_vec
 
 JIFFY_RX

Then another change I have made but without consequence is to remove the double EOI sent to software as it is useless (one EOI is enough) :

@@ -387,7 +387,7 @@ _wait2
             IF UPFIFOFULL THEN _wait2
             SET DATA=1
             WAIT UNTIL NOT CLK=0,ATN=1 # Possibly for a long time
-            IF NOT ATN THEN _jiffy_rx_end
+            IF NOT ATN THEN _end_of_rx
 
             # clk(3)data(1) => !bit4 & !Bit5
             # clk(2)data(0) => !bit6 & !bit7
@@ -412,16 +412,10 @@ _wait2
             PUSHD
             JUMP JIFFY_RX
 
-_jiffy_rx_end
-            LOAD CTRL_EOI
-            PUSHC
-            JUMP _end_of_rx
-
 RECEIVE_BYTE
 # initial state: DATA is low, CLK has to become 1
             IF JIFFYDOS THEN JIFFY_RX

rgc2000 avatar Dec 21 '23 10:12 rgc2000

Excellent work, Rene!!! Let me integrate this diff and see if the majority of problems have disappeared. I'll try to test also loading a file with JD, while no other devices are present.

GideonZ avatar Dec 21 '23 14:12 GideonZ

Awesome Rene!

On Thu, Dec 21, 2023, 8:03 AM Gideon @.***> wrote:

Excellent work, Rene!!! Let me integrate this diff and see if the majority of problems have disappeared. I'll try to test also loading a file with JD, while no other devices are present.

— Reply to this email directly, view it on GitHub https://github.com/GideonZ/1541ultimate/issues/308#issuecomment-1866314046, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAOSHCVSXAB2RBXRJIN65A3YKQ6SPAVCNFSM6AAAAAAWEL4WBKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQNRWGMYTIMBUGY . You are receiving this because you are subscribed to this thread.Message ID: @.***>

xlar54 avatar Dec 21 '23 14:12 xlar54

I have removed the 10us delay in the RELEASE routine. I was still having some spurious ?DEVICE NOT FOUND errors on printer with JiffyDOS kernal when the soft IEC was the only IEC device. It seems that the JiffyDOS kernal has more aggressive IEC timings than the regular kernal.

rgc2000 avatar Dec 21 '23 16:12 rgc2000

I have now tested both my test programs on the official fw3.11

The first one prints 8 pages correctly (Basic2.0 and Jiffy) :)

The second program (which should also print 8 pages) blocks the operation of U2+. No access to it via the middle button, ftp, putty, web api. In Basic2.0 it printed 3 full pages and got stuck on the fourth one. In Jiffy it printed 5 full pages and also got stuck.

radius75 avatar Dec 30 '23 11:12 radius75

I have done the test with your PRG files on my U2 and U2+ using both Basic 2.0 and JiffyDOS 6.01 and everything works fine until the end. I have noticed that Gideon has raised the IEC fifo length so in the PRINT160.PRG there is enough data in the fifo to fill 2 pages when the program exits. So I need to wait for 3 PNG generations (current page + 2 next pages) to get the Ultimate cartridge to be responsive again (more than 1 minute on U2+).

What can make your configuration to fail after the 3rd page ? Do you have other IEC peripherals ?

rgc2000 avatar Dec 30 '23 18:12 rgc2000

I ran print160.prg again on Basic2.0 and waited about 15 minutes. No response, only the reset button works. Ultimate2+ cartridge only connected to IEC Bus. My print configuration is in ZIP a few posts above. I'll link it. https://github.com/GideonZ/1541ultimate/files/13687951/u2p.config.cfg.zip I'll try to save the Log while printing, maybe it will help.

radius75 avatar Dec 30 '23 19:12 radius75