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

[rgc2000]

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]

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]

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]

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)

[GideonZ]

Sounds really excellent!!!

Message ID: @.***>

[rgc2000]

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]

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]

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]

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

[radius75]

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

[rgc2000]

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.

[radius75]

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

[rgc2000]

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

[radius75]

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

print480.prg.zip u2p config.cfg.zip

[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

print160.prg.zip

[GideonZ]

Interesting!!!

[rgc2000]

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]

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.

[GideonZ]

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.

[rgc2000]

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.

[johnlivdahl]

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+.

[rgc2000]

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.

[GideonZ]

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.

[rgc2000]

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]

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

[GideonZ]

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.

[xlar54]

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: @.***>

[rgc2000]

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.

[radius75]

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.

[rgc2000]

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 ?

[radius75]

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.

[rgc2000]

I have loaded your configuration and run PRINT160.PRG without any issue. 8 pages printed as expected. Basic program ends at 3min 40s . Printer activity ends at 4min 15s. Nothing left in print buffer after last PNG saved to USB stick.

I am using a breadbin PAL C64 and my USB key is the one that was delivered with the U2+ (black USB2 key 8GB with "Ultimate II+ by Gideon" written on it) formatted FAT32 and 650MB used on it.

Can you try another USB stick ? If there is a write error or FAT corruption it may be an issue.

[radius75]

Bingo! This is some problem with the USB memory. I set the output to /Temp/ and everything printed in Basic2.0 and Jiffy.

[radius75]

I connected a second flash memory in USB1, set file output to it, and saved 40 prints to it (the program was run 5 times in a row without restarting the C64). They are all saved in USB1. Nice! :)

The strange thing is that at this time the USB0 <---- memory suddenly set to FAILED. I saved the log from the moment I switched the printer to ON.

Number of items: 11
Action Category selected: Printer
Object level 2 returned 1.
Object level 1 returned 1.
Action set was: Turn On
About to execute a command in subsys Virtual Printer (00684388)
Object level 1 returned 1.
Action set was: Run
PRG Select: 2201
DMA Load.. print160.prg
About to execute a command in subsys C64 Machine (00688348)
Cartridge definition:
Name: (null)
Type: 65
Custom: 000931D4 (Length: 1272)
Required: 0000
Prohibited: 0000
Sampler found in FPGA... IO map: disabled.
Writing 85 to timing register. 5/8/0
Cartridge registers:
04040000: 04 00 02 17 00 41 01 00 00 04 00 00 00 00 00 00 .....A..........
Copying 1272 bytes from array 000931D4 to mem addr 00F00000
Begin of cart init: Type: 41. REU: 00. REU_SZ: 04, UCI: 00 (DF18), Mode: 04, Sampler: 00
End of cart init: Type: 41. REU: 00. REU_SZ: 04, UCI: 00 (DF18), Mode: 04, Sampler: 00
_____Load address: 0801...Now loading...DMA load complete: $0801-$0887
Resuming..
Cart got disabled, now restoring.
Cartridge definition:
Name: None
Type: 0
Custom: 00000000 (Length: 0)
Required: 0000
Prohibited: 0000
Sampler found in FPGA... IO map: disabled.
Writing 85 to timing register. 5/8/0
Cartridge registers:
04040000: 00 00 02 03 00 00 00 00 00 04 00 00 00 00 00 00 ................
Begin of cart init: Type: 00. REU: 00. REU_SZ: 04, UCI: 00 (DF18), Mode: 00, Sampler: 00
End of cart init: Type: 00. REU: 00. REU_SZ: 04, UCI: 00 (DF18), Mode: 00, Sampler: 00
Draw. No window to draw on.
Object level 0 returned -2.
MENU HIDE / EXIT.
Poll Focussed returned -2. DoBreak = 1.
@Saving printer file /Usb1/_PRINTER/page-041.png
@Saving printer file /Usb1/_PRINTER/page-042.png
@Saving printer file /Usb1/_PRINTER/page-043.png
@Usb0|2 USB unavailable.
USB SCSI: Out failed... Terminate.
ERROR Testing Unit.. -6
Invalidate event on Usb0.. Checking 0 mountpoints.
Invalidate event on Usb0.. Checking 1 files.
 0. /Usb1/print160.prg
Invalidation complete.
@Saving printer file /Usb1/_PRINTER/page-044.png
Saving printer file /Usb1/_PRINTER/page-045.png
@Saving printer file /Usb1/_PRINTER/page-046.png
@@Saving printer file /Usb1/_PRINTER/page-047.png
Saving printer file /Usb1/_PRINTER/page-048.png
@Ultimax set.. Now reading registers..
Mode=1
Frozen on Bad line. Raster = 57. VIC Irq Enable: F0. Vic IRQ: 71
CIA1 registers: 7F FF FF 00 34 08 FF 04 00 00 00 01 00 
Init IO.
CIA DDR: 00 FF Mode: 02
CIA DDR: 00 FF
State Usb1 reloaded. # of children = 14
Path before: /Usb1/
Path after: /
Deleting TBS Level 1 (Usb1)
Object level 1 returned 1.
Action set was: Enter
14 children fetched from Usb1.
Number of items: 11
Action Category selected: Developer
Object level 2 returned 1.
Object level 1 returned 1.
Action set was: Save Debug Log

[radius75]

It is a Sandisk pendrive with a capacity of 64 GB. 50% full. I will order Kingston 64GB and compare then. Happy New Year! :)

[radius75]

I checked that I have no problems with printing when I change "HighDensity" to the new "Square" mode. Even when I change the loop of this program to 1to640 and print 32 pages. I tested by running this three times in a row and produced 96 valid prints. The file size in Square mode was ~14KB, in HighDensity it was ~30KB. I think I'll stick with this setting because it doesn't cause USB failure and the prints look good.

[rgc2000]

It's normal that the file size is smaller in "square" density. You will only have pure back and white pixels, no dithering and so no shades of grey. The PNG compression algorithm is more efficient when there is only 2 colors.

[rgc2000]

@Usb0|2 USB unavailable. USB SCSI: Out failed... Terminate. ERROR Testing Unit.. -6 Invalidate event on Usb0.. Checking 0 mountpoints. Invalidate event on Usb0.. Checking 1 files. Invalidation complete.

Your USB0 device seems to disconnect itself from U2+ even if there is no access to it. You may be experiencing a power problem. When the printer creates a PNG file, the nios2 processor works at its full capacity. This can increase the power consumption of the cartridge and possibly drain too much power from the C64 power supply to keep the USB drive fully powered. I know that some USB drives require more power than others. You can try adding an additional power directly to the U2+'s micro USB port.

[radius75]

My PSU is new, it has 5V3A. I connected an external 5V2.5A to U2+ via micro USB, and U2+ connected only on SerialIEC to C64. With the HighDensity setting FAILED appeared after a few prints. Do you suggest providing internal 3A + 2.5A external at the same time? Even if it would help, I won't use C64 this way :)

[GideonZ]

Although power problems may cause USB issues, I think what happens here is that the USB task is just delayed for too long, which makes the driver think that the stick didn't respond, or something like that. The printer task may be holding a resource too long. Not sure, just speculating.

[rgc2000]

The main change in the virtual printer in this thread is to make it run in a very low priority task. Lower than the USB task to let the USB run even when the printer need to access the CPU. Then the system is not preemptive and maybe I can add some releases of the CPU in the PNG encoding loop. @radius75 would you like to test this with your USB key ?

[radius75]

I can check this, of course.

BTW Saving HighDensity printouts to /Temp always works correctly for me. And it does not cause FAILED on USB drives. Couldn't a virtual printer work by saving to Temp and automatically transferring the finished files to USB? Does this make sense?

[rgc2000]

I sent you an email with the modified firmware with periodic task switches while generating PNG. Using the Temp directory as a target may cause more problems than it solves (specially the file numbering).

[radius75]

I installed update.u2p Printing 32 pages on HighDensity, no FAILED on USB key. I did one test for Basic 2.0, and one for JiffyDos. Thanks a lot :)

[rgc2000]

Thank you for your test. This confirms that printer task should not be holding the CPU for too long to allow other tasks to run even if printer is running with the lowest priority. As FreeRTOS is configured to run in non-preemptive mode, a low priority task can starve another higher priority task. Then I don't know how often I should force a task switch. It is around 5-10 seconds in the firmware I sent you.

[radius75]

If a timestamp was saved in the Logs, would it help to determine anything?

[rgc2000]

Currently nothing is saved in the logs. There are 8 forced task switch’s in a B&W png generation and 20 in a color png generation.

[radius75]

I made a dozen more attempts to print multiple pages and had no problems. If necessary, suggest me another, more demanding program to test printing.

[rgc2000]

You can try to execute this small basic PRG that will print you 8 full pages of text. Each line has to start and end with the same char. This pattern should make the PNG compression and generation to last longer. It's a kind of "worst case" test.

printfull.prg.zip

[radius75]

I tested it. No problems with USB. It's very good. During all these printouts, I tried not to interfere, not to log in via ftp, putty, etc.

[rgc2000]

Thank you @radius75 for your test, I will commit this change in a new branch and create a pull request to ask @GideonZ to add this in his next release.