USB-CDC times out

[sago35]

Sometimes bytes from fmt.Printf () disappear.

temperature: 70.699997
temperature: 70.699997
temperature: 70.699997
tmperature: 70.699997
temperature: 70.699997
temperature: 70.699997
temperature: 70.587494
temperature: 70.587494
temperature: 70.925003
temperature: 70.925003
tmperature: 70.925003
temperature: 72.274994
temperature: 72.274994
temperature: 73.625000

The reason is that there is no retry after a timeout.
However, increasing the number of busy loops will have an impact on performance.

// src/machine/machine_atsamd51.go
func (usbcdc USBCDC) WriteByte(c byte) error {
    if usbLineInfo.lineState > 0 {
        // set the data
        // ...

        // wait for transfer to complete
        timeout := 3000
        for (getEPINTFLAG(usb_CDC_ENDPOINT_IN) & sam.USB_DEVICE_ENDPOINT_EPINTFLAG_TRCPT1) == 0 {
            timeout--
            if timeout == 0 {
                return errors.New("USBCDC write byte timeout")
            }
        }
    }

    return nil
}


// src/machine/usb.go
func (usbcdc USBCDC) Write(data []byte) (n int, err error) {
    for _, v := range data {
        usbcdc.WriteByte(v)
        // !!! If err! = nil, go to the next byte !!!
    }
    return len(data), nil
}

[sago35]

Sending some batches instead of using putchar will be faster.
If you want to send them in batches, you may want to make the timeout value longer.

By sending a certain number of bytes at once on the TinyGo side, I think the performance will improve considerably.

Before Change

https://github.com/sago35/tinygo/tree/b0eb3ff5362f7c5e80b23407ef6f7531cb8ab8ff

It takes 3.1ms to output 51 characters.
49 characters in between A and 2 characters in between B.
It is slow because it waits for the completion of transmission for each character.
And sometimes it times out.

After the change

https://github.com/sago35/tinygo/tree/e5e8ac99d126af0fa5050601c10f1bf113b10d46

It takes 170us to output 51 characters.
It is about 20 times faster.

test code

https://github.com/sago35/tinygo/tree/cdc-timeout

		d5.High()
		println("hello world!hello world!hello world! hello world!")
		d5.Low()

//go:nobounds
func printstring(s string) {
	machine.D10.High()
	//for i := 0; i < len(s); i++ {
	//	putchar(s[i])
	//}
	machine.UART0.WriteBytes([]byte(s))
	machine.D10.Low()
}

func printnl() {
	machine.D10.High()
	//putchar('\r')
	//putchar('\n')
	machine.UART0.WriteBytes([]byte("\r\n"))
	machine.D10.Low()
}

func (usbcdc USBCDC) WriteByte(c byte) error {
	// Supposedly to handle problem with Windows USB serial ports?
	if usbLineInfo.lineState > 0 {
		// set the data
		udd_ep_in_cache_buffer[usb_CDC_ENDPOINT_IN][0] = c

		usbEndpointDescriptors[usb_CDC_ENDPOINT_IN].DeviceDescBank[1].ADDR.Set(uint32(uintptr(unsafe.Pointer(&udd_ep_in_cache_buffer[usb_CDC_ENDPOINT_IN]))))

		// clean multi packet size of bytes already sent
		usbEndpointDescriptors[usb_CDC_ENDPOINT_IN].DeviceDescBank[1].PCKSIZE.ClearBits(usb_DEVICE_PCKSIZE_MULTI_PACKET_SIZE_Mask << usb_DEVICE_PCKSIZE_MULTI_PACKET_SIZE_Pos)

		// set count of bytes to be sent
		usbEndpointDescriptors[usb_CDC_ENDPOINT_IN].DeviceDescBank[1].PCKSIZE.SetBits((1 & usb_DEVICE_PCKSIZE_BYTE_COUNT_Mask) << usb_DEVICE_PCKSIZE_BYTE_COUNT_Pos)

		// clear transfer complete flag
		setEPINTFLAG(usb_CDC_ENDPOINT_IN, sam.USB_DEVICE_ENDPOINT_EPINTFLAG_TRCPT1)

		// send data by setting bank ready
		setEPSTATUSSET(usb_CDC_ENDPOINT_IN, sam.USB_DEVICE_ENDPOINT_EPSTATUSSET_BK1RDY)

		// wait for transfer to complete
		timeout := 3000
		D6.High()
		for (getEPINTFLAG(usb_CDC_ENDPOINT_IN) & sam.USB_DEVICE_ENDPOINT_EPINTFLAG_TRCPT1) == 0 {
			timeout--
			if timeout == 0 {
				D6.Low()
				D9.Toggle()
				return errUSBCDCWriteByteTimeout
			}
		}
		D6.Low()
	}

	return nil
}

[sago35]

I created a new version.
I don't know if flushing with \n as a trigger is better, but it seems to be more efficient for a text-based situation.
With the new method, there is no need to wait for the transmission to be completed, which results in a very short USB-CDC processing time.

If the timeout is to be avoided, the timeout value needs to be considered.

// WriteByte writes a byte of data to the USB CDC interface.
func (usbcdc *USBCDC) WriteByte(c byte) error {
	debugPortD1.High()

	// Supposedly to handle problem with Windows USB serial ports?
	if usbLineInfo.lineState > 0 {
		if c == '\n' || usbcdc.TxBuffer[usbcdc.TxPtr].Used() == 126 {
			ptr := usbcdc.TxPtr
			usbcdc.TxPtr = 1 - usbcdc.TxPtr
			usbcdc.TxBuffer[usbcdc.TxPtr].Clear()

			// set the data
			sz := usbcdc.TxBuffer[ptr].Used()
			for i := byte(0); i < sz; i++ {
				udd_ep_in_cache_buffer[usb_CDC_ENDPOINT_IN][i], _ = usbcdc.TxBuffer[ptr].Get()
			}

			if c == '\n' {
				udd_ep_in_cache_buffer[usb_CDC_ENDPOINT_IN][sz] = '\n'
				sz++
			}

			// wait for previous transfer to complete
			timeout := 3000000
			for (getEPINTFLAG(usb_CDC_ENDPOINT_IN) & sam.USB_DEVICE_ENDPOINT_EPINTFLAG_TRCPT1) != 0 {
				timeout--
				if timeout == 0 {
					return errUSBCDCWriteByteTimeout
				}
			}

			usbEndpointDescriptors[usb_CDC_ENDPOINT_IN].DeviceDescBank[1].ADDR.Set(uint32(uintptr(unsafe.Pointer(&udd_ep_in_cache_buffer[usb_CDC_ENDPOINT_IN]))))

			// clean multi packet size of bytes already sent
			usbEndpointDescriptors[usb_CDC_ENDPOINT_IN].DeviceDescBank[1].PCKSIZE.ClearBits(usb_DEVICE_PCKSIZE_MULTI_PACKET_SIZE_Mask << usb_DEVICE_PCKSIZE_MULTI_PACKET_SIZE_Pos)

			// set count of bytes to be sent
			usbEndpointDescriptors[usb_CDC_ENDPOINT_IN].DeviceDescBank[1].PCKSIZE.ClearBits(usb_DEVICE_PCKSIZE_BYTE_COUNT_Mask << usb_DEVICE_PCKSIZE_BYTE_COUNT_Pos)
			usbEndpointDescriptors[usb_CDC_ENDPOINT_IN].DeviceDescBank[1].PCKSIZE.SetBits((uint32(sz) & usb_DEVICE_PCKSIZE_BYTE_COUNT_Mask) << usb_DEVICE_PCKSIZE_BYTE_COUNT_Pos)

			// clear transfer complete flag
			setEPINTFLAG(usb_CDC_ENDPOINT_IN, sam.USB_DEVICE_ENDPOINT_EPINTFLAG_TRCPT1)

			// send data by setting bank ready
			setEPSTATUSSET(usb_CDC_ENDPOINT_IN, sam.USB_DEVICE_ENDPOINT_EPSTATUSSET_BK1RDY)

		} else {
			ok := usbcdc.TxBuffer[usbcdc.TxPtr].Put(c)
			if !ok {
				return errUSBCDCWriteByteOverflow
			}
		}
	}
	debugPortD1.Low()

	return nil
}

// src/examples/serial with debugPortD2
	for {
		debugPortD2.High()
		println("hello world!")
		debugPortD2.Low()
		time.Sleep(time.Second)
	}

before (tinygo 0.15) : 242.576 us

new : 36.642 us

[deadprogram]

Seems like you are on the right track here. I would suggest extending your code to include the following logic:

• if the character is a new line, then send buffer.
• if the buffer is full, send buffer
• if there are characters in the buffer, and some short period of time has passed since the last character, send buffer

The last part seems like it is necessary to prevent a stale partially full buffer from getting stuck without being sent.

What do you think?

[sago35]

if the character is a new line, then send buffer.

if the buffer is full, send buffer
if there are characters in the buffer, and some short period of time has passed since the last character, send buffer

I think it's the right idea.
I've thought about implementing it a bit.

For example, it would access TxBuffer and TxPtr from both SysTick_Handler and WriteByte.
So I was going to use sync.Mutex, but it seems to give me an error when using it with machine_atsamd51.
Is there a better way?

// USBCDC is the USB CDC aka serial over USB interface on the SAMD21.
type USBCDC struct {
	Buffer   *RingBuffer
	TxBuffer [2]*RingBuffer
	TxPtr    byte
	m        sync.Mutex
}

// WriteByte writes a byte of data to the USB CDC interface.
func (usbcdc *USBCDC) WriteByte(c byte) error {
	// Supposedly to handle problem with Windows USB serial ports?
	if usbLineInfo.lineState > 0 {
		if c == '\n' || usbcdc.TxBuffer[usbcdc.TxPtr].Used() == 126 {
			usbcdc.m.Lock()
			ptr := usbcdc.TxPtr
			usbcdc.TxPtr = 1 - usbcdc.TxPtr
			usbcdc.TxBuffer[usbcdc.TxPtr].Clear()
			usbcdc.m.Unlock()

			// ...
	}

	return nil
}

$ tinygo flash --target feather-m4 --size short --programmer cmsis-dap ./src/examples/spitest/
# runtime
/home/sago35/tinygo/tinygo/src/runtime/runtime_atsamd51.go: interp: branch on a non-constant

traceback:
/home/sago35/tinygo/tinygo/src/runtime/runtime_atsamd51.go:
  br i1 %69, label %for.loop, label %for.done, !dbg !3214
/home/sago35/tinygo/tinygo/src/runtime/runtime_atsamd51.go:25:12:
  call void @runtime.initClocks(i8* undef, i8* undef), !dbg !3146
runtime/<init>:
  call void @"runtime.init#1"(i8* undef, i8* undef), !dbg !3155

$ tinygo version
tinygo version 0.16.0-dev-f056092 linux/amd64 (using go version go1.14.4 and LLVM version 10.0.1)

[deadprogram]

@sago35 see #1172

[sago35]

I couldn't use runtime.Cond because I wanted to use it in a machine package.
@deadprogram

$ tinygo flash --target feather-m4 --size short --programmer cmsis-dap ./src/examples/spitest/
src/examples/spitest/spitest.go:7:2: import cycle not allowed
package github.com/tinygo-org/tinygo/src/examples/spitest
        imports machine
        imports runtime
        imports machine

[deadprogram]

See #1426 (comment) I think you can use the same sort of logic here @sago35

[aykevl]

Oops I didn't really look at the condition variable PR, but that's a major issue. It must be usable from the machine package, that's the main purpose after all.
Somewhat off-topic but perhaps runtime.Cond should be moved to a separate package to avoid this import cycle.
@niaow

[niaow]

Somewhat off-topic but perhaps runtime.Cond should be moved to a separate package to avoid this import cycle.
Yeah, that might make sense.

It is also worth noting that we cannot invoke cond.Wait() from inside the call graph of print, as we cannot suspend outside of a goroutine (and print is called from the scheduler/etc.). We would still need to poll which is annoying.

Hmm. . . now that I think about it more I really don't like this design because of that.

[sago35]

See #1426 (comment) I think you can use the same sort of logic here @sago35

I did not use the method in #1426 because I believe a better way has been found.

[aykevl]

While breaking on a newline should work for text based communication, it will likely break down for binary communication. Checking \n works in #1426 because that's strictly for log messages (println, panic, etc). In this case, USB-CDC can be used for many other things than just text.

I have a counter proposal for WriteByte:

• If there is no byte being sent, send it immediately.
• If a send is in progress, add the byte to a buffer and return. When the previous byte is transmitted, the new buffer should be sent.
• When the buffer is full and a send is in progress, busy-wait until the transmission is done (or block, using runtime.Cond or similar).

In pseudocode:

var buf = make([]byte, bufSize)
var bufUsed = 0
func WriteByte(b byte) {
    if inProgress() {
        if bufUsed == len(buf) {
            waitUntilTransmissionComplete()
        }
        buf[bufUsed] = b
        bufUsed++
        sendBuffer() // async, copies to DMA buffer or something like that
        bufUsed = 0
    } else {
        buf[bufUsed] = b
        bufUsed++
        sendBuffer() // async
        bufUsed = 0
    }
}

func usbcdcInterrupt() {
    if bufUsed != 0 {
        sendBuffer() // this certainly must be async
        bufUsed = 0
    }
}

What do you think?
This should improve performance significantly while being correct in all cases. WriteByte may not have sent the byte on return, but it will definitely send the byte eventually without further WriteByte (the latter is not the case when simply looking at \n bytes).

Also, now I think about it, maybe we shouldn't time out. A time out is basically always an error and the USB layer should handle that I think? Retrying after a time-out doesn't make a lot of sense, that would really just increase the timeout length.

[sago35]

How do I deal with race conditon?
I believe sendBuffer() and WriteByte() needs interruptDisable(), etc.

I don't currently know how to deal with the race condition, so I used the RingBuffer implementation.
But now that I think about it, the race condition may occur when I call WriteByte() from an interrupt to RingBuffer.

tinygo/src/machine/machine_atsamd51.go

Line 1722 in 1adfb75

sz := usbcdc.TxBuffer.Used()