tinygo icon indicating copy to clipboard operation
tinygo copied to clipboard
verified publisher icon tinygo-org

Output to serial monitor is 'loosing' some characters (RP2350, maybe other platforms)

Open SnapshotCiTy opened this issue 8 months ago • 16 comments

Output to serial monitor is 'loosing' some characters

Text that is output fast by successive fmt.Println, fmt.Printf, print, println statements, result after a few lines in 'randomly missing' characters.

func main() {
	time.Sleep(time.Second)

	startTime := time.Now()
	fmt.Printf("\033[2J")
	fmt.Printf("\033[H")

	numLines := 600
	delayMicroseconds := 0

	for range numLines {
		fmt.Println("12345678901234567890123456789012345678901234567890123456789012345678901234567890")

		time.Sleep(time.Microsecond * time.Duration(delayMicroseconds))
	}

	fmt.Printf("in %v - Printed %d lines with delay %d microseconds", time.Since(startTime), numLines, delayMicroseconds)
	time.Sleep(time.Second * 2)
}

When run on a pico2-w and pimoroni tiny2350 (only boards I have to test this), results in some characters to be 'lost' and not output trough the serial interface. Tested with tinygo monitor, SerialTools (macOs) and Screen (also on macOs).

If we add a delay of a few microseconds before printing the next line, this behaviour stops and no characters are lost, if the delay is enough.

  • When using fmt.Println - or fmt.Printf("...80 cols of text...\n") it requires a delay of 11 or 12 micro seconds to not 'loose characters'.
  • When printing with print or println, the required delay is 24 to 25 micro seconds, any less and some characters are 'lost'.

Compiling with "-opt 2" or "-gc leaking" did not change this behavior.

Running the program on macOS with "go run ." and "tinygo run ." doesn't exhibit this behavior.

Sample output of Characters 'missing' - every line should be 80 characters (1->0 8times) with a trailing line break.

12345678901234567890123456789012345678901234567890123456789012345678901234567890
12345678901234567890123456789012345678901234567890123456789012345678901234567890
12345678901234567890123456789012345678901234567890123456789012345678901234567890
123456789012345678901234567890123456789012345678901234567890123678901234567890
123456789012345678901234567890123456789012345678901234567890
123456789012345678901234567890123456789012345678901901234567890
1234567890123456789012345678901234567890123456789011234567890
12345678901234567890123456789012345678901234567890123234567890
1234567890123456789012345678901234567890123456789012344567890
123456789012345678901234567890123456789012345678901234564567890
123456789012345678901234567890123456789012345678901234567890
123456789012345678901234567890123456789012345678901234567897890
1234567890123456789012345678901234567890123456789012345678990
12345678901234567890123456789012345678901234567890123456789011234567890123456789012345678901234567890123456789012345678901234123456789012345678901234567890123456789012345678901234567890123490123456789012345678901234567890123456789012345678901234567890

SnapshotCiTy avatar May 05 '25 20:05 SnapshotCiTy

Trying to help you by testing Windows 11 PC. Smallest "delayMicroseconds" value was 20, without overlapping bytes Serial Debug Assistant (for Windows) - 115200 Bps 8N1 DTR/RTS

============================================================== / Raspberry Pico 2 W - RP2350 - serial monitor test Gustavo Murta 2025/06/29 tinygo version 0.38.0 windows/amd64 (using go version go1.24.2 and LLVM version 19.1.2) tinygo flash -target pico2 main.go

https://github.com/tinygo-org/tinygo/issues/4887 Output to serial monitor is 'loosing' some characters

package main

import (
	"fmt"
	"time"
)

const (
	numLines          = 100
	delayMicroseconds = 20
)

`
func main() {

	time.Sleep(time.Second * 3) // Delay a bit on startup to easily catch the first messages
	println("Pico 2W Serial monitor test")

	fmt.Printf("\033[2J") //  What is this?
	fmt.Printf("\033[H")  //  What is this?
	println()
	startTime := time.Now()

	for range numLines {
		fmt.Println("1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890")
		time.Sleep(time.Microsecond * delayMicroseconds) // * time.Duration(delayMicroseconds)
	}

	fmt.Printf("Printed %d lines in %v with delay %d microseconds", numLines, time.Since(startTime), delayMicroseconds)
	time.Sleep(time.Second * 2)
}

Gustavomurta avatar Jun 30 '25 01:06 Gustavomurta

Pico 2W Serial monitor test [2J[H 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890

1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 Printed 100 lines in 8.608ms with delay 20 microseconds

Gustavomurta avatar Jun 30 '25 01:06 Gustavomurta

Checking the time to print a line on Raspberry Pico RP2040. Raspberry Pico 2W RP2350 does not support rp.TIMER yet.

package main

import (
	"device/rp"
	"fmt"
	"time"
)

const (
	numLines          = 10
	delayMicroseconds = 20
)

func main() {

	time.Sleep(time.Second * 3) // Delay a bit on startup to easily catch the first messages
	println("Pico 2W Serial monitor test")

	startTime := time.Now()

	for range numLines {
		start := rp.TIMER.TIMELR.Get()
		fmt.Println("1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890")
		end := rp.TIMER.TIMELR.Get()
		fmt.Println("Duration time to print this line = ", (end - start), "us")
		time.Sleep(time.Microsecond * delayMicroseconds) // * time.Duration(delayMicroseconds)
	}

	fmt.Printf("Printed %d lines in %v with delay %d microseconds", numLines, time.Since(startTime), delayMicroseconds)
	time.Sleep(time.Second * 2)
}

Gustavomurta avatar Jun 30 '25 01:06 Gustavomurta 

**Pico 2W Serial monitor test**
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  173 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  74 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  73 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  70 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  72 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  71 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  72 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  71 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  70 us
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Duration time to print this line =  71 us
Printed 10 lines in 1.579ms with delay 20 microseconds

Gustavomurta avatar Jun 30 '25 01:06 Gustavomurta

AFAIK that's the Pico/Pico 2 hardware issue - the small transmit buffer results in characters being lost when overflowed (which is easily achievable).

squirrelbob avatar Jul 14 '25 00:07 squirrelbob

I don't think it's a hardware issue. I've never seen anything like that. It sounds like a USB port buffer clearing issue to me.

Gustavomurta avatar Jul 14 '25 01:07 Gustavomurta

It doesn't make a lot of sense to be honest. The issue is persistent. I have it with all 7 rp2040/rp2350s in my possession (different boards, different vendors). The stack doesn't matter - tried tinygo, arduino, pico SDK and rust. On a couple of PCs and Android devices. While I never ever had this kind of issue with any other of 40+ ESP/stm/Nordic/avr boards. The only one that had similar issue was an "overclocked" digispark with attiny85, but that was completely expected.

squirrelbob avatar Jul 14 '25 01:07 squirrelbob

I have experience with the USB protocol for device-to-pc communication. On PCs (Windows and Linux), I've used the Gousb package (Google) extensively. In this case, I recommend using Wireshark to capture more details about the USB communication. https://www.wireshark.org/

Gustavomurta avatar Jul 14 '25 16:07 Gustavomurta

What an unimaginable coincidence then, I guess. I personally find switching to a more mature MCU/board to be faster and easier than debugging RPI issues.

squirrelbob avatar Jul 14 '25 17:07 squirrelbob

I like the ESP32 and have done countless experiments and tests. Right now, I'm focused on the Raspberry Pico because of its potential. One important difference is that the Raspberry Pi documentation is much more reliable and comprehensive than Espressif's.

Gustavomurta avatar Jul 14 '25 17:07 Gustavomurta

Totally agree, and Pico is a game changer in some sense. I'm just trying to choose the right tool for the job. While it is great in almost everything I needed, it was quite subpar with two things: low power consumption and USB serial communication. As for the debugging, other guys have done much better work than I could in that regard. E.g. https://github.com/raspberrypi/pico-sdk/issues/1144, although this one looks more like a software issue with Pico SDK.

squirrelbob avatar Jul 14 '25 18:07 squirrelbob

Another test. Raspberry Pico Usb/Serial(COM6) and Serial/Uart (COM4) connected to CP2102 module.

100 printed lines without any error at Serial/UART (COM4) - delayMicroseconds = 0

1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
....
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890

At USB/Serial port (COM6)


---- Opened the serial port COM6 ----
Pico Serial monitor test
Printed 100 lines in 772.652ms with delay 0 microseconds

Test Program:

package main

import (
	"fmt"
	"machine"
	"time"
)

const (
	numLines          = 100
	delayMicroseconds = 0
)

func main() {

	machine.UART0.Configure(machine.UARTConfig{
		BaudRate: 115200,
		TX:       machine.GPIO0,
		RX:       machine.GPIO1,
	})

	time.Sleep(time.Second * 3) // Delay a bit on startup to easily catch the first messages
	println("Pico Serial monitor test")

	startTime := time.Now()

	for range numLines {
		machine.UART0.Write([]byte("1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890\r\n"))
		time.Sleep(time.Microsecond * delayMicroseconds)
	}

	fmt.Printf("Printed %d lines in %v with delay %d microseconds", numLines, time.Since(startTime), delayMicroseconds)
}

Gustavomurta avatar Jul 15 '25 02:07 Gustavomurta

@Gustavomurta what is your last example showing? that using the UART0 doesn't exhibit the issue? And that it only occurs using the hardware usb port? Can you try with 1000 lines? (I'm travelling and away from my bench and cannot try for a bit).

What I was getting from the previous comments on this thread was that it is a problem either in hardware or in the PicoSDK - as [https://github.com/raspberrypi/pico-sdk/issues/1144](issue #1144) seemed to indicate. Your last test seem to contradict that.

Also - why on earth did your run take 772ms to print 100 lines with no delay between the lines when it usually takes just a few ms?

Note: to answer a comment in the code // what is this : fmt.Printf("\033[2J") // What is this? <== escape sequence to clear the screen (xterm, terminal emulators) fmt.Printf("\033[H") // What is this? <== escape sequence to move the cursor to the top-left of the screen

SnapshotCiTy avatar Jul 15 '25 06:07 SnapshotCiTy

Hi SnapShotCiTy,

"what is your last example showing? that using the UART0 doesn't exhibit the issue? And that it only occurs using the hardware usb port? "

  • Yes, that is correct.

I haven't yet identified the cause of the problem using USB port. Maybe HW or SW.

"Why on earth did your run take 772ms to print 100 lines with no delay between the lines when it usually takes just a few ms?"

  • This was a result presented by the program. 100 lines by 772 ms. Each line took 7.72 ms.

See this approximate calculation:

115200 bps / 8 bits = 14.400 bytes/second

1 / 14.400 = 69.5 us/byte

(80 + 9)bytes * 69.5 us = 6.18 ms (each line)

Gustavomurta avatar Jul 15 '25 12:07 Gustavomurta

Testing Tinygo with ESP32.

See the time duration to send 100 lines - 754 ms. I think this should be the correct time when sent by Raspberry Pico (USB simulating serial). An important detail - the ESP32 uses a CP2102 chip in the USB-Serial interface.

Printed 100 lines in 754.417375ms with delay 0 microseconds

package main

import (
	"fmt"
	"machine"
	"time"
)

const (
	numLines          = 100
	delayMicroseconds = 0
)

func main() {

	machine.InitSerial()        // Initialize serial for debug output
	time.Sleep(time.Second * 3) // Delay a bit on startup to easily catch the first messages
	println("ESP32 Serial monitor test")

	startTime := time.Now()

	for range numLines {
		//start := rp.TIMER.TIMELR.Get()
		fmt.Println("1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890")
		//end := rp.TIMER.TIMELR.Get()
		//fmt.Println("Duration time to print this line = ", (end - start), "us")
		time.Sleep(time.Microsecond * delayMicroseconds) // * time.Duration(delayMicroseconds)
	}

	fmt.Printf("Printed %d lines in %v with delay %d microseconds", numLines, time.Since(startTime), delayMicroseconds)
}

ESP32 Serial monitor test
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
...
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890
Printed 100 lines in 754.417375ms with delay 0 microseconds

Gustavomurta avatar Jul 16 '25 16:07 Gustavomurta

Yes, I've seen the same problem on the rp2040. My guess would be that there is some race condition between putchar (in the runtime, where all the data is written to stdout) and the USB-CDC interrupts.

aykevl avatar Sep 29 '25 13:09 aykevl