Copying multiple larger files can hang the copy if autoreload is on

[dhalbert]

First reported by @theacodes. Considerable discord discussion starting about 7pm ET 2021-1-12 in #circuitpython

Seems to happen fairly often (though not always) on SAMD21. Not sure if it happens on SAMD51. Not tried on other boards.

Example, copying to a Metro M0 Express running near the tip of main. First erase the filesystem. Then, do not enter the REPL, but copy multiple larger files, e.g. like this set:

32278 Aug 29  2018 hit.wav
89134 Aug 29  2018 idle.wav
61164 Aug 29  2018 off.wav
75820 Aug 29  2018 on.wav
43438 Aug 29  2018 swing.wav

For me, one out of two times this caused the copy to hang.

@theacodes reports that a workaround is to copy one file at a time or to enter the REPL, so that auto-reload is not happening, and then copy.

This problem was not evident to @theacodes on 5.3.1.

[theacodes]

Confirming workaround: suspending autoreload through supervisor.disable_autoreload() or entering the REPL allows files to be copied without issue.

This was discovered while programming Big Honking Buttons. The factory setup script copies a set of files to the device - one set is the following WAV files:

drwxr-xr-x  9 stargirl  staff   288B Jul 24 13:37 ./
drwxr-xr-x  9 stargirl  staff   288B Jan 12 21:00 ../
-rw-r--r--  1 stargirl  staff    19K Jul 24 13:37 clap.wav
-rw-r--r--  1 stargirl  staff    63K Jul 24 13:37 dist.wav
-rw-r--r--  1 stargirl  staff    21K Jul 24 13:37 go.wav
-rw-r--r--  1 stargirl  staff    17K Jul 24 13:37 honk.wav
-rw-r--r--  1 stargirl  staff    37K Jul 24 13:37 kick.wav
-rw-r--r--  1 stargirl  staff    38K Jul 24 13:37 reverse.wav
-rw-r--r--  1 stargirl  staff    65K Jul 24 13:37 snare.wav

These in particular trigger the issue and would cause writes to the device to hang. It seems BHB's library code accessing the filesystem at startup may contribute to triggering the issue more often as well.

As a workaround, we are forcing the device into the REPL before copying files:

def force_into_repl(usb_device_id: str):
    """Forces a circuitpython device into the REPL."""
    port = serial_connect(usb_device_id)

    # Interrupt with Ctrl + C
    port.write(b"\x03")
    # Enter repl with enter after slight delay
    time.sleep(0.2)
    port.write(b"\n")
    port.close()

With that workaround, we can program devices consistently without hanging:

========== DEPLOYING CODE ==========
Waiting for CIRCUITPY drive...
Forcing BHB into repl (workaround for CircuitPython issue #3986)
Cleaning temporary files from src directories...
Downloading files to cache...
Using cached winterbloom_voltageio.py.
Copying files...
Copied factory/.cache/winterbloom_voltageio.py to lib
Copied firmware/winterbloom_bhb to lib
Copied samples to .
Copied examples to .
Copied firmware/LICENSE to .
Copied firmware/README.HTM to .
Copied examples/default.py to code.py
Flushing... 🚽
Done copying files, resetting...
Done!

[dhalbert]

I found the copying is much slower if the serial connection is not open.

This test is with code.py just being print("Hello, world").

Not connected:

halbert@salmonx:~/Downloads/sounds$ /bin/rm /media/halbert/CIRCUITPY/*.wav;sync
halbert@salmonx:~/Downloads/sounds$ cp -v *.wav /media/halbert/CIRCUITPY/
'hit.wav' -> '/media/halbert/CIRCUITPY/hit.wav'
'idle.wav' -> '/media/halbert/CIRCUITPY/idle.wav'
    [big delay; NeoPixel pulses green]
'off.wav' -> '/media/halbert/CIRCUITPY/off.wav'
    [big delay; NeoPixel pulses green]
'on.wav' -> '/media/halbert/CIRCUITPY/on.wav'
    [big delay; NeoPixel pulses green]
'swing.wav' -> '/media/halbert/CIRCUITPY/swing.wav'
    [big delay; NeoPixel pulses green]

Connected, in REPL or not (doesn't seem to matter on timing), and repeating the commands above, I see much smaller delays, still a few seconds for copying larger files (sometimes two at a time). I do not see the pulsing green NeoPixel as above.

I am not sure this completely jives with @theacodes' technique of forcing the REPL, and having trouble before that.

[theacodes]

Should I try with just opening a serial connection and not sending anything?

…

On Tue, Jan 12, 2021, 11:08 PM Dan Halbert ***@***.***> wrote: I found the copying is much slower if the serial connection is not open. This test is with code.py just being print("Hello, world"). Not connected: ***@***.***:~/Downloads/sounds$ /bin/rm /media/halbert/CIRCUITPY/*.wav;sync ***@***.***:~/Downloads/sounds$ cp -v *.wav /media/halbert/CIRCUITPY/ 'hit.wav' -> '/media/halbert/CIRCUITPY/hit.wav' 'idle.wav' -> '/media/halbert/CIRCUITPY/idle.wav' [big delay; NeoPixel pulses green] 'off.wav' -> '/media/halbert/CIRCUITPY/off.wav' [big delay; NeoPixel pulses green] 'on.wav' -> '/media/halbert/CIRCUITPY/on.wav' [big delay; NeoPixel pulses green] 'swing.wav' -> '/media/halbert/CIRCUITPY/swing.wav' [big delay; NeoPixel pulses green] Connected, in REPL or not (doesn't seem to matter on timing), and repeating the commands above, I see much smaller delays, still a few seconds for copying larger files (sometimes two at a time). I do *not* see the pulsing green NeoPixel as above. I am not sure this completely jives with @theacodes <https://github.com/theacodes>' technique of forcing the REPL, and having trouble before that. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#3986 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAB5I445BKEIZVGTJMQE3DLSZUME3ANCNFSM4WADE4LQ> .

[dhalbert]

Should I try with just opening a serial connection and not sending anything?

I thought you were doing that initially, and you added the "getting into the REPL" part. But if were not opening the connection before, yes, you could try that.

I think this may have to do with not calling the tinyusb "do tasks" call often enough. It probably gets called more often when a serial connection is open, because there's traffic that generates interrupts. The fix may be to enable tick interrupts all the time if there's any kind of USB connection, including MSC and CDC. I'm going to try that soon.

[hathach]

I am able to reproduce the issue with tip of main by copying all sample files here https://github.com/theacodes/Winterbloom-Big-Honking-Button/tree/master/samples . Bus analyzer show that firmware didn't response to the SCSI status phase, either the stack failed to manage the state and/or could be another buffer overflow, or maybe the tud_task() isn't called e.g cpy doesn't think it needs to call the usb task. Eventually the host have to issue a bus reset -> re-enumerate -> host tries again with on-going files which is the huge pause we see.

I will do more testing with different MCUs, and scenario, will update with more details later on.

[dhalbert]

Thanks!! I am going to instrument the calls to tud_task() and the ticks by toggling some pins to see what is going on.

[dhalbert]

@hathach In 5.3.1, we called tud_task() as one of the background tasks that runs on every timer tick, which was 1msec. The calling routine is usb_background().

That was changed in #2879 during 6.0 development. Now tud_task() is only set up to be called once each time the usb_irq_handler() is called:

circuitpython/supervisor/shared/usb/usb.c

Lines 97 to 100 in 409b5ff

	void usb_irq_handler(void) {
	tud_int_handler(0);
	background_callback_add(&usb_callback, usb_background_do, NULL);
	}

(It is not called in the interrupt handler, but it is put on a list of background routines to call (once) when they are given a chance to run.)

I think the idea was that only a USB interrupt would generate a task for TinyUSB to handle, and otherwise TinyUSB would have no work to do. But I don't think that's right, is it? It appears there are other times besides an interrupt when tud_task() has something to do.

As an experiment, I put usb_background() back in supervisor_background_tasks() and took out the special logic described above. That fixes the problem of this issue.

But I am still worried that we need to call tud_task() every msec, no matter what. I thought you told me in the past this was necessary. Currently in 6.x we don't generate ticks every msec unless there's some work going on that depends on that. Doing this reduces power consumption. But if we truly need to do tud_task() every msec, we have to always generate 1 msec ticks, and our tick-saving logic just needs to go away, at least when USB is connected.

#2868 may or may not be related to this (fixed an nrf problem), but I am not sure at all. You reviewed that PR extensively.

@jepler Do you have any comment on the above (especially #2879 changes)?

[jepler]

Re #2868 I don't mind at all modifying how we control when usb_background() or tud_task() are and I'm happy to help figure out what needs to be changed. It's not an understatement to say my changes were based on an insufficient understanding of tinyusb as well as just seeing "what worked"...

[tannewt]

Maybe we need to queue up tud_task after we queue a response back into tinyusb. For example, maybe we need to trigger tud_task after a write completes.