STM32H730, uart_stm32, Missing Characters

[Aluleichtbau]

Hi there,

i observed a suspicius effect with the STM32 shell uart. Baudrate: 115200, 8 data bits, 1 stop bit, parity None.

If I connect e.g. via Putty to the serial console and paste a string, some chars are missing. It is always an arbitrary set of characters between 2nd..4th char sent. The first char is always received. Typing works OK.

E.g. if I paste "disp status", the echo in the shell is "dpstatus" or "dip status".

Debugging the problem carried out that the read function zephyr\drivers\serial\uart_stm32.c: uart_stm32_fifo_read_visitor function takes exactly the same incomplete string from read register it echos to shell.

I recorded the reception of the string via J-Link and SystemView. It is remarkable that the first run of the ISR takes about 350 us, while the other runs of the same ISR take about 30 us. The following ISR runs occure in an interval of about 95 us. Since it seems there is no hardware fifo active and it takes more than 100 us for the ISR to pick up the first char from the read register, it is understandable that the second char is missing. Because the ISR needs another 200..300 us to finish, I see the reason why other chars are missing too.

I tried to find a reason for this tenfold runtime of the first ISR in the ISR algorithm, but didn't find any.

Transmitting a single character also causes the first ISR to run for about 350 us.

How it is caused?

How to work around?

The problem is present even when no threads, no other ISRs are intervening.

A colleque has different Serial-USB-adapter and does not have the problem.

I am aware of workarounds like: Decreasing the baudrate, use the same hardware as my colleque, controlling the speed chars are transmitted, etc.

My motivation is to learn and hopefully configure it to be robust enough for any FTDI chips.

Technical Details:

I use Zephyr OS on a STM32H730VB MCU. Clock frequency = 480MHz.
My Win10 computer connects via FTDI USB to serial to UART4.
The compiler is the gcc-arm-none-eabi 10.3.

This is the UART-relevant DTS config.

/ {
	// ...
	chosen {
		zephyr,console = &uart4;
		zephyr,shell-uart = &uart4;
	};
	// ...
	soc {
		// ...
		pinctrl: pin-controller@58020000 {
			// ...
			uart4_rx_pc11: uart4_rx_pc11 {
				pinmux = < 0x568 >;
				phandle = < 0x6 >;
			};
			uart4_tx_pa0: uart4_tx_pa0 {
				pinmux = < 0x8 >;
				bias-pull-up;
				phandle = < 0x5 >;
			};
			// ...
		};
		uart4: serial@40004c00 {
			compatible = "st,stm32-uart";
			reg = < 0x40004c00 0x400 >;
			clocks = < &rcc 0xe8 0x80000 >;
			resets = < &rctl 0x1213 >;
			interrupts = < 0x34 0x0 >;
			status = "okay";
			pinctrl-0 = < &uart4_tx_pa0 &uart4_rx_pc11 >;
			pinctrl-names = "default";
			current-speed = < 0x1c200 >;
		};
		// ...
	};
};

autoconf.h

#define CONFIG_SHELL 1
#define CONFIG_SHELL_LOG_LEVEL_DEFAULT 1
#define CONFIG_SHELL_LOG_LEVEL 3
#define CONFIG_SHELL_BACKENDS 1
#define CONFIG_SHELL_BACKEND_SERIAL 1
#define CONFIG_SHELL_BACKEND_SERIAL_INIT_PRIORITY 0
#define CONFIG_SHELL_PROMPT_UART "uart:~$ "
#define CONFIG_SHELL_BACKEND_SERIAL_INTERRUPT_DRIVEN 1
#define CONFIG_SHELL_BACKEND_SERIAL_TX_RING_BUFFER_SIZE 8
#define CONFIG_SHELL_BACKEND_SERIAL_RX_RING_BUFFER_SIZE 64
#define CONFIG_SHELL_BACKEND_SERIAL_LOG_MESSAGE_QUEUE_TIMEOUT 100
#define CONFIG_SHELL_BACKEND_SERIAL_LOG_MESSAGE_QUEUE_SIZE 512
#define CONFIG_SHELL_BACKEND_SERIAL_LOG_LEVEL_DEFAULT 1
#define CONFIG_SHELL_BACKEND_SERIAL_LOG_LEVEL 5
#define CONFIG_SHELL_STACK_SIZE 4096
#define CONFIG_SHELL_BACKSPACE_MODE_DELETE 1
#define CONFIG_SHELL_CMD_BUFF_SIZE 256
#define CONFIG_SHELL_PRINTF_BUFF_SIZE 30
#define CONFIG_SHELL_DEFAULT_TERMINAL_WIDTH 80
#define CONFIG_SHELL_DEFAULT_TERMINAL_HEIGHT 24
#define CONFIG_SHELL_ARGC_MAX 20
#define CONFIG_SHELL_TAB 1
#define CONFIG_SHELL_TAB_AUTOCOMPLETION 1
#define CONFIG_SHELL_ASCII_FILTER 1
#define CONFIG_SHELL_WILDCARD 1
#define CONFIG_SHELL_ECHO_STATUS 1
#define CONFIG_SHELL_VT100_COMMANDS 1
#define CONFIG_SHELL_VT100_COLORS 1
#define CONFIG_SHELL_METAKEYS 1
#define CONFIG_SHELL_HELP 1
#define CONFIG_SHELL_HELP_OPT_PARSE 1
#define CONFIG_SHELL_HELP_ON_WRONG_ARGUMENT_COUNT 1
#define CONFIG_SHELL_HISTORY 1
#define CONFIG_SHELL_HISTORY_BUFFER 512
#define CONFIG_SHELL_STATS 1
#define CONFIG_SHELL_CMDS 1
#define CONFIG_SHELL_CMDS_RESIZE 1
#define CONFIG_SHELL_CMD_ROOT ""
#define CONFIG_SHELL_LOG_BACKEND 1
#define CONFIG_SHELL_LOG_FORMAT_TIMESTAMP 1
#define CONFIG_SHELL_AUTOSTART 1
#define CONFIG_SHELL_CMDS_RETURN_VALUE 1
#define CONFIG_KERNEL_SHELL 1
#define CONFIG_KERNEL_SHELL_REBOOT_DELAY 0
#define CONFIG_DEVICE_SHELL 1
#define CONFIG_DEVMEM_SHELL 1
#define CONFIG_NO_OPTIMIZATIONS 1

EDIT: fixed image.
EDIT2: fixed line break in DTS

[erwango]

Quite interesting. Thanks for reporting.
One suspect would be CONFIG_PM but this isn't available on H7 (I hope you don't enable it).

Could you provide the sample and config you're using to reproduce this ?

[Aluleichtbau]

CONFIG_PM is disabled.

I started stripping down the application to a sample I can publish.

I was able to reproduce the problem with my boards dts, a minimal set of configs and the hello-world sample, i.e. no application.

The CONFIG_DEBUG and CONFIG_NO_OPTIMIZATIONS had a huge influence to the effect. Disabling both, the first ISR's runtime was ca. 170 us instead of 350 us. For further examinations I enabled them.

The app is build for an external loader to be flashed into external QSPI NOR flash (memory mapped). So the code partition is on external QSPI NOR flash which certainly is also related.

Having built the app for internal flash, the effect apparently vanished. The runtime is generally much faster. Apparently it even managed to echo the character before the next character has been received. I did not dig into why the runtimes are different here, because, due to the much shorter runtimes and the effect with the echo, the scenario seemed much different. For the application this setup is not an option - the internal flash is way to small.

It was suspected that caching related to QSPI and/or MCU might be an issue. So I disabled ICACHE for the internal flash build. The general runtimes of the ISRs raised to a level compareable to those in external flash (where ICACHE is enabled). The first ISR has also been longer than than the subseqent ones but still much shorter than the first ISRs from the builds for external flash.

To be complete, the ICACHE has been disabled in the build for external flash leading to the first ISR to run for ca. 850 us and the second for ca 500 us.

I had trouble with SystemView to trace when DCACHE was disabled, so no results regarding DCACHE.

All these observations might be useful for #62349

Maybe some configurations regarding icaching regarding memory-mapped QSPI NOR flash code sections are not correct.