March 16, 2025

Black Pill boards - F411 USB -- experiments sending data

I am getting ready to do some experiments with USB, and these "experiments" will involve sprinkling printf statements at important places in the code and watching what happens.

I have already learned that this can cause trouble with USB. The problem is that it takes time to send characters over a serial port. The delay sending a message can be long enough to interfer with critical USB timing. This is a surprising and unexpected consequence that I have encountered (but rarely) when debugging other systems.

Consider a serial port running at 115200 baud. I always use a "rule of thumb" that a character is 10 bits, so we can send 11,520 characters per second. Now consider a 100 character message. It will take 100/11,520 = 0.008 second (8 milliseconds) to send. Anything that causes a delay longer than 1 millisecond could interfere with USB.

Possible solutions

There are several ways to solve this. One way is to set up some kind of internal "log" of USB events and then display this after whatever USB activity of interest has finished. This works, but involves writing quite a bit of specialized code.

Another way is to do all the serial output from "mainline code" that is not running at interrupt level. All of the USB activity of interest happens in interrupt code (as it turns out), so USB interrupts can still happen and be handled without interference.

Another way is to let serial output be interrupt driven. I think this is the best solution. It is a worthwhile addition to any serial driver in any case, and allows printf statements to be sprinkled in interrupt code. Some interesting questions do arise, which will be discussed below.

Some information about USB interrupts

I add some code to Hydra for the F411. The idea is to have two counters. One counts every interrupt, the other counts every one of those that is a SOF interrupt. I print the counter values once per second: 
 usb, sof count = 889 814
 usb, sof count = 1840 1765
 usb, sof count = 2790 2715
 usb, sof count = 3741 3666
 usb, sof count = 4692 4617
 usb, sof count = 5642 5567
So we are getting 950 interrupts per second, and they are all SOF interrupts.

Perhaps the rate is really 1000 per second and my timing is off? Somebody said USB frame rates are 512 microseconds, but they are wrong. The timing is 1 millisecond (so we should see 1000 Hz here. No doubt my CPU clock based delays are off.

We only get these SOF interrupts when we have a cable plugged into the host. The host is providing this 1000 Hz "heartbeat". The details are all part of the USB protocol.

Remember when we talked about sending data from our VCP device. We speculated that the transfer would started by Handle_USBAsynchXfer() which we now know gets a chance every millisecond to look at the pointers and see if there is pending data.

Experiment 1

I add some printf statements and try sending 100 bytes of data. I see this: 
USB Tx asynch start: 100
USB Tx asynch send: 64
This is from Handle_USBAsynchXfer() as we predicted. It sees the 100 bytes in the buffer waiting to be sent. It is limited to sending 64 bytes per transfer, so it sends those.

The bad part is that this is all we see. We expect a subsequent interrupt to finish up by sending 36 bytes, but we never see it.

Some more experimenting is surprising. This is just "what happens" when there is no listener. Once I start picocom on /dev/ttyACM0 to receive these packets, I get different results: 

USB Tx asynch start: 100
USB Tx asynch send: 64
USB Tx datain start: 36
USB Tx datain send: 36
And to be sort of complete, I try sending 500 bytes of data: 
USB Tx asynch start: 500
USB Tx asynch send: 64
USB Tx datain start: 436
USB Tx datain send: 64
USB Tx datain start: 372
USB Tx datain send: 64
USB Tx datain start: 308
USB Tx datain send: 64
USB Tx datain start: 244
USB Tx datain send: 64
USB Tx datain start: 180
USB Tx datain send: 64
USB Tx datain start: 116
USB Tx datain send: 64
USB Tx datain start: 52
USB Tx datain send: 37
USB Tx datain start: 15
USB Tx datain send: 15
I get peculiar and unpredictable (apparently random) behavior once the buffer has less that 64 bytes (in the case here, 52 bytes). Here we see 37 then 15 get sent. Every ending is different, sometimes we see: 
USB Tx datain start: 52
USB Tx datain send: 1
USB Tx datain start: 51
USB Tx datain send: 51
This seems like a harmless bug, it should just send the 52 bytes, but maybe there are deeper issues I don't understand.

What if we try sending 800 bytes (which is bigger than the 512 byte size of the buffer)? 

USB Tx asynch start: 455
USB Tx asynch send: 64
USB Tx datain start: 456
USB Tx datain send: 64
USB Tx datain start: 457
USB Tx datain send: 64
USB Tx datain start: 458
USB Tx datain send: 64
USB Tx datain start: 459
USB Tx datain send: 64
USB Tx datain start: 480
USB Tx datain send: 64
USB Tx datain start: 416
USB Tx datain send: 64
USB Tx datain start: 352
USB Tx datain send: 64
USB Tx datain start: 288
USB Tx datain send: 64
USB Tx datain start: 224
USB Tx datain send: 64
USB Tx datain start: 160
USB Tx datain send: 64
USB Tx datain start: 96
USB Tx datain send: 64
USB Tx datain start: 32
USB Tx datain send: 32
So we send 12 packets of 64 bytes and a finishing packet of 32, which is exactly 800 bytes. It works! Notice how the buffer (512 bytes in size) is getting filled as the 64 byte packets are being sent over USB.

Conclusion

My worry about interference by serial timing was needless. It just worked to put the printf statements I wanted into the driver code.

Experiments are worthwhile! Along with study of the code, they can answer questions more quickly (and accurately) than a lot of code study. But both are required.

Feedback? Questions? Drop me a line!

Tom's Computer Info / tom@mmto.org